分类 Java 相关 下的文章

JVM Heap dump 相关知识

最近在研究 JVM heap 相关的东西, 把相关的内容整理在这里

  1. 什么是 HPROF
    HPROF 是 Heap and CPU Profiling Agent 的工具, 是通过使用 JVM TI 的接口实现的 agent, 它在 JDK 里面是用来展示如何使用 JVM TI 的小工具. 同时它也是 Hotspot JVM 产生的 heap dump 的文件格式. HPROF 的格式参考下面. https://docs.oracle.com/javase/8/docs/technotes/samples/hprof.html. 使用以下命令, 查看帮助

    java -agentlib:hprof=help
    HPROF: Heap and CPU Profiling Agent (JVMTI Demonstration Code)
    
    hprof usage: java -agentlib:hprof=[help]|[<option>=<value>, ...]
    
    Option Name and Value  Description                    Default
    ---------------------  -----------                    -------
    heap=dump|sites|all    heap profiling                 all
    cpu=samples|times|old  CPU usage                      off
    monitor=y|n            monitor contention             n
    format=a|b             text(txt) or binary output     a
    file=<file>            write data to file             java.hprof[{.txt}]
    net=<host>:<port>      send data over a socket        off
    depth=<size>           stack trace depth              4
    interval=<ms>          sample interval in ms          10
    cutoff=<value>         output cutoff point            0.0001
    lineno=y|n             line number in traces?         y
    thread=y|n             thread in traces?              n
    doe=y|n                dump on exit?                  y
    msa=y|n                Solaris micro state accounting n
    force=y|n              force output to <file>         y
    verbose=y|n            print messages about dumps     y
  2. 什么是 JVM TI
    JVM TI 是 JDK 5 开始, 取代早期(JDK 4 及以前) JVM 提供的 DI (Debug Interface) 和 PI (Profiling Interface) 的统一接口. 参考
  3. HPROF 文件里面都可以有啥?
    CPU profiling 的数据, 一般以 stack trace sample 的形式存在; Heap 内存分配的信息; 以及锁竞争的信息.

参考:

  1. JDK 自带文档 demo/jvmti/hprof/src/manual.html
  2. http://www.brendangregg.com/blog/2014-06-09/java-cpu-sampling-using-hprof.html

JVM 的 "VM Thread" 线程

最近在帮一个同事看一个 Java 应用为什么会被经常重启的时候, 定位到 Java 应用中一个线程经常以 CPU 使用率100%的方式出现在 htop 的头部, 它是什么线程, 为什么会导致一个 CPU 100%? 这引起了我的兴趣.

相关背景及症状表现

这个应用程序运行中一个有8个 CPU 的 VM 上面, 经常看到该应用程序已最低13%的使用率运行, 有时候CPU 使用率会突然升到100%, 不过大多数会以13%或稍高来运行. 从 htop 的结果可以看到, 主要一个是一个线程导致一个 CPU 100% 运行:
cpu1.png

上面的截图中 25179 是 Java 进程ID, 25201 是占用一个 CPU core 的 Java 线程. 从 Thread dump 或者 Linux 的 proc 文件系统可以看到该线程的名字:

appUser@appHost:$ cat /proc/25179/task/25201/status
Name:    VM Thread
State:    R (running)
Tgid:    25179
Ngid:    0
Pid:    25201
PPid:    1626
TracerPid:    0

从上面的 shell 输出中可以看到, 该线程名字是 "VM Thread", 它经常单独占用一个 CPU core, 并且导致它100%.

VM Thread 做什么的?

"VM Thread" 是 JVM 自身启动的一个线程, 它主要用来协调其它线程达到安全点(Safepoint). 需要达到安全点的线程主要有: Stop the world 的 GC, 做 thread dump, 线程挂起以及偏向锁的撤销.
一般在 Thread dump 中, 它的表现为下面的样子, 没有线程栈信息:

"VM Thread" os_prio=0 tid=0x00007f5a212dc000 nid=0x1ad8d runnable

同时, 在 Thread dump 中, 有很多线程虽然当时不需要锁同步, 却能看到很多线程在 BLOCKED 状态, 如下:


