01 引言

作為一名從事Java開(kāi)發(fā)快一年的程序員，在線上經(jīng)常碰到某個(gè)模塊的Pod發(fā)出CPU與內(nèi)存告警的問(wèn)題，而這些問(wèn)題會(huì)導(dǎo)致系統(tǒng)響應(yīng)緩慢甚至是服務(wù)不可用。一般情況下可以通過(guò)重啟或者調(diào)高Pod的資源量或者增加Pod數(shù)量暫時(shí)解決問(wèn)題，但這是治標(biāo)不治本的，只有找到問(wèn)題發(fā)生的原因才能從根本上解決問(wèn)題。那么在該如何快速定位到導(dǎo)致告警的原因呢？下面將匯總一下大致的處理思路。

一般來(lái)說(shuō)導(dǎo)致Java程序CPU與內(nèi)存沖高的原因有兩種：

• 代碼中某個(gè)位置讀取數(shù)據(jù)量較大，導(dǎo)致系統(tǒng)內(nèi)存耗盡，從而導(dǎo)致Full GC次數(shù)過(guò)多，系統(tǒng)緩慢。
• 代碼中有比較耗CPU的操作，導(dǎo)致CPU過(guò)高，系統(tǒng)運(yùn)行緩慢。
• 代碼某個(gè)位置有阻塞性的操作，導(dǎo)致該功能調(diào)用整體比較耗時(shí)，但出現(xiàn)是比較隨機(jī)的；
• 某個(gè)線程由于某種原因而進(jìn)入WAITING狀態(tài)，此時(shí)該功能整體不可用，但是無(wú)法復(fù)現(xiàn)；
• 由于鎖使用不當(dāng)，導(dǎo)致多個(gè)線程進(jìn)入死鎖狀態(tài)，從而導(dǎo)致系統(tǒng)整體比較緩慢。

前兩種情況出現(xiàn)的頻率較高，可能會(huì)導(dǎo)致系統(tǒng)不可用，后三種會(huì)導(dǎo)致某個(gè)功能運(yùn)行緩慢，但是不至于導(dǎo)致系統(tǒng)不可用。

對(duì)于第一種情況，本人曾經(jīng)遇到過(guò)某個(gè)查全量數(shù)據(jù)的接口在某段時(shí)間被頻繁調(diào)用導(dǎo)致內(nèi)存耗盡、瘋狂GC的情況：記一次GC導(dǎo)致的CPU與內(nèi)存沖高的問(wèn)題解決。下面將總結(jié)一些具體的排查步驟。

02 分析工具

01 top命令查看CPU占用情況

PID為進(jìn)程編號(hào)，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.05Tasks: 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 stKiB Mem :  3782864 total,  1477524 free,   329656 used,  1975684 buff/cacheKiB 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.35Threads:  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 stKiB Mem:   2046460 total,  1924856 used,   121604 free,    14396 buffersKiB 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。

02 用jstack查看Java線程信息

jstack 進(jìn)程號(hào) | 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è)雙引號(hào)圈起來(lái)的就是線程名，如果是“VM Thread”這就是虛擬機(jī)GC回收線程，如果是"main"則是其他線程，后面的runnable是線程狀態(tài)。

03 使用jstat查看GC信息

jstat -gcutil 進(jìn)程號(hào) 統(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á)到閾值(具體看垃圾回收器和啟動(dòng)時(shí)配置的閾值)就會(huì)進(jìn)程Full GC。

04 使用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文件過(guò)大可以使用-Xmx設(shè)置最大堆內(nèi)存大小，防止內(nèi)存溢出。

通過(guò)ha457.jar的GUI界面可以很清晰的看到各種類型的數(shù)據(jù)內(nèi)存占用情況、對(duì)象之間的引用關(guān)系以及可能存在內(nèi)存泄漏的對(duì)象。

03 原因分析

01 Full GC次數(shù)過(guò)多

相對(duì)來(lái)說(shuō)，這種情況是最容易出現(xiàn)的，尤其是新功能上線時(shí)。對(duì)于Full GC較多的情況，其主要有如下兩個(gè)特征：

• 線上多個(gè)線程的CPU都超過(guò)了100%，通過(guò)jstack命令可以看到這些線程主要是垃圾回收線程
• 通過(guò)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ù)與增長(zhǎng)情況。

進(jìn)一步分析：使用jmap -dump命令dump內(nèi)存，然后使用使用ha457.jar離線分析。

• 生成大量的對(duì)象，導(dǎo)致內(nèi)存溢出
• 內(nèi)存占用不高，但是Full GC次數(shù)還是比較多，此時(shí)可能是代碼中手動(dòng)調(diào)用 System.gc()導(dǎo)致GC次數(shù)過(guò)多。

02 某個(gè)業(yè)務(wù)邏輯執(zhí)行時(shí)間過(guò)長(zhǎng)

如果是Full GC次數(shù)過(guò)多，那么通過(guò) jstack得到的線程信息會(huì)是類似于VM Thread之類的線程，而如果是代碼中有比較耗時(shí)的計(jì)算，那么我們得到的就是一個(gè)線程的具體堆棧信息。

如下是一個(gè)代碼中有比較耗時(shí)的計(jì)算，導(dǎo)致CPU過(guò)高的線程信息：

