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 查看里面的内容了.

wireshark TSL 1.0 显示协议列为 1.2 的问题

今天遇到一个问题: 新代码发布上去之后, 应用程序启动失败, 显示如下报错信息:

ConnectionException: Socket connection to security.tianxiaohui.com:443 failed with 1 retries
Received fatal alert: protocol_version

从这个出错信息看, 这个客户端连接对应的 server 的 https 出错, 出错的信息显示协议版本问题. 遇到这种问题, 一般我们都会认为客户端和服务端的 TLS 协议的版本不一致造成的.
为了尽快恢复问题, 我们立即对新版本 rollback. 可是出乎意料的是, 老版本也报这个错. 只能这么猜测: 这个 https 访问只在服务器启动的时候访问, 上次老版本发布的时候, 两端的 TLS 协议版本还是能够匹配工作的. 从上次发布完到最近一次新版本发布, 服务器端做了改动, 导致应用不管老版本, 还是新版本, 都无法访问这个 https 的服务.

为了确认这个猜想, 我们对服务器重启, 以便获取 tcp dump, 然后去验证. 结果在使用 wireshark 对这个 tcpdump 进行分析的时候, 遇到了这个 wireshark 显示 TLS 版本不统一的问题, 如下图:
tls.png

在 Protocol 列, 无论是 client hello 还是 server 的 response 都显示为 TLSv1.2, 其实如果查看 client 的详细版本, 会发现内部其实是 TLSv1.0. 如果不仔细查看, 可能会得出错误的结论.

为什么会出现这种情况呢? 这要回到 wireshark 的 SSL dissector 的源码, 从源码看, 对于这个 client hello 协议版本的判断, 是即根据 client 又根据 server 两边做判断的. 正常情况下, 2 端都是一直的, 或能正常协商的情况下, 依照服务端版本取值的. 如果服务端没回应, 这个时候, 是以 client 端的 client hello 的版本做设置的. 我们这里出现的这个问题, 就是属于服务端有回应, 是不同的版本, 导致 wireshark 的显示为和 client 真正发的不一致的问题.

官方网站有个这样的问题: https://www.wireshark.org/lists/wireshark-users/201701/msg00004.html

Browsing the SSL dissector's code it appears that the SSL session
version is based on not just the client hello but also the server

  1. So it would seem that in file-c.pcap the server has responded
  2. TLS v1.2 is used while in file-u.pcap either the server's

response was not seen or responded that TLS 1.0 will be used.

诊断一台服务器 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 释放了很多.