Kyle's Notebook

Java 应用常用调试分析方法总结

Word count: 4.3kReading time: 19 min
2020/10/04

日志配置

要在生产环境部署 Java 应用,配置日志输出是必备的预备工作。

应用日志

以 Spring Boot 应用为例,其 Starter 包已经引入了 logback、log4j 等应用框架,因此应用程序常用的配置项可以在 application.yml 进行设定。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
logging:
group:
tomcat: org.apache.catalina, org.apache.tomcat
spring: org.springframework, springfox
swagger: io.swagger
kafka: org.apache.kafka
es: org.elasticsearch
level:
kafka: warn
tomcat: warn
swagger: error
spring: warn
es: warn
file:
max-size: 5MB
# path: logs
max-history: 7
name: logs/${spring.application.name}.log
pattern:
rolling-file-name: logs/${spring.application.name}.%d{yyyy-MM-dd}.%i.gz

值得注意的是:

  • 严格管理日志级别,避免在生产环境输出开发测试阶段的调试信息,以免对业务系统造成压力。

  • 复杂的配置项可以通过 xml 文件进行定义(如 classpath:log4j.xml),在 application.yml 引入即可。

JVM 日志

一般情况下 JVM 层面的事故出现时,将来不及使用 jstat 等命令查看事发原因,因此需要保留现场,把进程快照、堆栈快照等信息保存下来以供后续排查问题使用。以下是比较通用的 JVM 参数配置:

1
2
3
4
5
6
7
8
9
10
11
# JDK 8
LOG_DIR="/tmp/logs"
JAVA_OPT_LOG=" -verbose:gc"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintGCDetails"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintGCDateStamps"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintGCApplicationStoppedTime"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintTenuringDistribution"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -Xloggc:${LOG_DIR}/gc_%p.log"
JAVA_OPT_OOM=" -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=${LOG_DIR} -XX:ErrorFile=${LOG_DIR}/hs_error_pid%p.log "
JAVA_OPT="${JAVA_OPT_LOG} ${JAVA_OPT_OOM}"
JAVA_OPT="${JAVA_OPT} -XX:-OmitStackTraceInFastThrow"
1
2
3
4
5
6
7
8
# JDK 8+
LOG_DIR="/tmp/logs"
JAVA_OPT_LOG=" -verbose:gc"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -Xlog:gc,gc+ref=debug,gc+heap=debug,gc+age=trace:file=${LOG_DIR}/gc_%p.log:tags,uptime,time,level"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -Xlog:safepoint:file=${LOG_DIR}/safepoint_%p.log:tags,uptime,time,level"
JAVA_OPT_OOM=" -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=${LOG_DIR} -XX:ErrorFile=${LOG_DIR}/hs_error_pid%p.log "
JAVA_OPT="${JAVA_OPT_LOG} ${JAVA_OPT_OOM}"
JAVA_OPT="${JAVA_OPT} -XX:-OmitStackTraceInFastThrow"

可以总结为以下几个方面:

  • GC 日志:时间戳、STW 时间,对象年龄分布等。

  • Safe Point 日志(便于分析线程阻塞等问题)。

  • 发生 OOM 时导出堆转储文件以及错误日志。

  • ……

输入日志如下:

GC 日志分析

  • 1 表示 GC 发生的时间,一般使用可读的方式打印;

  • 2 表示日志表明是 G1 的“转移暂停: 混合模式”,停顿了约 223ms;

  • 3 表明由 8 个 Worker 线程并行执行,消耗了 214ms;

  • 4 表示 Diff 越小越好,说明每个工作线程的速度都很均匀;

  • 5 表示外部根区扫描,外部根是堆外区。JNI 引用,JVM 系统目录,Classloaders 等;

  • 6 表示更新 RSet 的时间信息;

  • 7 表示该任务主要是对 CSet 中存活对象进行转移(复制);

  • 8 表示花在 GC 之外的工作线程的时间;

  • 9 表示并行阶段的 GC 总时间;

  • 10 表示其他清理活动;

  • 11表示收集结果统计;

  • 12 表示时间花费统计。

