寫在前面
線上環境突然出現Java程序CPU佔用率持續超過100%的問題，該如何排查並定位呢？
問題一：我們如何知道線上環境的那個伺服器（或者哪個Docker容器）出現了CPU持續高的故障了呢？
如果是有比較完善的監控設施，當出現CPU持續高時可以透過傳送報警通知的方式告知開發人員，如果沒有監控通知，那隻能透過使用者側感知了，比如操作響應慢，甚至出現了服務不可用的現象。
問題二：存在哪些可能的原因會導致Java程序的CPU佔用率會持續高呢？
如果是突然出現的問題，可能是跟當時併發壓力有關，比如使用者訪問量突然增多觸發大量的TCP連線請求，也可能是觸發了某個程式碼邏輯的BUG進入死迴圈等。根據經驗，會引起Java程序CPU佔用率持續高的原因可能有如下幾個：
- 併發量突然增大引起TCP連線數陡增，Tomcat容器處理不過來
- 資料量猛然變大引起頻繁Full GC，這個可以從GC日誌可以看出來
- 如果列印日誌非常多，也可能導致CPU持續高，當然這個原因一般不會突然才冒出來，在測試階段就能感知了
既然存在多種可能的原因，那麼在排查的時候就需要依次定位了。
執行緒堆疊
不論是何種原因引起的Java程序CPU佔用率高問題，排查的入口都是先從執行緒堆疊資訊入手。
可以檢視Java執行緒堆疊資訊的工具有：jstack命令，Arthas工具。
jstack命令
jstack命令是JDK自帶的，在使用它檢視程序堆疊之前先要找到具體的程序ID。
先透過top命令確定CPU佔用高的Java程序ID，如下示例：
ubuntu@epic-doberman:~$ top
top - 15:49:15 up 30 min, 2 users, load average: 0.86, 0.32, 0.12
Tasks: 122 total, 1 running, 121 sleeping, 0 stopped, 0 zombie
%Cpu(s): 25.3 us, 0.0 sy, 0.0 ni, 74.6 id, 0.0 wa, 0.0 hi, 0.2 si, 0.0 st
MiB Mem : 7925.5 total, 6999.9 free, 454.5 used, 711.5 buff/cache
MiB Swap: 0.0 total, 0.0 free, 0.0 used. 7470.9 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
8632 ubuntu 20 0 4386476 28076 18604 S 99.7 0.3 1:56.00 java
1 root 20 0 22708 13540 9444 S 0.0 0.2 0:02.23 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd
3 root 20 0 0 0 0 S 0.0 0.0 0:00.00 pool_workqueue_release
4 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/R-rcu_g
5 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/R-rcu_p
6 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/R-slub_
7 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/R-netns
9 root 20 0 0 0 0 I 0.0 0.0 0:00.31 kworker/0:1-events
10 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/0:0H-events_highpri
12 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/R-mm_pe
13 root 20 0 0 0 0 I 0.0 0.0 0:00.00 rcu_tasks_kthread
如上，CPU佔用高的程序ID為8632。..
接著，使用JDK自帶的jstack命令匯出程序堆疊檔案。
$ jstack
Usage:
jstack [-l] <pid>
(to connect to running process)
jstack -F [-m] [-l] <pid>
(to connect to a hung process)
jstack [-m] [-l] <executable> <core>
(to connect to a core file)
jstack [-m] [-l] [server_id@]<remote server IP or hostname>
(to connect to a remote debug server)
Options:
-F to force a thread dump. Use when jstack <pid> does not respond (process is hung)
-m to print both java and native frames (mixed mode)
-l long listing. Prints additional information about locks
-h or -help to print this help message
$ jstack 8632 > 8632.tdump
將程序8632的執行緒堆疊資訊匯出到檔案8632.tdump之後，使用JDK自帶的jvisualvm工具分析堆疊資訊。
線上程堆疊檔案中查詢並分析狀態為RUNNABLE的執行緒，結合程式碼進行分析，如果能直接確定出問題原因則修復程式碼即可。
對於使用jstack命令檢視執行緒堆疊，可以結合shell指令碼來實現快速檢視，如下示例：
#!/bin/bash
# Desc: 檢視Java程序CPU使用率高的執行緒堆疊資訊
# Name: show_java_process_thread_stack.sh
echo "Show java process thread stack"
pid=$1
if [ ! "$pid" ]; then
echo "Usage: sh $0 pid"
echo " e.g: sh $0 1234"
echo ""
exit 1
fi
top -H -p "$pid"|head -20
echo ""
top_thread_id=`top -H -p $pid|head -8|awk '/java/{print $2}'`
#echo "top cpu thread: $top_thread_id"
thread_id_hex=`printf "%x" "$top_thread_id"`
#echo "$thread_id_hex"
jstack "$pid"|grep "$thread_id_hex" -A 100 > jstack_tmp
cat jstack_tmp
rm -rf jstack_tmp
#echo "Done."
如果是程式碼死迴圈問題，通常在分析執行緒堆疊之後很快就能定位到具體的位置。
而倘若是因為大量使用者請求引起的TCP連線數很多，此時線上程堆疊中也會有所體現，如下示例：
同時，再結合相關網路連線檢視命令，也能大致確認（此時會存在大量TCP連線處於TIME_WAIT狀態），參考檢視linux中的TCP連線數。
$ sudo netstat -anpt
Arthas工具thread命令
使用Arthas排查檢視執行緒堆疊資訊非常方便，透過如下步驟使用arthas可以便捷地檢視到執行緒堆疊資訊，對於定位可能存在死迴圈的程式碼位置非常有幫助。
第一步：啟動arthas
# 使用與目標程序相同的使用者許可權啟動arthas
$ java -jar arthas-boot.jar
ubuntu@epic-doberman:~/Scripts$ java -jar arthas-boot.jar
[INFO] JAVA_HOME: /usr/lib/jvm/java-8-openjdk-amd64/jre
[INFO] arthas-boot version: 3.7.2
[INFO] Found existing java process, please choose one and input the serial number of the process, eg : 1. Then hit ENTER.
* [1]: 2730 test-java-util.jar
第二步：選擇目標程序編號並回車
1
[INFO] arthas home: /home/ubuntu/.arthas/lib/3.7.2/arthas
[INFO] Try to attach process 2730
Picked up JAVA_TOOL_OPTIONS:
[INFO] Attach process 2730 success.
[INFO] arthas-client connect 127.0.0.1 3658
,---. ,------. ,--------.,--. ,--. ,---. ,---.
/ O \ | .--. ''--. .--'| '--' | / O \ ' .-'
| .-. || '--'.' | | | .--. || .-. |`. `-.
| | | || |\ \ | | | | | || | | |.-' |
`--' `--'`--' '--' `--' `--' `--'`--' `--'`-----'
wiki https://arthas.aliyun.com/doc
tutorials https://arthas.aliyun.com/doc/arthas-tutorials.html
version 3.7.2
main_class
pid 2730
time 2024-06-13 16:24:38
[arthas@2730]$
第三步：執行dashboard命令找到CPU佔用率高的執行緒ID
$ dashboard
第四步：執行thread <執行緒ID>檢視指定執行緒的堆疊資訊
[arthas@2730]$ thread 1
"main" Id=1 RUNNABLE
at org.chench.extra.java.mock.DeadLoopSampleMock.mock(DeadLoopSampleMock.java:20)
at org.chench.extra.java.mock.DeadLoopSampleMock.main(DeadLoopSampleMock.java:14)
如果存在多個執行緒佔用CPU都比較高的情況，可以直接執行thread -n <執行緒數量N>檢視當前最忙的前N個執行緒並列印堆疊。
# 檢視當前最繁忙的前3個執行緒堆疊，各執行緒堆疊資訊之間透過2個空行分隔
$ thread -n 3
"main" Id=1 cpuUsage=99.96% deltaTime=204ms time=1835502ms RUNNABLE
at org.chench.extra.java.mock.DeadLoopSampleMock.mock(DeadLoopSampleMock.java:20)
at org.chench.extra.java.mock.DeadLoopSampleMock.main(DeadLoopSampleMock.java:14)
"C2 CompilerThread0" [Internal] cpuUsage=1.55% deltaTime=3ms time=823ms
"arthas-command-execute" Id=57 cpuUsage=0.12% deltaTime=0ms time=6ms RUNNABLE
at sun.management.ThreadImpl.dumpThreads0(Native Method)
at sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:461)
at com.taobao.arthas.core.command.monitor200.ThreadCommand.processTopBusyThreads(ThreadCommand.java:206)
at com.taobao.arthas.core.command.monitor200.ThreadCommand.process(ThreadCommand.java:122)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.process(AnnotatedCommandImpl.java:82)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.access$100(AnnotatedCommandImpl.java:18)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:111)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:108)
at com.taobao.arthas.core.shell.system.impl.ProcessImpl$CommandProcessTask.run(ProcessImpl.java:385)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:750)
GC日誌
當線上應用因為堆記憶體空間不足而引起頻繁Full GC時，同樣會導致CPU佔用持續高的問題。如果經過排查執行緒堆疊資訊無法定位到具體的原因，就要轉換思路，需要定位是否出現了Full GC。
在排查是否出現了頻繁Full GC問題時，可以從2個方面入手：GC日誌，JVM記憶體資訊。
檢視GC日誌有多種方式，可以使用JDK自帶的jstat命令檢視實時的GC資訊，也可以在啟動引數中指定輸出GC日誌到到檔案中。
jstat命令檢視GC概要
使用jstat命令可以試試檢視JVM堆記憶體狀態以及GC資訊，命令語法為：jstat -gcutil <程序ID> <重新整理頻率，單位：毫秒>，如下示例：
$ jstat -gcutil 34444 1000
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 34.38 13.91 53.31 93.42 86.18 427 0.770 5 0.348 1.119
0.00 34.38 13.91 53.31 93.42 86.18 427 0.770 5 0.348 1.119
0.00 34.38 13.91 53.31 93.42 86.18 427 0.770 5 0.348 1.119
0.00 34.38 33.96 53.31 93.42 86.18 427 0.770 5 0.348 1.119
0.00 34.38 33.96 53.31 93.42 86.18 427 0.770 5 0.348 1.119
0.00 34.38 33.96 53.31 93.42 86.18 427 0.770 5 0.348 1.119
輸出引數含義：
-
S0: 新生代中Survivor space 0區已使用空間的百分比
-
S1: 新生代中Survivor space 1區已使用空間的百分比
-
E: 新生代已使用空間的百分比
-
O: 老年代已使用空間的百分比
-
M: 元空間已使用空間的百分比
-
CCS: Compressed class space utilization as a percentage
-
YGC: 從應用程式啟動到當前，發生Yang GC 的次數
-
YGCT: 從應用程式啟動到當前，Yang GC所用的時間（單位：秒）
-
FGC: 從應用程式啟動到當前，發生Full GC的次數
-
FGCT: 從應用程式啟動到當前，Full GC所用的時間
-
GCT: 從應用程式啟動到當前，用於垃圾回收的總時間（單位：秒）
GC日誌檔案
使用JDK自帶的jstat命令只能檢視GC的概要資訊，如果希望知道更加具體的GC細節，應該在應用啟動引數中指定生成gc.log日誌檔案。
引數格式為：-Xloggc:/tmp/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps，相關引數含義如下：
- -Xloggc:/tmp/gc.log 日誌檔案的輸出路徑
- -XX:+PrintGC 輸出GC日誌
- -XX:+PrintGCDetails 輸出GC的詳細日誌
- -XX:+PrintGCTimeStamps 輸出GC的時間戳（以基準時間的形式）
- -XX:+PrintGCDateStamps 輸出GC的時間戳（以日期的形式，如
2013-05-04T21:53:59.234+0800） - -XX:+PrintHeapAtGC 在進行GC的前後列印出堆的資訊
記憶體dump
Arthas工具memory命令
還可以透過Arthas診斷工具的memory命令檢視JVM記憶體資訊。
$ memory
Memory used total max usage
heap 77M 136M 1762M 4.43%
ps_eden_space 20M 42M 626M 3.23%
ps_survivor_space 5M 17M 17M 30.53%
ps_old_gen 52M 77M 1321M 3.98%
nonheap 65M 66M -1 98.30%
code_cache 10M 10M 240M 4.17%
metaspace 49M 50M -1 98.26%
compressed_class_space 6M 6M 1024M 0.63%
direct 0K 0K - 0.00%
mapped 0K 0K - 0.00%
堆記憶體dump檔案
不論使用JDK自帶的jstat命令還是使用Arthas工具的memory命令，都只能檢視到JVM堆記憶體的概要資訊，並不利於排查和定位程式碼問題。如果是因為堆記憶體空間不足導致OutOfMemoryError報錯，定位問題最好的辦法是生成堆記憶體dump檔案，然後再使用MAT工具進行分析，找到問題的根本原因並解決。
生成堆dump檔案至少有三種方式：
其一：在啟動引數中指定生成dump檔案的時機和路徑，如：-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/headpdump.hprof
其二：使用JDk自帶的jmap命令匯出指定Java程序的堆記憶體dump檔案，如：jmap -dump:file=/tmp/dump.hprof <程序ID>
其三：使用Arthas工具的heapdump命令將當前堆記憶體快照儲存到檔案中，如：heapdump /tmp/dump.hprof
第一種方式只有在Java程序出現OutOfMemoryError報錯之後才會生成dump檔案，而透過JDK提供的jmap命令或Arthas工具的heapdump命令方式可以隨時生成堆dump檔案，特別是出現頻繁Full GC的時候匯出堆記憶體dump檔案非常有利於定位和解決問題。
最後總結
排查Java程序CPU佔用高的問題，基本思路如下：
首先，從執行緒堆疊入手，排查可能存在的程式碼死迴圈問題，可用的工具：JDK自帶的jstack命令，Arthas工具的thread命令。
其次，如果執行緒堆疊中定位不到具體的原因，再去看看gc日誌是否出現了頻繁Full GC的問題，可用的工具：JDK自帶的jstat命令，Arthas工具的memory命令。
最後，如果出現了頻繁Full GC的問題，則使用JDK自帶的jmap命令或者Arthas工具的heapdump命令匯出堆記憶體檔案，使用MAT工具進行分析和定位程式碼問題。
另外，為了方便線上排查問題，應該將相關的工具一起打到作業系統映象中，這樣在遇到線上故障時就不會手忙腳亂了。
附
jstack命令用法
$ jstack -help
Usage:
jstack [-l] <pid>
(to connect to running process)
jstack -F [-m] [-l] <pid>
(to connect to a hung process)
jstack [-m] [-l] <executable> <core>
(to connect to a core file)
jstack [-m] [-l] [server_id@]<remote server IP or hostname>
(to connect to a remote debug server)
Options:
-F to force a thread dump. Use when jstack <pid> does not respond (process is hung)
-m to print both java and native frames (mixed mode)
-l long listing. Prints additional information about locks
-h or -help to print this help message
jstat命令用法
$ jstat -help
Usage: jstat -help|-options
jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]]
Definitions:
<option> An option reported by the -options option
<vmid> Virtual Machine Identifier. A vmid takes the following form:
<lvmid>[@<hostname>[:<port>]]
Where <lvmid> is the local vm identifier for the target
Java virtual machine, typically a process id; <hostname> is
the name of the host running the target Java virtual machine;
and <port> is the port number for the rmiregistry on the
target host. See the jvmstat documentation for a more complete
description of the Virtual Machine Identifier.
<lines> Number of samples between header lines.
<interval> Sampling interval. The following forms are allowed:
<n>["ms"|"s"]
Where <n> is an integer and the suffix specifies the units as
milliseconds("ms") or seconds("s"). The default units are "ms".
<count> Number of samples to take before terminating.
-J<flag> Pass <flag> directly to the runtime system.
jmap命令用法
$ jmap -help
Usage:
jmap [option] <pid>
(to connect to running process)
jmap [option] <executable <core>
(to connect to a core file)
jmap [option] [server_id@]<remote server IP or hostname>
(to connect to remote debug server)
where <option> is one of:
<none> to print same info as Solaris pmap
-heap to print java heap summary
-histo[:live] to print histogram of java object heap; if the "live"
suboption is specified, only count live objects
-clstats to print class loader statistics
-finalizerinfo to print information on objects awaiting finalization
-dump:<dump-options> to dump java heap in hprof binary format
dump-options:
live dump only live objects; if not specified,
all objects in the heap are dumped.
format=b binary format
file=<file> dump heap to <file>
Example: jmap -dump:live,format=b,file=heap.bin <pid>
-F force. Use with -dump:<dump-options> <pid> or -histo
to force a heap dump or histogram when <pid> does not
respond. The "live" suboption is not supported
in this mode.
-h | -help to print this help message
-J<flag> to pass <flag> directly to the runtime system
【參考】
GC日誌生成-Xloggc，GC情況實時檢視命令jstat
java 七 如何檢視 GC 日誌
jstat命令詳解---JVM的統計監測工具