1 引言
作為一名從事Java開發(fā)快一年的程序員睦尽，在線上經(jīng)常碰到某個(gè)模塊的Pod發(fā)出CPU與內(nèi)存告警的問題酒贬，而這些問題會導(dǎo)致系統(tǒng)響應(yīng)緩慢甚至是服務(wù)不可用。一般情況下可以通過重啟或者調(diào)高Pod的資源量或者增加Pod數(shù)量暫時(shí)解決問題乓梨，但這是治標(biāo)不治本的牲剃，只有找到問題發(fā)生的原因才能從根本上解決問題遣疯。那么在該如何快速定位到導(dǎo)致告警的原因呢？下面將匯總一下大致的處理思路凿傅。
一般來說導(dǎo)致Java程序CPU與內(nèi)存沖高的原因有兩種：
- 代碼中某個(gè)位置讀取數(shù)據(jù)量較大缠犀，導(dǎo)致系統(tǒng)內(nèi)存耗盡数苫，從而導(dǎo)致Full GC次數(shù)過多，系統(tǒng)緩慢辨液。
- 代碼中有比較耗CPU的操作虐急，導(dǎo)致CPU過高，系統(tǒng)運(yùn)行緩慢滔迈。
- 代碼某個(gè)位置有阻塞性的操作止吁，導(dǎo)致該功能調(diào)用整體比較耗時(shí)，但出現(xiàn)是比較隨機(jī)的燎悍；
- 某個(gè)線程由于某種原因而進(jìn)入WAITING狀態(tài)敬惦，此時(shí)該功能整體不可用，但是無法復(fù)現(xiàn)谈山；
- 由于鎖使用不當(dāng)俄删，導(dǎo)致多個(gè)線程進(jìn)入死鎖狀態(tài)，從而導(dǎo)致系統(tǒng)整體比較緩慢奏路。
前兩種情況出現(xiàn)的頻率較高畴椰，可能會導(dǎo)致系統(tǒng)不可用，后三種會導(dǎo)致某個(gè)功能運(yùn)行緩慢思劳，但是不至于導(dǎo)致系統(tǒng)不可用迅矛。
對于第一種情況，本人曾經(jīng)遇到過某個(gè)查全量數(shù)據(jù)的接口在某段時(shí)間被頻繁調(diào)用導(dǎo)致內(nèi)存耗盡潜叛、瘋狂GC的情況：記一次GC導(dǎo)致的CPU與內(nèi)存沖高的問題解決。
下面將總結(jié)一些具體的排查步驟壶硅。
2 分析工具
2.1 top命令查看CPU占用情況
PID為進(jìn)程編號威兜，COMMAND為其中執(zhí)行命令，java即為要找的應(yīng)用
-
top: 展示所有進(jìn)程占用情況 -
top -N num: 展示CPU占用最高的num個(gè)進(jìn)程
root@8d36124607a0:/# top
top - 14:01:23 up 1 day, 17:54, 1 user, load average: 0.00, 0.01, 0.05
Tasks: 101 total, 1 running, 100 sleeping, 0 stopped, 0 zombie
%Cpu(s): 0.8 us, 1.2 sy, 0.0 ni, 98.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 3782864 total, 1477524 free, 329656 used, 1975684 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 3181392 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
9 root 20 0 1031064 52580 19248 S 90.3 10.4 26:30.37 javacatalina.sh
root@8d36124607a0:/# top -Hp 9
top - 08:31:16 up 30 min, 0 users, load average: 0.75, 0.59, 0.35
Threads: 11 total, 1 running, 10 sleeping, 0 stopped, 0 zombie
%Cpu(s): 3.5 us, 0.6 sy, 0.0 ni, 95.9 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem: 2046460 total, 1924856 used, 121604 free, 14396 buffers
KiB Swap: 1048572 total, 0 used, 1048572 free. 1192532 cached Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
10 root 20 0 2557160 289824 15872 R 79.3 14.2 0:41.49 java
11 root 20 0 2557160 289824 15872 S 1.2 14.2 0:06.78 java
可以看到占用CPU消耗最高的PID為10庐椒，該ID即為線程ID椒舵，使用如下命令將其轉(zhuǎn)化為16進(jìn)制格式：
root@8d36124607a0:/# printf "%x\n" 10
得到輸出a線程即為0xa。
2.2 使用jstack查看Java線程信息
-
jstack 進(jìn)程號 | grep 線程ID：查看線程堆棧信息约谈，將上一步驟的Java線程進(jìn)程ID與CPU占用量較高的線程ID（16進(jìn)制格式）填入其中笔宿。 -
jstack pid >> stack.txt：將今后曾所有堆棧信息都打印到stack.txt中
root@8d36124607a0:/# jstack 9 | grep 0xa
"VM Thread" os_prio=0 tid=0x00007f871806e000 nid=0xa runnable”
第一個(gè)雙引號圈起來的就是線程名，如果是“VM Thread”這就是虛擬機(jī)GC回收線程棱诱，如果是"main"則是其他線程泼橘，后面的runnable是線程狀態(tài)。
2.3 使用jstat查看GC信息
jstat -gcutil 進(jìn)程號 統(tǒng)計(jì)間隔毫秒 統(tǒng)計(jì)次數(shù)（缺省代表一直統(tǒng)計(jì)）
root@8d36124607a0:/# jstat -gcutil 9 1000 10
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 0.00 0.00 75.07 59.09 59.60 3259 0.919 6517 7.715 8.635
0.00 0.00 0.00 0.08 59.09 59.60 3306 0.930 6611 7.822 8.752
0.00 0.00 0.00 0.08 59.09 59.60 3351 0.943 6701 7.924 8.867
0.00 0.00 0.00 0.08 59.09 59.60 3397 0.955 6793 8.029 8.984
查看某進(jìn)程GC持續(xù)變化情況迈勋，如果發(fā)現(xiàn)返回中FGC很大且一直增大炬灭，確認(rèn)為Full GC! 也可以使用“jmap -heap 進(jìn)程ID”查看一下進(jìn)程的堆內(nèi)從是不是要溢出了，特別是老年代內(nèi)從使用情況一般是達(dá)到閾值(具體看垃圾回收器和啟動時(shí)配置的閾值)就會進(jìn)程Full GC靡菇。
2.4 使用Jmap分析內(nèi)存
-
jmap -dump:format=b,file=文件名稱 進(jìn)程ID：生成內(nèi)存dump文件重归，進(jìn)行離線分析米愿。 - dump文件界面分析工具：IBM HeapAnalyzer，點(diǎn)擊進(jìn)入找到ha457.jar的下載鏈接進(jìn)行下載
-
java -Xmx4G -jar ha457.jar：運(yùn)行jar文件鼻吮，如果dump文件過大可以使用-Xmx設(shè)置最大堆內(nèi)存大小育苟，防止內(nèi)存溢出。
通過ha457.jar的GUI界面可以很清晰的看到各種類型的數(shù)據(jù)內(nèi)存占用情況椎木、對象之間的引用關(guān)系以及可能存在內(nèi)存泄漏的對象违柏。
3 原因分析
3.1 Full GC次數(shù)過多
相對來說，這種情況是最容易出現(xiàn)的拓哺，尤其是新功能上線時(shí)勇垛。對于Full GC較多的情況，其主要有如下兩個(gè)特征：
- 線上多個(gè)線程的CPU都超過了100%士鸥，通過jstack命令可以看到這些線程主要是垃圾回收線程
- 通過jstat命令監(jiān)控GC情況闲孤，可以看到Full GC次數(shù)非常多，并且次數(shù)在不斷增加烤礁。
初步排查：使用top與top -Hp命令找到CPU占用最高的Java線程讼积，將其轉(zhuǎn)為16進(jìn)制后，使用jstack命令抓取該線程信息脚仔，發(fā)現(xiàn)線程名稱是"VM Thread"垃圾回收線程勤众。
進(jìn)一步確認(rèn)： 使用jstat -gcutil命令查看gc次數(shù)與增長情況。
進(jìn)一步分析：使用jmap -dump命令dump內(nèi)存鲤脏，然后使用使用ha457.jar離線分析们颜。
- 生成大量的對象，導(dǎo)致內(nèi)存溢出
- 內(nèi)存占用不高猎醇，但是Full GC次數(shù)還是比較多窥突，此時(shí)可能是代碼中手動調(diào)用 System.gc()導(dǎo)致GC次數(shù)過多。
3.2 某個(gè)業(yè)務(wù)邏輯執(zhí)行時(shí)間過長
如果是Full GC次數(shù)過多硫嘶，那么通過 jstack得到的線程信息會是類似于VM Thread之類的線程阻问，而如果是代碼中有比較耗時(shí)的計(jì)算，那么我們得到的就是一個(gè)線程的具體堆棧信息沦疾。
如下是一個(gè)代碼中有比較耗時(shí)的計(jì)算称近，導(dǎo)致CPU過高的線程信息：
這里可以看到，在請求UserController的時(shí)候哮塞，由于該Controller進(jìn)行了一個(gè)比較耗時(shí)的調(diào)用刨秆，導(dǎo)致該線程的CPU一直處于100%。
我們可以根據(jù)堆棧信息彻桃，直接定位到UserController的34行坛善，查看代碼中具體是什么原因?qū)е掠?jì)算量如此之高。
3.3 死鎖
如果有死鎖，會直接提示眠屎。關(guān)鍵字：deadlock剔交。使用jstack打印線程信息會打印出業(yè)務(wù)死鎖的位置。
3.4 線程一直處于WAITTING狀態(tài)
對于這種情況改衩，這是比較罕見的一種情況岖常，但是也是有可能出現(xiàn)的，而且由于其具有一定的 “不可復(fù)現(xiàn)性”葫督，因在排查的時(shí)候是非常難以發(fā)現(xiàn)的竭鞍。
某個(gè)線程由于某種原因而進(jìn)入WAITING狀態(tài)，此時(shí)該功能整體不可用橄镜，但是無法復(fù)現(xiàn)偎快。jstack多查詢幾次，每次間隔30秒洽胶，對比一直停留在parking 導(dǎo)致的WAITING狀態(tài)的線程晒夹。
可以通過給線程命名快速定位到是哪個(gè)業(yè)務(wù)代碼。
3.5 隨機(jī)出現(xiàn)大量線程訪問接口緩慢
對于這種情況姊氓，比較典型的例子就是丐怯，我們某個(gè)接口訪問經(jīng)常需要2~3s才能返回。
這是比較麻煩的一種情況翔横，因?yàn)橐话銇碚f读跷，其消耗的CPU不多，而且占用的內(nèi)存也不高禾唁，也就是說效览，我們通過上述兩種方式進(jìn)行排查是無法解決這種問題的。
而且由于這樣的接口耗時(shí)比較大的問題是不定時(shí)出現(xiàn)的荡短，這就導(dǎo)致了我們在通過 jstack命令即使得到了線程訪問的堆棧信息钦铺，我們也沒法判斷具體哪個(gè)線程是正在執(zhí)行比較耗時(shí)操作的線程。
對于不定時(shí)出現(xiàn)的接口耗時(shí)比較嚴(yán)重的問題肢预，我們的定位思路基本如下：
首先找到該接口，通過壓測工具不斷加大訪問力度洼哎，如果說該接口中有某個(gè)位置是比較耗時(shí)的烫映，由于我們的訪問的頻率非常高，那么大多數(shù)的線程最終都將阻塞于該阻塞點(diǎn)
這樣通過多個(gè)線程具有相同的堆棧日志噩峦，我們基本上就可以定位到該接口中比較耗時(shí)的代碼的位置锭沟。
如下是一個(gè)代碼中有比較耗時(shí)的阻塞操作通過壓測工具得到的線程堆棧日志：
從上面的日志可以看你出，這里有多個(gè)線程都阻塞在了UserController的第18行识补，說明這是一個(gè)阻塞點(diǎn)族淮，也就是導(dǎo)致該接口比較緩慢的原因。
4 總結(jié)
4.1 排查命令總結(jié)
-
top：查看系統(tǒng)進(jìn)程CPU與內(nèi)存占用情況，找到占用最多的進(jìn)程ID -
top -Hp 進(jìn)程號：查看該進(jìn)程號的所有線程CPU與內(nèi)存占用情況祝辣，找到占用最多的線程ID（顯示的PID即為10進(jìn)制線程編號贴妻，printf "%x\n" 進(jìn)程號轉(zhuǎn)為16進(jìn)制線程號） -
jstack 進(jìn)程號 >> stack.txt：將進(jìn)程號所屬進(jìn)程的堆棧信息輸出到stack.txt中 -
jstack 進(jìn)程號 | grep 16進(jìn)制線程號：查看進(jìn)程號先所屬線程的堆棧信息，可查看線程名蝙斜，區(qū)分出普通線程與GC線程（"VM Thread"）名惩。 -
jstat -gcutil 進(jìn)程號 統(tǒng)計(jì)間隔毫秒 統(tǒng)計(jì)次數(shù)（缺省代表一直統(tǒng)計(jì)）：如果是因?yàn)镚C問題，進(jìn)一步觀察GC情況 -
jmap -heap 進(jìn)程ID：查看詳細(xì)進(jìn)程內(nèi)存使用信息 -
jmap -dump:format=b,file=文件名稱 進(jìn)程ID：將進(jìn)程內(nèi)存信息dump到磁盤上供進(jìn)一步分析孕荠。 -
java -Xmx4G -jar ha457.jar：使用ha457.jar來分析內(nèi)存泄漏情況娩鹉。
4.2 異常情況解決總結(jié)
- GC問題：top+top -Hp + jstack排查是"VM Thread"消耗過多資源，可以進(jìn)一步使用jmap工具進(jìn)行內(nèi)存溢出排查稚伍。
- 業(yè)務(wù)執(zhí)行過慢問題：top+top -Hp + jstack排查發(fā)現(xiàn)是普通業(yè)務(wù)線程弯予，可看到具體是哪個(gè)接口。
- 死鎖：
jstack + Java進(jìn)程打印堆棧信息中包含死鎖信息deadlock - 線程處于waiting狀態(tài)：多打印幾次jstack信息个曙，對比一直停留在waiting狀態(tài)的線程锈嫩。
