Java应用全链路故障排查实战指南：从系统资源到JVM深度诊断

主机问题排查

• CPU 相关问题：可以使用 top、vmstat、pidstat、ps 等工具排查；
• 内存相关问题：可以使用 free、top、ps、vmstat等工具排查；
• IO 相关问题：可以使用 lsof、iostat、pidstat等工具排查；
• 网络相关问题：可以使用 ifconfig、ip、dig、ping等工具排查。

CPU占用高

1. 首先，在 Linux 服务器上运行 top -Hp pid 命令，来查看进程中哪个线程 CPU 使用高；
2. 然后，输入大写的 P 将线程按照 CPU 使用率排序，并把明显占用 CPU 的线程 ID 转换为 16 进制；
3. 最后，在 jstack 命令输出的线程栈中搜索这个线程 ID，定位出问题的线程当时的调用栈。

使用Java启动参数辅助诊断

verbose

• -verbose:class ：输出jvm载入类的相关信息，当jvm报告说找不到类或者类冲突时可此进行诊断。

  [Loaded com.alibaba.fastjson.parser.deserializer.ParseProcess from file:/Users/user/Software/apache-maven-3.8.1/repository/com/alibaba/fastjson/1.2.83/fastjson-1.2.83.jar][Loaded com.alibaba.fastjson.parser.deserializer.ExtraProcessor from file:/Users/user/Software/apache-maven-3.8.1/repository/com/alibaba/fastjson/1.2.83/fastjson-1.2.83.jar]
  

• -verbose:gc ：输出每次GC的相关情况。

  //metaspace空间不够，导致GC
  [GC (Metadata GC Threshold)  47571K->7553K(565248K), 0.0037410 secs]
  //metaspace空间不够，导致FullGC 
  [Full GC (Metadata GC Threshold)  7553K->7210K(369664K), 0.0119384 secs] 
  // 内存分配失败
  [GC (Allocation Failure)  154666K->18687K(369664K), 0.0023040 secs]
  // 在进行内存分配的时候，会通过算法预估是否会出现无法分配预估值的问题，若是则会提前进行一次gc
  [Full GC (Ergonomics)  725603K->716406K(2180608K), 0.4325655 secs]
  

• -verbose:jni：输出native方法调用的相关情况，一般用于诊断jni调用错误信息。

  [Dynamic-linking native method java.io.FileInputStream.open0 ... JNI]
  [Dynamic-linking native method java.io.FileInputStream.readBytes ... JNI]
  [Dynamic-linking native method java.lang.reflect.Array.newArray ... JNI]
  [Dynamic-linking native method com.szkingdom.KgbpClientApi.JniInit ... JNI]
  [Dynamic-linking native method com.szkingdom.KgbpClientApi.GetKgbpcliVersion ... JNI]
  

NMT 特性（Java本地内存追踪）

# 开启 NMT 并选择 summary 模式(会影响性能)
-XX:NativeMemoryTracking=summary

（1）开启NMT后，可以通过jcmd命令查看NMT报告。使用以下命令：

jcmd <pid> VM.native_memory summary

（2）开启NMT后，也可以指定启动参数，在应用退出时打印NMT报告。使用以下命令：

# 在应用退出时打印 NMT 统计信息
-XX:+UnlockDiagnosticVMOptions -XX:+PrintNMTStatistics

输出结果（显示JVM内存使用情况，包括Java堆、类、线程、代码、垃圾收集器、编译器等内存占用情况‌）：