"MyThreadPool-2" #77 daemon prio=5 os_prio=0 tid=0x00007f597a01c000 nid=0x1ae5e waiting for monitor entry [0x00007f591558a000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at com.sun.org.apache.xml.internal.dtm.ref.DTMManagerDefault.<init>(DTMManagerDefault.java:96)
    at com.sun.org.apache.xalan.internal.xsltc.dom.XSLTCDTMManager.<init>(XSLTCDTMManager.java:68)
    at com.sun.org.apache.xalan.internal.xsltc.dom.XSLTCDTMManager.newInstance(XSLTCDTMManager.java:78)

为什么这里出现 VM Thread 占用这么多 CPU

原因是这个程序因为内存泄漏, heap 几乎用光, 使用 jstat 命令看到, 每隔大约3s左右, 就有一次新的 full GC, 而CMS 的 full GC 只有单线程在工作, 所以只有一个 CPU core 在忙.

Refer:

  1. https://blog.jamesdbloom.com/JVMInternals.html
  2. http://hg.openjdk.java.net/jdk9/jdk9/hotspot/file/385668275400/src/share/vm/gc/cms/concurrentMarkSweepGeneration.cpp

Java 无法 attach 到目标进程, 使用 core dump 转换为 Java heap dump

有时候, 当我们尝试对一个已经 GC overhead 非常高的 Java 应用进程去做 heap dump 的时候, 或者使用 jstack/jcmd 去做 thread dump 的时候, 发现我们跟本没办法 attach 到目标 Java 进程, 得到下面的错误:

/usr/bin/jcmd 7674 GC.heap_dump /tmp/heap.log.hprof
7674:
com.sun.tools.attach.AttachNotSupportedException: Unable to open socket file: target process not responding or HotSpot VM not loaded
at sun.tools.attach.LinuxVirtualMachine.<init>(LinuxVirtualMachine.java:106)
at sun.tools.attach.LinuxAttachProvider.attachVirtualMachine(LinuxAttachProvider.java:63)
at com.sun.tools.attach.VirtualMachine.attach(VirtualMachine.java:213)
at sun.tools.jcmd.JCmd.executeCommandForPid(JCmd.java:140)
at sun.tools.jcmd.JCmd.main(JCmd.java:129)

一般我们会多尝试几次, 期望有哪次可以 attach 到目标 Java 进程, 不过有时候, 尝试好多次都无法达到目的.

除了这种尝试的方法之外, 我们还可以尝试另外一种方式: 先获得目标进程的 core dump, 再从 core dump 转成 Java heap dump.