系统日志

如果 Java 程序还配置了 Systemd,还可以通过 journalctl 系列命令查看日志(如 journalctl -u test-svc.service -f 筛选出特定服务的日志)。

1
journalctl -u test-svc.service -f
1
2
3
4
-- Logs begin at Thu 2020-09-17 14:56:01 CST. --
Oct 04 23:35:04 ecs20200311-0002 systemd[1]: Started test-svc.
Oct 04 23:35:04 ecs20200311-0002 test-svc-svc[3214]: test-svc is running, pid: [23613]
Oct 04 23:35:05 ecs20200311-0002 test-svc-svc[3218]: test-svc stop successfully!

另一方面,有时 Java 进程会毫无预兆的退出,且没有任何遗言输出(比如由系统 oom-killer 在系统内存耗尽时被选择性杀死),此时可以使用 dmesg -T 查看:

dmesg 日志

无论由于何种原因退出,都能从以上方法中找到一些线索,但前提是不要为自己挖坑(比如在代码中加入 System.exit(); 等命令)。

保留现场

哪怕生产环境往往配备了监控系统,但其保留的信息未必能有针对性地为服务排查问题。因此在服务出现故障前,可以使用自动化方式将必要的信息保存下来,一般用到以下信息:

  • 瞬时态:lsof、heap 这些没有时间序列概念的混杂信息,体积都比较大,无法进入监控系统产生有用价值,只能在某些时刻查看分析(线程、堆、网络快照)。

  • 历史态:CPU、内存,这些数据可以体现出趋势性的问题,这些数据需要监控系统的协作(系统监控、业务监控、GC 日志数据采集等)。

服务器

网络

保留当前网络连接,使得后续可查看梳理各种网络连接状态,排查 TIME_WAIT、CLOSE_WAIT 或者其他连接过高的问题,比如连接没有主动关闭):

1
ss -antp > $DUMP_DIR/ss.dump 2>&1

保留网络状态(按照各个协议进行统计输出):

1
netstat -s > $DUMP_DIR/netstat-s.dump 2>&1

对于一些速度非常高得模块,比如 Kafka、Redis 经常出现跑满网卡的情况,容易挤占 Java 程序的资源,使用以下命令保留网络流量:

1
sar -n DEV 1 2 > $DUMP_DIR/sar-traffic.dump 2>&1

进程

比如通过查看进程,看到打开了哪些文件,以进程的维度来查看整个资源的使用情况,包括每条网络连接、每个打开的文件句柄。同时也很容易看到连接到了哪些服务器、使用了哪些资源。

1
lsof -p $PID > $DUMP_DIR/lsof-$PID.dump

CPU

输出当前系统的 CPU 和负载(与上述信息有部分重合):

1
mpstat > $DUMP_DIR/mpstat.dump 2>&1
1
vmstat 1 3 > $DUMP_DIR/vmstat.dump 2>&1
1
sar -p ALL > $DUMP_DIR/sar-cpu.dump 2>&1
1
uptime > $DUMP_DIR/uptime.dump 2>&1

磁盘

一般以计算为主的服务节点,I/O 资源会比较正常,但有时也会发生问题,比如:日志输出过多,或者磁盘本身出现问题等。此命令可以输出每块磁盘的基本性能信息,用来排查 I/O 问题。

1
iostat -x > $DUMP_DIR/iostat.dump 2>&1

内存

大体展现操作系统的内存概况,比如 SWAP 影响了 GC,SLAB 区挤占了 JVM 的内存。

1
free -h > $DUMP_DIR/free.dump 2>&1

其他

包括系统日志、内核参数等。

1
ps -ef > $DUMP_DIR/ps.dump 2>&1
1
dmesg > $DUMP_DIR/dmesg.dump 2>&1
1
sysctl -a > $DUMP_DIR/sysctl.dump 2>&1

JVM

进程快照

即进程最后的“遗言”。