這里可以看到，在請(qǐng)求UserController的時(shí)候，由于該Controller進(jìn)行了一個(gè)比較耗時(shí)的調(diào)用，導(dǎo)致該線程的CPU一直處于100%。我們可以根據(jù)堆棧信息，直接定位到UserController的34行，查看代碼中具體是什么原因?qū)е掠?jì)算量如此之高。

03 死鎖

如果有死鎖，會(huì)直接提示。關(guān)鍵字：deadlock。使用jstack打印線程信息會(huì)打印出業(yè)務(wù)死鎖的位置。

04 程一直處于WAITTING狀態(tài)

對(duì)于這種情況，這是比較罕見(jiàn)的一種情況，但是也是有可能出現(xiàn)的，而且由于其具有一定的 “不可復(fù)現(xiàn)性”，因在排查的時(shí)候是非常難以發(fā)現(xiàn)的。

某個(gè)線程由于某種原因而進(jìn)入WAITING狀態(tài)，此時(shí)該功能整體不可用，但是無(wú)法復(fù)現(xiàn)。jstack多查詢幾次，每次間隔30秒，對(duì)比一直停留在parking 導(dǎo)致的WAITING狀態(tài)的線程。

可以通過(guò)給線程命名快速定位到是哪個(gè)業(yè)務(wù)代碼。

05 隨機(jī)出現(xiàn)大量線程訪問(wèn)接口緩慢

對(duì)于這種情況，比較典型的例子就是，我們某個(gè)接口訪問(wèn)經(jīng)常需要2~3s才能返回。

這是比較麻煩的一種情況，因?yàn)橐话銇?lái)說(shuō)，其消耗的CPU不多，而且占用的內(nèi)存也不高，也就是說(shuō)，我們通過(guò)上述兩種方式進(jìn)行排查是無(wú)法解決這種問(wèn)題的。

而且由于這樣的接口耗時(shí)比較大的問(wèn)題是不定時(shí)出現(xiàn)的，這就導(dǎo)致了我們?cè)谕ㄟ^(guò) jstack命令即使得到了線程訪問(wèn)的堆棧信息，我們也沒(méi)法判斷具體哪個(gè)線程是正在執(zhí)行比較耗時(shí)操作的線程。

對(duì)于不定時(shí)出現(xiàn)的接口耗時(shí)比較嚴(yán)重的問(wèn)題，我們的定位思路基本如下：

首先找到該接口，通過(guò)壓測(cè)工具不斷加大訪問(wèn)力度，如果說(shuō)該接口中有某個(gè)位置是比較耗時(shí)的，由于我們的訪問(wèn)的頻率非常高，那么大多數(shù)的線程最終都將阻塞于該阻塞點(diǎn)

這樣通過(guò)多個(gè)線程具有相同的堆棧日志，我們基本上就可以定位到該接口中比較耗時(shí)的代碼的位置。

如下是一個(gè)代碼中有比較耗時(shí)的阻塞操作通過(guò)壓測(cè)工具得到的線程堆棧日志：

從上面的日志可以看你出，這里有多個(gè)線程都阻塞在了UserController的第18行，說(shuō)明這是一個(gè)阻塞點(diǎn)，也就是導(dǎo)致該接口比較緩慢的原因。

04 總結(jié)

1、排查命令總結(jié)

• top：

查看系統(tǒng)進(jìn)程CPU與內(nèi)存占用情況，找到占用最多的進(jìn)程ID

• top -Hp 進(jìn)程號(hào)：

查看該進(jìn)程號(hào)的所有線程CPU與內(nèi)存占用情況，找到占用最多的線程ID（顯示的PID即為10進(jìn)制線程編號(hào)，printf "%x\n" 進(jìn)程號(hào)轉(zhuǎn)為16進(jìn)制線程號(hào)）

• jstack 進(jìn)程號(hào) >> stack.txt：

將進(jìn)程號(hào)所屬進(jìn)程的堆棧信息輸出到stack.txt中

• jstack 進(jìn)程號(hào) | grep 16進(jìn)制線程號(hào)：

查看進(jìn)程號(hào)先所屬線程的堆棧信息，可查看線程名，區(qū)分出普通線程與GC線程（"VM Thread"）。

• jstat -gcutil 進(jìn)程號(hào) 統(tǒng)計(jì)間隔毫秒 統(tǒng)計(jì)次數(shù)（缺省代表一直統(tǒng)計(jì)）：

如果是因?yàn)镚C問(wèn)題，進(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來(lái)分析內(nèi)存泄漏情況。

2、異常情況解決總結(jié)

• GC問(wèn)題：

top+top -Hp + jstack排查是"VM Thread"消耗過(guò)多資源，可以進(jìn)一步使用jmap工具進(jìn)行內(nèi)存溢出排查。

• 業(yè)務(wù)執(zhí)行過(guò)慢問(wèn)題：

top+top -Hp + jstack排查發(fā)現(xiàn)是普通業(yè)務(wù)線程，可看到具體是哪個(gè)接口。

• 死鎖：

jstack + Java進(jìn)程打印堆棧信息中包含死鎖信息deadlock

• 線程處于waiting狀態(tài)：

多打印幾次jstack信息，對(duì)比一直停留在waiting狀態(tài)的線程。

總結(jié)

到此這篇關(guān)于Java線上CPU內(nèi)存沖高問(wèn)題排查解決的文章就介紹到這了,更多相關(guān)Java線上CPU內(nèi)存沖高內(nèi)容請(qǐng)搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關(guān)文章希望大家以后多多支持腳本之家！

最新評(píng)論