Native Memory Tracking:Total: reserved=11176849KB, committed=3944465KB
-                 Java Heap (reserved=9437184KB, committed=3386880KB)(mmap: reserved=9437184KB, committed=3386880KB) -                     Class (reserved=1117755KB, committed=76731KB)(classes #11773)(malloc=11835KB #18794) (mmap: reserved=1105920KB, committed=64896KB) -                    Thread (reserved=97019KB, committed=97019KB)(thread #48)(stack: reserved=96820KB, committed=96820KB)(malloc=147KB #246) (arena=52KB #91)-                      Code (reserved=136061KB, committed=16205KB)(malloc=2941KB #7263) (mmap: reserved=133120KB, committed=13264KB) -                        GC (reserved=356342KB, committed=335142KB)(malloc=11542KB #259) (mmap: reserved=344800KB, committed=323600KB) -                  Compiler (reserved=166KB, committed=166KB)(malloc=31KB #713) (arena=135KB #7)-                  Internal (reserved=12413KB, committed=12413KB)(malloc=12381KB #16759) (mmap: reserved=32KB, committed=32KB) -                    Symbol (reserved=16732KB, committed=16732KB)(malloc=14230KB #147028) (arena=2501KB #1)-    Native Memory Tracking (reserved=3000KB, committed=3000KB)(malloc=10KB #120) (tracking overhead=2990KB)-               Arena Chunk (reserved=177KB, committed=177KB)(malloc=177KB)

使用JDK自带工具查看JVM情况

jvisualvm

在线程面板可以看到，大量以 Thread 开头的线程基本都是有节奏的 10 秒运行一下，其他时间都在休眠，和我们的代码逻辑匹配：

点击面板的线程 Dump 按钮，可以查看线程瞬时的线程栈

jstack pid（线程栈）

通过命令行工具 jstack，也可以实现抓取线程栈的操作：

➜  ~ jstack 23940
2020-01-29 13:08:15
Full thread dump Java HotSpot(TM) 64-Bit Server VM (11.0.3+12-LTS mixed mode):..."main" #1 prio=5 os_prio=31 cpu=440.66ms elapsed=574.86s tid=0x00007ffdd9800000 nid=0x2803 waiting on condition  [0x0000700003849000]java.lang.Thread.State: TIMED_WAITING (sleeping)at java.lang.Thread.sleep(java.base@11.0.3/Native Method)at java.lang.Thread.sleep(java.base@11.0.3/Thread.java:339)at java.util.concurrent.TimeUnit.sleep(java.base@11.0.3/TimeUnit.java:446)at org.geekbang.time.commonmistakes.troubleshootingtools.jdktool.CommonMistakesApplication.main(CommonMistakesApplication.java:41)at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.3/Native Method)at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.3/NativeMethodAccessorImpl.java:62)at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.3/DelegatingMethodAccessorImpl.java:43)at java.lang.reflect.Method.invoke(java.base@11.0.3/Method.java:566)at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:48)at org.springframework.boot.loader.Launcher.launch(Launcher.java:87)at org.springframework.boot.loader.Launcher.launch(Launcher.java:51)at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:52)"Thread-1" #13 prio=5 os_prio=31 cpu=17851.77ms elapsed=574.41s tid=0x00007ffdda029000 nid=0x9803 waiting on condition  [0x000070000539d000]java.lang.Thread.State: TIMED_WAITING (sleeping)at java.lang.Thread.sleep(java.base@11.0.3/Native Method)at java.lang.Thread.sleep(java.base@11.0.3/Thread.java:339)at java.util.concurrent.TimeUnit.sleep(java.base@11.0.3/TimeUnit.java:446)at org.geekbang.time.commonmistakes.troubleshootingtools.jdktool.CommonMistakesApplication.lambda$null$1(CommonMistakesApplication.java:33)at org.geekbang.time.commonmistakes.troubleshootingtools.jdktool.CommonMistakesApplication$$Lambda$41/0x00000008000a8c40.run(Unknown Source)at java.lang.Thread.run(java.base@11.0.3/Thread.java:834)
...

jstat -gcutil pid（GC）

如果没有条件使用图形界面 jvisualvm 或jconsole，又希望看到 GC 趋势的话，我们可以使用 jstat 工具。

jstat 工具允许以固定的监控频次输出 JVM 的各种监控指标，比如使用 -gcutil 输出 GC 和内存占用汇总信息，每隔 5 秒输出一次，输出 100 次，可以看到 Young GC 比较频繁，而 Full GC 基本 10 秒一次：

➜  ~ jstat -gcutil 23940 5000 100S0    S1      E       O      M     CCS   YGC     YGCT  FGC    FGCT   CGC   CGCT      GCT0.00 100.00  0.36  87.63  94.30  81.06   539   14.021   33   3.972   837  0.976   18.9680.00 100.00  0.60  69.51  94.30  81.06   540   14.029   33   3.972   839  0.978   18.9790.00   0.00  0.50  99.81  94.27  81.03   548   14.143   34   4.002   840  0.981   19.1260.00 100.00  0.59  70.47  94.27  81.03   549   14.177   34   4.002   844  0.985   19.1640.00 100.00  0.57  99.85  94.32  81.09   550   14.204   34   4.002   845  0.990   19.1960.00 100.00  0.65  77.69  94.32  81.09   559   14.469   36   4.198   847  0.993   19.6590.00 100.00  0.65  77.69  94.32  81.09   559   14.469   36   4.198   847  0.993   19.6590.00 100.00  0.70  35.54  94.32  81.09   567   14.763   37   4.378   853  1.001   20.1420.00 100.00  0.70  41.22  94.32  81.09   567   14.763   37   4.378   853  1.001   20.1420.00 100.00  1.89  96.76  94.32  81.09   574   14.943   38   4.487   859  1.007   20.4380.00 100.00  1.39  39.20  94.32  81.09   575   14.946   38   4.487   861  1.010   20.442

• S0 表示 Survivor0 区占用百分比；S1 表示 Survivor1 区占用百分比；E 表示 Eden 区占用百分比
• O 表示老年代占用百分比；M 表示元数据区占用百分比
• YGC 表示年轻代回收次数；YGCT 表示年轻代回收耗时
• FGC 表示老年代回收次数；FGCT 表示老年代回收耗时

jmap -heap pid 或 jmap -histo[:live] pid（堆内存）

使用jmap -heap pid查看进程堆内存使用情况，包括使用的GC算法、堆配置参数和各代中堆内存使用情况

root@ubuntu:/# jmap -heap 21711
Attaching to process ID 21711, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 20.10-b01using thread-local object allocation.
Parallel GC with 4 thread(s)Heap Configuration:
MinHeapFreeRatio = 40   
MaxHeapFreeRatio = 70   
MaxHeapSize      = 2067791872 (1972.0MB)
NewSize          = 1310720 (1.25MB)
MaxNewSize       = 17592186044415 MB
OldSize          = 5439488 (5.1875MB)
NewRatio         = 2   
SurvivorRatio    = 8   
PermSize         = 21757952 (20.75MB)
MaxPermSize      = 85983232 (82.0MB)Heap Usage:
PS Young Generation
Eden Space:capacity = 6422528 (6.125MB)used     = 5445552 (5.1932830810546875MB)free     = 976976 (0.9317169189453125MB)84.78829520089286% used
From Space:capacity = 131072 (0.125MB)used     = 98304 (0.09375MB)free     = 32768 (0.03125MB)75.0% used
To Space:capacity = 131072 (0.125MB)used     = 0 (0.0MB)free     = 131072 (0.125MB)0.0% used
PS Old Generationcapacity = 35258368 (33.625MB)used     = 4119544 (3.9287033081054688MB)free     = 31138824 (29.69629669189453MB)11.683876009235595% used
PS Perm Generationcapacity = 52428800 (50.0MB)used     = 26075168 (24.867218017578125MB)free     = 26353632 (25.132781982421875MB)49.73443603515625% used....

使用jmap -histo[:live] pid查看堆内存中的对象数目、大小统计直方图，如果带上live则只统计活对象：

root@ubuntu:/# jmap -histo:live 21711 | more
num     #instances         #bytes  class name---------------------------------1:         38445        5597736  <constMethodKlass>2:         38445        5237288  <methodKlass>3:          3500        3749504  <constantPoolKlass>4:         60858        3242600  <symbolKlass>5:          3500        2715264  <instanceKlassKlass>6:          2796        2131424  <constantPoolCacheKlass>7:          5543        1317400  [I8:         13714        1010768  [C9:          4752        1003344  [B10:          1225         639656  <methodDataKlass>11:         14194         454208  java.lang.String12:          3809         396136  java.lang.Class13:          4979         311952  [S14:          5598         287064  [[I15:          3028         266464  java.lang.reflect.Method16:           280         163520  <objArrayKlassKlass>17:          4355         139360  java.util.HashMap$Entry18:          1869         138568  [Ljava.util.HashMap$Entry;19:          2443          97720  java.util.LinkedHashMap$Entry20:          2072          82880  java.lang.ref.SoftReference21:          1807          71528  [Ljava.lang.Object;22:          2206          70592  java.lang.ref.WeakReference

堆转储（只dump出live存活对象）

jmap -dump:live,format=b,file=<filename.hprof> <pid>

OOM问题排查

使用 Dump 进行堆转储

在出现 OOM 之后，我们可以根据错误日志中的异常信息，

1. 使用 jstat 命令观察堆内存占用及GC情况，可以大致定位出现 OOM 的内存区块和类型。
2. 使用 jmap 命令分析对象内存占用排行。
3. 建议为生产环境的系统配置 JVM 参数启用详细的 GC 日志，方便观察垃圾收集器的行为；并开启 HeapDumpOnOutOfMemoryError，以便在出现 OOM 时能自动 dump 进行堆转储（包含了堆现场全貌和线程栈信息）。对于 JDK8，可以这么设置：

XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=. 
-XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=100M

使用MAT 分析 Dump 文件

jvisualvm 的堆转储分析功能并不是很强大，只能查看类使用内存的直方图，无法有效跟踪内存使用的引用关系，所以更推荐使用 Eclipse 的 Memory Analyzer（也叫做 MAT）做堆转储的分析。

比如，我手头有一个 OOM 后得到的转储文件 java_pid29569.hprof，现在要使用 MAT 的直方图、支配树、线程栈等功能来分析此次 OOM 的原因。首先，用 MAT 打开后先进入的是概览信息界面，可以看到整个堆的大小是 437.6MB：

工具栏的第二个按钮可以打开直方图，直方图按照类型进行分组，列出了每个类有多少个实例以及占用的内存。可以看到，char[]字节数组占用内存最多，对象数量也很多，结合第二位的 String 类型对象数量也很多，大概可以猜出（String 使用 char[]作为实际数据存储）程序可能是被字符串占满了内存，导致 OOM。

在 char[]上点击右键，选择 List objects->with incoming references，就可以列出所有的 char[]实例，以及每个 char[]的整个引用关系链：

随机展开一个 char[]，如下图所示:

接下来，我们按照红色框中的引用链来查看，尝试找到这些大 char[]的来源：

• 在①处看到，这些 char[]几乎都是 10000 个字符、占用 20000 字节左右（char 是 UTF-16，每一个字符占用 2 字节）;
• 在②处看到，char[]被 String 的 value 字段引用，说明 char[]来自字符串；
• 在③处看到，String 被 ArrayList 的 elementData 字段引用，说明这些字符串加入了一个 ArrayList 中；
• 在④处看到，ArrayList 又被 FooService 的 data 字段引用，这个 ArrayList 整个 RetainedHeap 列的值是 431MB。Retained Heap（深堆）代表对象本身和对象关联的对象占用的内存，Shallow Heap（浅堆）代表对象本身占用的内存。

如果我们希望看到字符串完整内容的话，可以右键选择 Copy->Value，把值复制到剪贴板或保存到文件中：

我们已经从内存角度定位到 FooService 是根源了。那么，OOM 的时候，FooService 是在执行什么逻辑呢？为解决这个问题，我们可以点击工具栏的第五个按钮（下图红色框所示）。打开线程视图，首先看到的就是一个名为 main 的线程（Name 列），展开后果然发现了 FooService：

使用 Wireshark 分析网络问题

使用 Arthas 分析性能问题/异常排查

• **watch：**查看各方法的出入参
• **trace：**查看方法内部调用路径，并输出方法路径上的每个节点上耗时
• **stack：**查看方法的调用栈
• **monitor：**监视一个时间段中指定方法的执行次数，成功次数，失败次数，耗时等信息
• **sc -d：**查看类加载情况，辅助判断类冲突

watch

watch com.xxx handle '{params,returnObj,throwExp}' -n 5 -x 3 

• -x 参数设置为 3 代表参数打印的深度为 3 层

trace

trace com.xxx send  -n 5 --skipJDKMethod false 

stack

stack com.xxx send  -n 5 

monitor

monitor com.xxx send  -n 10  --cycle 10 

查看类加载情况（会输出类加载器id）

sc -d com.xxx

查看类加载器（会输出所有类加载器及其id）

classloader -l

Idea插件：Arthas Idea，帮助生成指定方法的arthas相关命令