1
jinfo $PID > $DUMP_DIR/jinfo.dump 2>&1

堆快照

jstat 将输出当前的 GC 信息。

1
2
jstat -gcutil $PID > jstat-gcutil.dump 2>&1
jstat -gccapacity $PID > jstat-gccapacity.dump 2>&1

可借助 jmap 来进行分析。

1
2
3
4
jmap $PID > jmap.dump 2>&1
jmap -heap $PID > jmap-heap.dump 2>&1
jmap -histo $PID > jmap-histo.dump 2>&1
jmap -dump:format=b,file=heap.bin $PID > /dev/null 2>&1

jmap 命令在 9 版本里被移除了,取而代之的是 jhsdb。

1
2
3
4
jhsdb jmap --heap --pid $PID
jhsdb jmap --pid $PID
jhsdb jmap --histo --pid $PID
jhsdb jmap --binaryheap --pid $PID

对于 jmap 无法执行的情况,可以使用 gcore 生成 core 文件、再生成 dump。

1
2
gcore -o core $PID
jhsdb jmap --exe java --core core --binaryheap

dump 文件一般需要下载到本地,使用 MAT 等工具分析内存泄漏等问题。

栈快照

jstack 将会获取当时的执行栈,一般取一次即可,能还原 Java 进程中的线程情况。

1
jstack $PID > jstack.dump 2>&1

如果需要更精细的信息,可以结合 top:

1
top -Hp $PID -b -n 1 -c > top-$PID.dump 2>&1

有时 jstack 并不能够运行(比如 Java 进程几乎不响应)。可以尝试向进程发送 kill -3 信号打印 jstack 的 trace 信息到日志文件中,是 jstack 的一个替补方案。

1
kill -3 $PID

把以上数据导出写成脚本,运行可生成 日志

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
#!/bin/bash
: ${1?"Usage: '$0 \$pid' should supply a PID"}

PID=$1
DUMP_DATE=`date +%Y%m%d%H%M%S`
DUMP_DIR=`hostname`"-"$DUMP_DATE

if [ ! -d $DUMP_DIR ]; then
mkdir $DUMP_DIR
fi

echo "Dumping $PID to the $DUMP_DIR..."

# resource (yum install -y iostat sysstat)
lsof -p $PID > $DUMP_DIR/lsof-$PID.dump
ss -antp > $DUMP_DIR/ss.dump 2>&1
netstat -s > $DUMP_DIR/netstat-s.dump 2>&1
iostat -x > $DUMP_DIR/iostat.dump 2>&1
mpstat > $DUMP_DIR/mpstat.dump 2>&1
vmstat 1 3 > $DUMP_DIR/vmstat.dump 2>&1
free -h > $DUMP_DIR/free.dump 2>&1
sar -n DEV 1 2 > $DUMP_DIR/sar-traffic.dump 2>&1
sar -p ALL > $DUMP_DIR/sar-cpu.dump 2>&1
sysctl -a > $DUMP_DIR/sysctl.dump 2>&1
uptime > $DUMP_DIR/uptime.dump 2>&1
ps -ef > $DUMP_DIR/ps.dump 2>&1
dmesg > $DUMP_DIR/dmesg.dump 2>&1
top -Hp $PID -b -n 1 -c > $DUMP_DIR/top-$PID.dump 2>&1

# java
kill -3 $PID
jinfo $PID > $DUMP_DIR/jinfo.dump 2>&1
jstack $PID > $DUMP_DIR/jstack.dump 2>&1
jstat -gcutil $PID > $DUMP_DIR/jstat-gcutil.dump 2>&1
jstat -gccapacity $PID > $DUMP_DIR/jstat-gccapacity.dump 2>&1
jmap $PID > $DUMP_DIR/jmap.dump 2>&1
jmap -heap $PID > $DUMP_DIR/jmap-heap.dump 2>&1
jmap -histo $PID > $DUMP_DIR/jmap-histo.dump 2>&1
jmap -dump:format=b,file=$DUMP_DIR/heap.bin $PID > /dev/null 2>&1