具体的方法步骤是:

  1. 安装 gcore

    $ sudo apt install gdb -y   #gcore command in gdb package
  2. 设置 core dump 可允许的大小. 通常生产环境的 core dump 都是禁止的, 一方面 core dump 特别大, 占用磁盘比较大, 另外 core dump 可能包含运行时内存的敏感数据. 如果你的生产环境的 core size 是 unlimited 的或者特别大, 可以忽略这步.

    $ sudo cp /etc/security/limits.conf /etc/security/limits.d/   # 复制limits.conf模板文件到配置文件夹
    $ sudo vim /etc/security/limits.d/limits.conf     # 编辑配置文件, 修改我们目标 Java 进程的用户的配置
    #### 我们假设我们的目标进程使用 appUser 运行, 给他设置 core file 的 hard, soft 允许大小
             appUser hard core unlimited
             appUser soft core unlimited
    
    $ sudo su appUser  # 切换到 appUser
    $ ulimit -a        # 查看它的 core file size 的 hard, soft 大小   
    ### 有时候, 即便你改好了, 还是看到 core size 是0, 不过不要悲观, 继续下去, 可以参数 core dump.                                                                         
    $ exit             # 退出 appUser 
  3. 获取 core dump

    $ pgrep java   # 显示查看目标进程的 pid
    $ sudo gcore <pid>     # 使用 gcore 获取 core dump, 根据目标进程的内存占用大小, 可能会花费不同的时间
    ### 有时候使用别的用户, 即使使用 sudo 也不能 ptrace, 会得到 ptrace 无法 attach 的错误, 这时候, 切换到
    ### appUser 用户, 直接 gcore <pid> 就行. 如果报无法写入, 看你在哪个文件夹, 到一个可写的文件夹就好了
    $ ls -lah core.<pid>   # 查看获取的 core dump 的大小, 通常在当前目录
  4. 把 core file 的 hard, soft 修改的配置改回来

    $ sudo rm -f /etc/security/limits.d/limits.conf # 之前我们把模板加到这个文件, 现在删掉
  5. 转换 core dump 到 Java heap dump. 一定要使用运行对应目标进程运行的 JDK.
    如果你是 Hotspot JDK (Oracle 或者 OpenJDK):

    $ find /app -name jmap     # 找到运行目标进程的 JDK 里面的 jmap 命令
    $ sudo /usr/bin/jmap  -dump:format=b,file=heap.hprof  /usr/bin/java ./core.<pid>   #转换

    如果你是 IBM J9 JDK:

    $ find /app -name jextract  # 找到运行目标进程的 JDK 里面的 jextract 命令
    $ jextract core.<pid>       # 从 core dump 转成 heap dump core.<pid>.zip
    ## 对于这个 core.<pid>.zip 使用 MAT 并且安装的 dtfj 插件, 可以打开, 或者使用 IBM JDK 的 jdmpview 工具里 
    ## 面的 heapdump 命令, 可以把 这个 zip 文件转换成 IBM PHD 格式的 heap dump, 然后使用带 DTFJ 插件的 MAT 
    ## 工具分析. 
    $ /usr/bin/jdmpview 
    $ heapdump
    $ ls -lah
    -rw-r--r--  1 root    root    7.5G Aug 21 17:51 core.16751
    -rw-rw-r--  1 user1   user1   926M Aug 21 19:09 core.16751.zip
    -rw-rw-r--  1 user1   user1    19M Aug 21 19:46 core.16751.zip.phd

    到这里, 获取 heap dump 的过程结束, 下面是怎么从 prod 环境复制 heap dump 到本地环境. 你可以选择使用 scp 或者 rsync 复制到本地, 也可以向下面一样, 使用 nc 建立一个下载服务器, 从本地下载.

  6. 设置 nc 下载服务

    $ sudo apt install netcat -y # 若 nc 没有安装, 则安装
    $ sudo nc -4 -v -l 7070 < ./heap.hprof   # 一种 nc 支持这种参数
    $ sudo nc -v -l -p 7070 < ./heap.hprof   # 另外一种支持这种参数
  7. 下载到本地

    1. 使用浏览器访问 http://<;host>:7070/
    2. 或者使用 curl 命令去下载 → curl "http://<host>:7070/" --output heap.hprof
  8. 清理

    $ rm core.<pid>  dump.hprof

    有了 Heap dump, 你就可以使用 MAT 或者 JVisualVM 查看里面的内容了.

诊断一台服务器 CPU 稍微偏高的问题案例

运行同一Java web 应用的一个集群里面, 有台服务器最近 CPU 的使用率持续偏高一些, 其它服务器的 CPU 使用率大概都在5%一下, 而这台服务器却保持在15%左右. 它运行的代码和其它server 的代码一模一样. 另外即便重启应用, 还是一样的问题.
cpualittlehigh.png

那么这台服务器为什么会出现这种问题呢? 首先做了 profiling, 发现它的火焰图和其它服务器的火焰图并无二致. 如果登上机器, 使用 top 命令查看, 明显看到它的 CPU 使用率要相对高一些. 另外, 我们发现这台服务器上的所有的进程的 CPU 使用率相对其它同样服务器高一些.

使用 vmstat 命令, 我们可以看到, 它的 interrupt 和 context switch 明显比其他服务器高:
inter&cs.png

于是进一步查看 /proc/interrupts, 也能明显确认 Rescheduling Interrupts 也明显高(这个是累计, 可以使用 procinfo 查看 per second):
res.png

一般来说, 这种 Interrupts 都是由于某个进程持续不断的发出中断导致的, 这种发出中断的进程要想一只发生中断, 那么它也也要不断的运行, 它的 CPU 使用率也不会太低. 所以经常见的就是排除法 -> shutdown 某个进程, 看系统 CPU 使用率有没有改进. 于是我们尝试了对 CPU 使用率较高的几个进程使用了排除法. 可以仍然没有奏效.

考虑到这个 server 是一个 VM (使用 KVM), 所以我们有进一步查看了同一个 Hypervisor 上面的其它 VM, 发现其它 VM 也有相同的问题, 于是我们转而怀疑问题出现在 Hypervisor 上面.

于是对 Hypervisor 上的进程使用排除法, 实际排除的时候先找最像的. 于是我们找到了这个元凶进程 -> kswapd0:
image2020-8-18_2-4-41.png

从上面截图可以看到这个 kswapd 进程 CPU 使用率并不低, swap 的使用量(used)的是3.9G, 其实最开始发现它的时候是 swap 14个G, 后来截图的时候, 已经通过 swapoff 释放了很多.