必备面试题:系统CPU飙高和GC频繁,如何排查?
來(lái)源:http://t.cn/EI9JdBu
處理過(guò)線上問(wèn)題的同學(xué)基本上都會(huì)遇到系統(tǒng)突然運(yùn)行緩慢,CPU 100%,以及Full GC次數(shù)過(guò)多的問(wèn)題。當(dāng)然,這些問(wèn)題的最終導(dǎo)致的直觀現(xiàn)象就是系統(tǒng)運(yùn)行緩慢,并且有大量的報(bào)警。本文主要針對(duì)系統(tǒng)運(yùn)行緩慢這一問(wèn)題,提供該問(wèn)題的排查思路,從而定位出問(wèn)題的代碼點(diǎn),進(jìn)而提供解決該問(wèn)題的思路。
對(duì)于線上系統(tǒng)突然產(chǎn)生的運(yùn)行緩慢問(wèn)題,如果該問(wèn)題導(dǎo)致線上系統(tǒng)不可用,那么首先需要做的就是,導(dǎo)出jstack和內(nèi)存信息,然后重啟系統(tǒng),盡快保證系統(tǒng)的可用性。這種情況可能的原因主要有兩種:
-
代碼中某個(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)行緩慢;
相對(duì)來(lái)說(shuō),這是出現(xiàn)頻率最高的兩種線上問(wèn)題,而且它們會(huì)直接導(dǎo)致系統(tǒng)不可用。另外有幾種情況也會(huì)導(dǎo)致某個(gè)功能運(yùn)行緩慢,但是不至于導(dǎo)致系統(tǒng)不可用:
-
代碼某個(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)整體比較緩慢。
對(duì)于這三種情況,通過(guò)查看CPU和系統(tǒng)內(nèi)存情況是無(wú)法查看出具體問(wèn)題的,因?yàn)樗鼈兿鄬?duì)來(lái)說(shuō)都是具有一定阻塞性操作,CPU和系統(tǒng)內(nèi)存使用情況都不高,但是功能卻很慢。下面我們就通過(guò)查看系統(tǒng)日志來(lái)一步一步甄別上述幾種問(wèn)題。
1. 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命令查看系統(tǒng)CPU的占用情況,如下是系統(tǒng)CPU較高的一個(gè)示例:
top?-?08:31:10?up?30?min,??0?users,??load?average:?0.73,?0.58,?0.34 KiB?Mem:???2046460?total,??1923864?used,???122596?free,????14388?buffers KiB?Swap:??1048572?total,????????0?used,??1048572?free.??1192352?cached?MemPID?USER??????PR??NI????VIRT????RES????SHR?S??%CPU?%MEM?????TIME+?COMMAND9?root??????20???0?2557160?288976??15812?S??98.0?14.1???0:42.60?java可以看到,有一個(gè)Java程序此時(shí)CPU占用量達(dá)到了98.8%,此時(shí)我們可以復(fù)制該進(jìn)程id9,并且使用如下命令查看呢該進(jìn)程的各個(gè)線程運(yùn)行情況:
top?-Hp?9
該進(jìn)程下的各個(gè)線程運(yùn)行情況如下:
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?MemPID?USER??????PR??NI????VIRT????RES????SHR?S?%CPU?%MEM?????TIME+?COMMAND10?root??????20???0?2557160?289824??15872?R?79.3?14.2???0:41.49?java11?root??????20???0?2557160?289824??15872?S?13.2?14.2???0:06.78?java可以看到,在進(jìn)程為9的Java程序中各個(gè)線程的CPU占用情況,接下來(lái)我們可以通過(guò)jstack命令查看線程id為10的線程為什么耗費(fèi)CPU最高。需要注意的是,在jsatck命令展示的結(jié)果中,線程id都轉(zhuǎn)換成了十六進(jìn)制形式。可以用如下命令查看轉(zhuǎn)換結(jié)果,也可以找一個(gè)科學(xué)計(jì)算器進(jìn)行轉(zhuǎn)換:
root@a39de7e7934b:/#?printf?"%x\n"?10 a這里打印結(jié)果說(shuō)明該線程在jstack中的展現(xiàn)形式為0xa,通過(guò)jstack命令我們可以看到如下信息:
"main"?#1?prio=5?os_prio=0?tid=0x00007f8718009800?nid=0xb?runnable?[0x00007f871fe41000]java.lang.Thread.State:?RUNNABLEat?com.aibaobei.chapter2.eg2.UserDemo.main(UserDemo.java:9)"VM?Thread"?os_prio=0?tid=0x00007f871806e000?nid=0xa?runnable這里的VM Thread一行的最后顯示nid=0xa,這里nid的意思就是操作系統(tǒng)線程id的意思。而VM Thread指的就是垃圾回收的線程。這里我們基本上可以確定,當(dāng)前系統(tǒng)緩慢的原因主要是垃圾回收過(guò)于頻繁,導(dǎo)致GC停頓時(shí)間較長(zhǎng)。我們通過(guò)如下命令可以查看GC的情況:
root@8d36124607a0:/#?jstat?-gcutil?9?1000?10S0?????S1?????E??????O??????M?????CCS????YGC?????YGCT????FGC????FGCT?????GCT0.00???0.00???0.00??75.07??59.09??59.60???3259????0.919??6517????7.715????8.6350.00???0.00???0.00???0.08??59.09??59.60???3306????0.930??6611????7.822????8.7520.00???0.00???0.00???0.08??59.09??59.60???3351????0.943??6701????7.924????8.8670.00???0.00???0.00???0.08??59.09??59.60???3397????0.955??6793????8.029????8.984可以看到,這里FGC指的是Full GC數(shù)量,這里高達(dá)6793,而且還在不斷增長(zhǎng)。從而進(jìn)一步證實(shí)了是由于內(nèi)存溢出導(dǎo)致的系統(tǒng)緩慢。那么這里確認(rèn)了內(nèi)存溢出,但是如何查看你是哪些對(duì)象導(dǎo)致的內(nèi)存溢出呢,這個(gè)可以dump出內(nèi)存日志,然后通過(guò)eclipse的mat工具進(jìn)行查看,如下是其展示的一個(gè)對(duì)象樹(shù)結(jié)構(gòu):
經(jīng)過(guò)mat工具分析之后,我們基本上就能確定內(nèi)存中主要是哪個(gè)對(duì)象比較消耗內(nèi)存,然后找到該對(duì)象的創(chuàng)建位置,進(jìn)行處理即可。這里的主要是PrintStream最多,但是我們也可以看到,其內(nèi)存消耗量只有12.2%。也就是說(shuō),其還不足以導(dǎo)致大量的Full GC,此時(shí)我們需要考慮另外一種情況,就是代碼或者第三方依賴的包中有顯示的System.gc()調(diào)用。這種情況我們查看dump內(nèi)存得到的文件即可判斷,因?yàn)槠鋾?huì)打印GC原因:
[Full?GC?(System.gc())?[Tenured:?262546K->262546K(349568K),?0.0014879?secs]?262546K->262546K(506816K),?[Metaspace:?3109K->3109K(1056768K)],?0.0015151?secs]?[Times:?user=0.00?sys=0.00,?real=0.01?secs] [GC?(Allocation?Failure)?[DefNew:?2795K->0K(157248K),?0.0001504?secs][Tenured:?262546K->402K(349568K),?0.0012949?secs]?265342K->402K(506816K),?[Metaspace:?3109K->3109K(1056768K)],?0.0014699?secs]?[Times:?user=0.00比如這里第一次GC是由于System.gc()的顯示調(diào)用導(dǎo)致的,而第二次GC則是JVM主動(dòng)發(fā)起的。總結(jié)來(lái)說(shuō),對(duì)于Full GC次數(shù)過(guò)多,主要有以下兩種原因:
-
代碼中一次獲取了大量的對(duì)象,導(dǎo)致內(nèi)存溢出,此時(shí)可以通過(guò)eclipse的mat工具查看內(nèi)存中有哪些對(duì)象比較多;
-
內(nèi)存占用不高,但是Full GC次數(shù)還是比較多,此時(shí)可能是顯示的System.gc()調(diào)用導(dǎo)致GC次數(shù)過(guò)多,這可以通過(guò)添加-XX:+DisableExplicitGC來(lái)禁用JVM對(duì)顯示GC的響應(yīng)。
2. CPU過(guò)高
在前面第一點(diǎn)中,我們講到,CPU過(guò)高可能是系統(tǒng)頻繁的進(jìn)行Full GC,導(dǎo)致系統(tǒng)緩慢。而我們平常也肯能遇到比較耗時(shí)的計(jì)算,導(dǎo)致CPU過(guò)高的情況,此時(shí)查看方式其實(shí)與上面的非常類似。首先我們通過(guò)top命令查看當(dāng)前CPU消耗過(guò)高的進(jìn)程是哪個(gè),從而得到進(jìn)程id;然后通過(guò)top -Hp <pid>來(lái)查看該進(jìn)程中有哪些線程CPU過(guò)高,一般超過(guò)80%就是比較高的,80%左右是合理情況。這樣我們就能得到CPU消耗比較高的線程id。接著通過(guò)該線程id的十六進(jìn)制表示在jstack日志中查看當(dāng)前線程具體的堆棧信息。
在這里我們就可以區(qū)分導(dǎo)致CPU過(guò)高的原因具體是Full GC次數(shù)過(guò)多還是代碼中有比較耗時(shí)的計(jì)算了。如果是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ì)算量如此之高。
3. 不定期出現(xiàn)的接口耗時(shí)現(xià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è)工具得到的線程堆棧日志:
"http-nio-8080-exec-2"?#29?daemon?prio=5?os_prio=31?tid=0x00007fd08cb26000?nid=0x9603?waiting?on?condition?[0x00007000031d5000]java.lang.Thread.State:?TIMED_WAITING?(sleeping)at?java.lang.Thread.sleep(Native?Method)at?java.lang.Thread.sleep(Thread.java:340)at?java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)at?com.aibaobei.user.controller.UserController.detail(UserController.java:18)"http-nio-8080-exec-3"?#30?daemon?prio=5?os_prio=31?tid=0x00007fd08cb27000?nid=0x6203?waiting?on?condition?[0x00007000032d8000]java.lang.Thread.State:?TIMED_WAITING?(sleeping)at?java.lang.Thread.sleep(Native?Method)at?java.lang.Thread.sleep(Thread.java:340)at?java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)at?com.aibaobei.user.controller.UserController.detail(UserController.java:18)"http-nio-8080-exec-4"?#31?daemon?prio=5?os_prio=31?tid=0x00007fd08d0fa000?nid=0x6403?waiting?on?condition?[0x00007000033db000]java.lang.Thread.State:?TIMED_WAITING?(sleeping)at?java.lang.Thread.sleep(Native?Method)at?java.lang.Thread.sleep(Thread.java:340)at?java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)at?com.aibaobei.user.controller.UserController.detail(UserController.java:18)從上面的日志可以看你出,這里有多個(gè)線程都阻塞在了UserController的第18行,說(shuō)明這是一個(gè)阻塞點(diǎn),也就是導(dǎo)致該接口比較緩慢的原因。
4. 某個(gè)線程進(jìn)入WAITING狀態(tài)
對(duì)于這種情況,這是比較罕見(jiàn)的一種情況,但是也是有可能出現(xiàn)的,而且由于其具有一定的“不可復(fù)現(xiàn)性”,因而我們?cè)谂挪榈臅r(shí)候是非常難以發(fā)現(xiàn)的。筆者曾經(jīng)就遇到過(guò)類似的這種情況,具體的場(chǎng)景是,在使用CountDownLatch時(shí),由于需要每一個(gè)并行的任務(wù)都執(zhí)行完成之后才會(huì)喚醒主線程往下執(zhí)行。而當(dāng)時(shí)我們是通過(guò)CountDownLatch控制多個(gè)線程連接并導(dǎo)出用戶的gmail郵箱數(shù)據(jù),這其中有一個(gè)線程連接上了用戶郵箱,但是連接被服務(wù)器掛起了,導(dǎo)致該線程一直在等待服務(wù)器的響應(yīng)。最終導(dǎo)致我們的主線程和其余幾個(gè)線程都處于WAITING狀態(tài)。
對(duì)于這樣的問(wèn)題,查看過(guò)jstack日志的讀者應(yīng)該都知道,正常情況下,線上大多數(shù)線程都是處于TIMED_WAITING狀態(tài),而我們這里出問(wèn)題的線程所處的狀態(tài)與其是一模一樣的,這就非常容易混淆我們的判斷。解決這個(gè)問(wèn)題的思路主要如下:
-
通過(guò)grep在jstack日志中找出所有的處于TIMED_WAITING狀態(tài)的線程,將其導(dǎo)出到某個(gè)文件中,如a1.log,如下是一個(gè)導(dǎo)出的日志文件示例:
-
等待一段時(shí)間之后,比如10s,再次對(duì)jstack日志進(jìn)行g(shù)rep,將其導(dǎo)出到另一個(gè)文件,如a2.log,結(jié)果如下所示:
-
重復(fù)步驟2,待導(dǎo)出3~4個(gè)文件之后,我們對(duì)導(dǎo)出的文件進(jìn)行對(duì)比,找出其中在這幾個(gè)文件中一直都存在的用戶線程,這個(gè)線程基本上就可以確認(rèn)是包含了處于等待狀態(tài)有問(wèn)題的線程。因?yàn)檎5恼?qǐng)求線程是不會(huì)在20~30s之后還是處于等待狀態(tài)的。
-
經(jīng)過(guò)排查得到這些線程之后,我們可以繼續(xù)對(duì)其堆棧信息進(jìn)行排查,如果該線程本身就應(yīng)該處于等待狀態(tài),比如用戶創(chuàng)建的線程池中處于空閑狀態(tài)的線程,那么這種線程的堆棧信息中是不會(huì)包含用戶自定義的類的。這些都可以排除掉,而剩下的線程基本上就可以確認(rèn)是我們要找的有問(wèn)題的線程。通過(guò)其堆棧信息,我們就可以得出具體是在哪個(gè)位置的代碼導(dǎo)致該線程處于等待狀態(tài)了。
這里需要說(shuō)明的是,我們?cè)谂袛嗍欠駷橛脩艟€程時(shí),可以通過(guò)線程最前面的線程名來(lái)判斷,因?yàn)橐话愕目蚣艿木€程命名都是非常規(guī)范的,我們通過(guò)線程名就可以直接判斷得出該線程是某些框架中的線程,這種線程基本上可以排除掉。而剩余的,比如上面的Thread-0,以及我們可以辨別的自定義線程名,這些都是我們需要排查的對(duì)象。
經(jīng)過(guò)上面的方式進(jìn)行排查之后,我們基本上就可以得出這里的Thread-0就是我們要找的線程,通過(guò)查看其堆棧信息,我們就可以得到具體是在哪個(gè)位置導(dǎo)致其處于等待狀態(tài)了。如下示例中則是在SyncTask的第8行導(dǎo)致該線程進(jìn)入等待了。
"Thread-0"?#11?prio=5?os_prio=31?tid=0x00007f9de08c7000?nid=0x5603?waiting?on?condition?[0x0000700001f89000]java.lang.Thread.State:?WAITING?(parking)at?sun.misc.Unsafe.park(Native?Method)at?java.util.concurrent.locks.LockSupport.park(LockSupport.java:304)at?com.aibaobei.chapter2.eg4.SyncTask.lambda$main$0(SyncTask.java:8)at?com.aibaobei.chapter2.eg4.SyncTask$$Lambda$1/1791741888.run(Unknown?Source)at?java.lang.Thread.run(Thread.java:748)5. 死鎖
對(duì)于死鎖,這種情況基本上很容易發(fā)現(xiàn),因?yàn)閖stack可以幫助我們檢查死鎖,并且在日志中打印具體的死鎖線程信息。如下是一個(gè)產(chǎn)生死鎖的一個(gè)jstack日志示例:
可以看到,在jstack日志的底部,其直接幫我們分析了日志中存在哪些死鎖,以及每個(gè)死鎖的線程堆棧信息。這里我們有兩個(gè)用戶線程分別在等待對(duì)方釋放鎖,而被阻塞的位置都是在ConnectTask的第5行,此時(shí)我們就可以直接定位到該位置,并且進(jìn)行代碼分析,從而找到產(chǎn)生死鎖的原因。
6. 小結(jié)
本文主要講解了線上可能出現(xiàn)的五種導(dǎo)致系統(tǒng)緩慢的情況,詳細(xì)分析了每種情況產(chǎn)生時(shí)的現(xiàn)象,已經(jīng)根據(jù)現(xiàn)象我們可以通過(guò)哪些方式定位得到是這種原因?qū)е碌南到y(tǒng)緩慢。簡(jiǎn)要的說(shuō),我們進(jìn)行線上日志分析時(shí),主要可以分為如下步驟:
-
通過(guò)?top命令查看CPU情況,如果CPU比較高,則通過(guò)top -Hp <pid>命令查看當(dāng)前進(jìn)程的各個(gè)線程運(yùn)行情況,找出CPU過(guò)高的線程之后,將其線程id轉(zhuǎn)換為十六進(jìn)制的表現(xiàn)形式,然后在jstack日志中查看該線程主要在進(jìn)行的工作。這里又分為兩種情況
-
如果是正常的用戶線程,則通過(guò)該線程的堆棧信息查看其具體是在哪處用戶代碼處運(yùn)行比較消耗CPU;
-
如果該線程是VM Thread,則通過(guò)jstat -gcutil <pid> <period> <times>命令監(jiān)控當(dāng)前系統(tǒng)的GC狀況,然后通過(guò)jmap dump:format=b,file=<filepath> <pid>導(dǎo)出系統(tǒng)當(dāng)前的內(nèi)存數(shù)據(jù)。導(dǎo)出之后將內(nèi)存情況放到eclipse的mat工具中進(jìn)行分析即可得出內(nèi)存中主要是什么對(duì)象比較消耗內(nèi)存,進(jìn)而可以處理相關(guān)代碼;
-
如果通過(guò)?top?命令看到CPU并不高,并且系統(tǒng)內(nèi)存占用率也比較低。此時(shí)就可以考慮是否是由于另外三種情況導(dǎo)致的問(wèn)題。具體的可以根據(jù)具體情況分析:
-
如果是接口調(diào)用比較耗時(shí),并且是不定時(shí)出現(xiàn),則可以通過(guò)壓測(cè)的方式加大阻塞點(diǎn)出現(xiàn)的頻率,從而通過(guò)jstack查看堆棧信息,找到阻塞點(diǎn);
-
如果是某個(gè)功能突然出現(xiàn)停滯的狀況,這種情況也無(wú)法復(fù)現(xiàn),此時(shí)可以通過(guò)多次導(dǎo)出jstack日志的方式對(duì)比哪些用戶線程是一直都處于等待狀態(tài),這些線程就是可能存在問(wèn)題的線程;
-
如果通過(guò)jstack可以查看到死鎖狀態(tài),則可以檢查產(chǎn)生死鎖的兩個(gè)線程的具體阻塞點(diǎn),從而處理相應(yīng)的問(wèn)題。
本文主要是提出了五種常見(jiàn)的導(dǎo)致線上功能緩慢的問(wèn)題,以及排查思路。當(dāng)然,線上的問(wèn)題出現(xiàn)的形式是多種多樣的,也不一定局限于這幾種情況,如果我們能夠仔細(xì)分析這些問(wèn)題出現(xiàn)的場(chǎng)景,就可以根據(jù)具體情況具體分析,從而解決相應(yīng)的問(wèn)題。
總結(jié)
以上是生活随笔為你收集整理的必备面试题:系统CPU飙高和GC频繁,如何排查?的全部?jī)?nèi)容,希望文章能夠幫你解決所遇到的問(wèn)題。
- 上一篇: 你在京东购买的商品,是怎么出现在抖音里面
- 下一篇: 抓住职场的快车道