# advance
if [ ! -f $DUMP_DIR/jmap-heap.dump ]; then
gcore -o $DUMP_DIR/core $PID
#jhsdb jmap --exe ${JDK}java --core $DUMP_DIR/core --binaryheap
fi

tar -zcvf ${DUMP_DIR}.tar.gz ${DUMP_DIR}
echo "OK!"
echo "DUMP: ${DUMP_DIR}.tar.gz"

rm -rf ${DUMP_DIR}

问题排查

定位异常线程

有时某些线上应用在运行一段时间后 CPU 使用率飙升,可能的原因是某些业务逻辑计算量太大或陷入死循环,也可能是 GC 的问题,此时就需要找出具体是由哪个线程触发的。

首先查看进程信息:

1
2
top
# Shift + P 快捷键按 CPU 的使用率进行排序

查看某个进程中占用 CPU 最多的线程:

1
top -Hp $pid

把线程 id 转换成十六进制表示:

1
printf %x $tid

查看 Java 进程的栈信息:

1
jstack $pid > $pid.log

查看生成的文件,找到十六进制表示的线程 id,找到发生问题的线程上下文:

1
less $pid.log

比如:
GC 问题导致 CPU 升高应用假死

堆被填满但又没有发生 OOM,于是 GC 进程就一直执行回收,但回收效果不好、造成 CPU 升高应用假死。

此时要进一步对问题成因进行分析,就需要把内存信息导出到本地,使用其他工具进行分析。

内存泄漏现象

这里尤其指的是堆内存泄漏,堆外内存泄漏比较复杂,在其他章节再总结分析过程。

使用 jmap 命令可以看到大体的内存布局,以及每个区域中的内存使用情况。

1
jmap -heap $PID > jmap-heap.dump 2>&1

jmap 输出内存布局

另一方面需要关心的是堆中每种类型的对象占据内存的大小。比如某个对象数量很小,但占用的空间很大,这就说明存在大对象。

jmap 输出每种类型占用空间

一般内存溢出的表现形式就是老年代占用持续上升,即使经过了多轮 FGC 也没有明显改善。内存泄漏是其中一种原因,其本质就有些对象并没有切断和 GC Roots 的关系。

以上方法只能大致看到一些统计信息,要作进一步排查可通过 VisualVM、MAT 等工具分析它们的联系(需要导出二进制格式的堆转储快照)。

1
2
jmap -dump:format=b,file=heap.bin $PID    # JDK 8
jhsdb jmap --binaryheap --pid $PID # JDK 8+

直接内存溢出

以下述描述场景为例。

现象描述

有一次发现某个服务占用的内存不断增长,直到虚拟机分配的内存上限,但是不会 OOM。如果开启了 SWAP,会发现被不断占用。

  • 内存增长可以通过 top 命令去观察(RES 列的数值);如果使用 jmap 命令去看内存占用,得到的只是堆的大小,只是很小的一部分。

  • 使用 ps -p pid -o rss,vsz 可以观测到除了虚拟内存比较高,实际使用的内存 RSS 也非常高,超过 -Xmx 的设定。

  • 使用 jps -v 查看启动参数、使用 java -XX:+PrintFlagsFinal 2>&1 | grep MaxHeapSize 查看默认值,可发现实际内存使用远远超出最大内存设定。

要追踪 Native 内存的使用情况,可在启动参数上加入 -XX:NativeMemoryTracking=detail 即可启用,在运行状态下使用 jcmd:

1
jcmd $PID VM.native_memory summary

即使 NMT 能看到堆内内存、Code 区域或者使用 unsafe.allocateMemory 和 DirectByteBuffer 申请的堆外内存,但仍然不能解决问题。

Pmap

使用 pmap 命令查看进程的内存分配,通过 RSS 升序序排列,可以发现除了大块的堆内存以外,还有数量非常多的小块堆外内存,还有巨量小的物理内存块映射到不同的虚拟内存段上。

1
pmap -x 2154 | sort -n -k3
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
Address           Kbytes     RSS   Dirty Mode  Mapping
---------------- ------- ------- -------
0000000100080000 1048064 0 0 ----- [ anon ]
00007f2d4fff1000 60 0 0 ----- [ anon ]
00007f2d537fb000 8212 0 0 ----- [ anon ]
00007f2d57ff1000 60 0 0 ----- [ anon ]
...省略 N 行
00007f2e3c000000 65524 22064 22064 rw--- [ anon ]
00007f2e00000000 65476 22068 22068 rw--- [ anon ]
00007f2e18000000 65476 22072 22072 rw--- [ anon ]
00007f2e30000000 65476 22076 22076 rw--- [ anon ]
00007f2dc0000000 65520 22080 22080 rw--- [ anon ]
00007f2dd8000000 65520 22080 22080 rw--- [ anon ]
00007f2da8000000 65524 22088 22088 rw--- [ anon ]
00007f2e8c000000 65528 22088 22088 rw--- [ anon ]

GDB

可以通过 gdb 工具将堆外内存 dump 出来:读取 /proc 目录下的 maps 文件,能精准地知晓目前进程的内存分布。

以下脚本通过传入进程 id,能够将所关联的内存(加载到内存中的 class 文件、堆文件一块给 dump 下来)全部 dump 到文件中。这个命令会影响服务,要慎用。

1
pid=$1;grep rw-p /proc/$PID/maps | sed -n 's/^\([0-9a-f]*\)-\([0-9a-f]*\) .*$/\1 \2/p' | while read start stop; do gdb --batch --pid $pid -ex "dump memory $1-$start-$stop.dump 0x$start 0x$stop"; done
1
2
3
4
5
6
7
8
9
10
11
12
13
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1"
0x00007f2ed432afd7 in pthread_join () from /lib64/libthread.so.0
[New LWP 2277]
[New LWP 2163]
[New LWP 2162]
[New LWP 2161]
[New LWP 2160]
[New LWP 2159]
[New LWP 2158]
[New LWP 2157]
[New LWP 2156]
...

更多时候只需要 dump 一部分内存就可以。这个操作会影响服务,注意 dump 的内存块大小,线上要慎用。

复制 pman 的一块 64M 内存,比如 00007f2d70000000,然后去掉前面的 0,使用下面代码得到内存块的开始和结束地址。

1
cat /proc/$PID/maps | grep 7f2d70000000
1
7f2d6fff1000-7f2d70000000 ---p 00000000 00:00 0 7f2d70000000-7f2d73ffc000 rw-p 00000000 00:00 0

dump 出这 64MB 的内存。

1
2
gdb --batch --pid $PID -ex "dump memory a.dump 0x7f2d70000000 0x7f2d73ffc000"
du -h a.dump

使用 strings 查看打印的内容(一些类似编码解码的操作)。

1
strings -10 a.dump
1
2
0R4f1Qej1ty5GT8V1R8no6T44564wz499E6Y582q2R9h8CC175GJ3yeJ1Q3P5Vt757Mcf6378kM36hxZ5U8uhg2A26T5l7f68719WQK6vZ2BOdH9lH5C7838qf1
...

可以发现一些原本应该存在于堆的内容使用了额外的内存进行分配,只可能是 Native 程序对堆外内存的操作。

Perf

Perf 除了能够进行一些性能分析,还能帮助找到相应的 Native 调用。首先开启监控栈函数调用。

1
perf record -g -p $PID

访问服务器的 8888 端口,将会把内存使用的阈值增加到 85%,程序会逐渐把这部分内存占满。

perf 运行一段时间后 Ctrl+C 结束会生成一个文件 perf.data,查看分析报告。

1
perf report -i perf.data

一般第三方 JNI 程序或者 JDK 内的模块,都会调用相应的本地函数。在 Linux 上这些函数库的后缀都是 so,比如 libzip.so、libpthread-2.17.so 等:

1
2
3
4
5
6
Samples: 26K of event 'cpu-clock', Event count (approx.): 6583500000
Children Self Command Shared Object Symblo
+ 19.02% 0.35% java libc-2.17.so [.] __GI___libc_read
+ 18.93% 1.25% java libpthread-2.17.so [.] pthread_cond_timewait@...
+ 7.43% 0.06% java libzip.so [.] Java_java_util_zip_Inflater_inflateBytes
...

其中 libzip.so 占据大量 CPU,查看 JDK 代码,发现 bzip 包使用了大量 native 方法 java.util.zip.Inflater#inflateBytesBytes,即大量的内存申请和销毁实在堆外发生的。

进程调用了申请了内存却没有调用 Deflater 释放内存。与 pmap 内存地址相比对,确实是 zip 造成的,应该检查业务代码中 zip 相关的操作。

GPerftools

还可以利用 GPerftools 的 Heap Profiler 功能定位 Native 函数。安装成功后输出两个环境变量:

1
2
3
mkdir -p /opt/test 
export LD_PRELOAD=/usr/lib64/libtcmalloc.so
export HEAPPROFILE=/opt/test/heap

在同一个终端启动应用程序,可见申请内存的动作都被记录到 /opt/test:

1
2
3
4
5
java -jar ...
...
Dumping heap profile to /opt/test/heap.0001.heap (100MB currently in use)
Dumping heap profile to /opt/test/heap.0002.heap (100MB currently in use)
...

再使用 pprof 分析这些文件:

1
2
cd /opt/test
pprof -text *heap | head -n 200
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
Total: 25205.3 MB
20559.2 81.6% 81.6% 20559.2 81.6% inflateBackEnd
4487.3 17.8% 99.4% 4487.3 17.8% inflateInit2_
75.7 0.3% 99.7% 75.7 0.3% os::malloc@8bbaa0
70.3 0.3% 99.9% 4557.6 18.1% Java_java_util_zip_Inflater_init
7.1 0.0% 100.0% 7.1 0.0% readCEN
3.9 0.0% 100.0% 3.9 0.0% init
1.1 0.0% 100.0% 1.1 0.0% os::malloc@8bb8d0
0.2 0.0% 100.0% 0.2 0.0% _dl_new_object
0.1 0.0% 100.0% 0.1 0.0% __GI__dl_allocate_tls
0.1 0.0% 100.0% 0.1 0.0% _nl_intern_locale_data
0.0 0.0% 100.0% 0.0 0.0% _dl_check_map_versions
0.0 0.0% 100.0% 0.0 0.0% __GI___strdup
0.0 0.0% 100.0% 0.1 0.0% _dl_map_object_deps
0.0 0.0% 100.0% 0.0 0.0% nss_parse_service_list
0.0 0.0% 100.0% 0.0 0.0% __new_exitfn
0.0 0.0% 100.0% 0.0 0.0% getpwuid
0.0 0.0% 100.0% 0.0 0.0% expand_dynamic_string_token

也可以追踪到申请内存最多的函数 java.util.zip.Inflater#init

未完待续。

CATALOG
  1. 1. 日志配置
    1. 1.1. 应用日志
    2. 1.2. JVM 日志
    3. 1.3. 系统日志
  2. 2. 保留现场
    1. 2.1. 服务器
      1. 2.1.1. 网络
      2. 2.1.2. 进程
      3. 2.1.3. CPU
      4. 2.1.4. 磁盘
      5. 2.1.5. 内存
      6. 2.1.6. 其他
    2. 2.2. JVM
      1. 2.2.1. 进程快照
      2. 2.2.2. 堆快照
      3. 2.2.3. 栈快照
  3. 3. 问题排查
    1. 3.1. 定位异常线程
    2. 3.2. 内存泄漏现象
    3. 3.3. 直接内存溢出
      1. 3.3.1. 现象描述
      2. 3.3.2. Pmap
      3. 3.3.3. GDB
      4. 3.3.4. Perf
      5. 3.3.5. GPerftools