2019獨(dú)角獸企業(yè)重金招聘Python工程師標(biāo)準(zhǔn)>>>

背景：Java線(xiàn)上服務(wù)運(yùn)行一周后，某個(gè)周六晚上CPU使用率突然持續(xù)99%，Java進(jìn)程處于假死狀態(tài)，不響應(yīng)請(qǐng)求。秉著先恢復(fù)服務(wù)再排查問(wèn)題的原則，在我連接VPN采用重啟大法后，CPU使用率恢復(fù)正常，服務(wù)也正常響應(yīng)了，如下圖一所示：

如果想學(xué)習(xí)Java工程化、高性能及分布式、深入淺出。微服務(wù)、Spring，MyBatis，Netty源碼分析的朋友可以加我的Java高級(jí)交流：854630135，群里有阿里大牛直播講解技術(shù)，以及Java大型互聯(lián)網(wǎng)技術(shù)的視頻免費(fèi)分享給大家。

?

（圖一）CPU使用率圖

但是，當(dāng)晚的并發(fā)量也沒(méi)有比平時(shí)高出許多，為什么會(huì)突然出現(xiàn)這種CPU爆表的情況？帶著這個(gè)疑問(wèn)，我走上了問(wèn)題排查的道路。

首先，我查了相關(guān)的錯(cuò)誤日志，發(fā)現(xiàn)故障的時(shí)間段內(nèi)有大量的ckv請(qǐng)求超時(shí)，但請(qǐng)求超時(shí)并不是ckv server的問(wèn)題，而是ckv client的請(qǐng)求并沒(méi)有發(fā)出去。那么，為什么ckv client的請(qǐng)求沒(méi)有發(fā)出去呢？日志并沒(méi)有提供更多的信息給我。

于是，我在Java服務(wù)上開(kāi)啟了JMX，本地采用jvisualvm來(lái)觀(guān)察Java進(jìn)程運(yùn)行時(shí)的堆棧內(nèi)存、線(xiàn)程使用情況。JMX（Java Management Extensions，即Java管理擴(kuò)展）是Java平臺(tái)上為應(yīng)用程序、設(shè)備、系統(tǒng)等植入管理功能的框架；jvisualvm是JDK內(nèi)置的性能分析工具，位于JDK根目錄的bin文件夾下面，它可以通過(guò)JMX從Java程序獲取運(yùn)行時(shí)的實(shí)時(shí)數(shù)據(jù)，從而進(jìn)行動(dòng)態(tài)的性能分析，如圖二所示：

?

（圖二）jvisualvm

通過(guò)觀(guān)察Heap內(nèi)存的使用情況，發(fā)現(xiàn)其是緩慢增加的，每隔一小段時(shí)間被GC回收，圖形呈鋸齒狀，似乎沒(méi)有什么問(wèn)題；Threads也沒(méi)有存在死鎖的問(wèn)題，線(xiàn)程運(yùn)行良好；在Sampler查看Thread CPU Time的時(shí)候發(fā)現(xiàn)，log4j的異步日志線(xiàn)程占用的CPU時(shí)間是最多的。于是，初步懷疑這是log4j的鍋。接著，我對(duì)項(xiàng)目代碼進(jìn)行了review，發(fā)現(xiàn)某些接口打印了大量的無(wú)用日志，日志級(jí)別使用也不規(guī)范。最后，我對(duì)項(xiàng)目的日志進(jìn)行了整體的梳理，優(yōu)化后發(fā)布上線(xiàn)，并繼續(xù)觀(guān)察。

我本以為問(wèn)題已經(jīng)解決了。然而，幾天后又出現(xiàn)了CPU爆表的情況，這時(shí)，我才發(fā)現(xiàn)自己錯(cuò)怪了log4j。與上次爆表的情況不同，這次我在公司（表示很淡定），于是我機(jī)智地保留了一臺(tái)機(jī)器來(lái)做觀(guān)察，其他機(jī)器做重啟處理?，F(xiàn)在，要開(kāi)始我的表演了，具體如下：

（1）登陸機(jī)器，用 top 命令查看進(jìn)程資源占用情況。不出所料，Java進(jìn)程把CPU撐爆了，如下圖三所示：

?

（圖三）進(jìn)程資源占用情況

（2）Java進(jìn)程把CPU都占用完了，那么具體是進(jìn)程內(nèi)的哪些線(xiàn)程占用的呢？于是，我用了 top -H -p6902 （6902是Java進(jìn)程的PID）命令找出了具體的線(xiàn)程資源占用情況，如下圖四所示：

?

（圖四）Java線(xiàn)程資源占用情況

圖四中的PID為Java線(xiàn)程的id，可以看到id為6904、6905、6906、6907這四個(gè)線(xiàn)程基本把CPU資源全部吃完了。

（3）現(xiàn)在，我們已經(jīng)拿到耗盡CPU資源的線(xiàn)程id了。這時(shí)，我們就可以使用jstack來(lái)查找這些id對(duì)應(yīng)的具體線(xiàn)程堆棧信息了。jstack是JDK內(nèi)置的堆棧跟蹤工具，位于JDK根目錄的bin文件夾下面，可用于打印的Java堆棧信息。我用命令 jstack 6902 > jstack.txt （6902是Java進(jìn)程的PID）打印出了Java進(jìn)程的堆棧信息放到j(luò)stack.txt文件了；由于堆棧打印的線(xiàn)程的native id是十六機(jī)制的，所以，我把十進(jìn)制的線(xiàn)程id（6904、6905、6906、6907）轉(zhuǎn)化成十六進(jìn)制（0x1af8、0x1af9、0x1afa、0x1afb）；最后，通過(guò) cat jstack.txt | grep -C 20 0x1af8 命令找到了具體的線(xiàn)程信息，如下圖五所示：

?

（圖五）線(xiàn)程堆棧信息

如果想學(xué)習(xí)Java工程化、高性能及分布式、深入淺出。微服務(wù)、Spring，MyBatis，Netty源碼分析的朋友可以加我的Java高級(jí)交流：854630135，群里有阿里大牛直播講解技術(shù)，以及Java大型互聯(lián)網(wǎng)技術(shù)的視頻免費(fèi)分享給大家。

通過(guò)圖五可以發(fā)現(xiàn)，把CPU占滿(mǎn)的線(xiàn)程是GC的線(xiàn)程，Java的垃圾回收把CPU的資源耗盡了。

（4）現(xiàn)在，我們已經(jīng)定位到是GC的問(wèn)題了。那么，我們就來(lái)看看GC的回收情況，我們可以通過(guò)jstat來(lái)觀(guān)察。jstat是JDK內(nèi)置的JVM檢測(cè)統(tǒng)計(jì)工具，位于JDK根目錄的bin文件夾下面，可以對(duì)堆內(nèi)存的使用情況進(jìn)行實(shí)時(shí)統(tǒng)計(jì)。我使用了命令 jstat -gcutil 6902 2000 10 （6902是Java進(jìn)程的PID）來(lái)觀(guān)察GC的運(yùn)行信息，如下圖六所示：

?

（圖六）GC運(yùn)行信息

通過(guò)圖六可以知道，E（Eden區(qū)）跟O（Old區(qū)）的內(nèi)存已經(jīng)被耗盡了，FGC（Full GC）的次數(shù)高達(dá)6989次，FGCT（Full GC Time）的時(shí)間高達(dá)36453秒，即平均每次FGC的時(shí)間為：36453/6989 ≈ 5.21秒。也就是說(shuō)，Java進(jìn)程都把時(shí)間花在GC上了，所以就沒(méi)有時(shí)間來(lái)處理其他事情。

（5）GC出現(xiàn)圖六的這種情況，基本可以確認(rèn)是在程序中存在內(nèi)存泄露的問(wèn)題。那么，如何確定是哪些代碼導(dǎo)致的這個(gè)問(wèn)題呢？這時(shí)候，我們就可以使用jmap查看Java的內(nèi)存占用信息。jmap是JDK內(nèi)置的內(nèi)存映射工具，位于JDK根目錄的bin文件夾下面，可用于獲取java進(jìn)程的內(nèi)存映射信息。通過(guò)命令 jmap -histo 6902 （6902是Java進(jìn)程的PID）打印出了Java的內(nèi)存占用信息，如下圖七所示：

?

（圖七）Java內(nèi)存占用信息

由圖七可以得到，占用內(nèi)存資源的TOP10類(lèi)（[C 是指char[]，String類(lèi)內(nèi)部使用char[]來(lái)保存數(shù)據(jù)）的名稱(chēng)、實(shí)例數(shù)以及占用內(nèi)存大小（單位：byte），于是問(wèn)題排查就變得非常簡(jiǎn)單了。最后，通過(guò)review代碼確定了問(wèn)題所在：

部分接口使用到了L5QOSPacket這個(gè)L5的工具類(lèi)沒(méi)有做單例，每次請(qǐng)求接口都會(huì)生成一個(gè)新的實(shí)例，浪費(fèi)了大量的內(nèi)存。

代碼里邊用到的一個(gè)第三方提供的QcClient客戶(hù)端存在內(nèi)存泄露問(wèn)題，代碼中不恰當(dāng)?shù)豱ew了大量的對(duì)象，而且對(duì)存儲(chǔ)在ConcurrentHashMap的數(shù)據(jù)沒(méi)有做清除清理，從而導(dǎo)致數(shù)據(jù)一直累計(jì)，內(nèi)存占用持續(xù)增加。

解決以上兩個(gè)問(wèn)題后，Heap內(nèi)存的占用維持在2.5G左右，已經(jīng)沒(méi)有持續(xù)增長(zhǎng)的跡象了，業(yè)務(wù)已正常運(yùn)行。

以上就是我排查問(wèn)題的整個(gè)過(guò)程，以及在這個(gè)過(guò)程中用到的一些Java性能監(jiān)測(cè)工具。除了本文提及的jvisualvm、jstack、jstat、jmap這些工具，在JDK根目錄的bin文件夾下面還有其他許多非常有用的工具，例如：使用 jinfo 查看Java進(jìn)程相關(guān)信息，感興趣的童鞋可以去研究下。

如果想學(xué)習(xí)Java工程化、高性能及分布式、深入淺出。微服務(wù)、Spring，MyBatis，Netty源碼分析的朋友可以加我的Java高級(jí)交流：854630135，群里有阿里大牛直播講解技術(shù)，以及Java大型互聯(lián)網(wǎng)技術(shù)的視頻免費(fèi)分享給大家。

轉(zhuǎn)載于:https://my.oschina.net/u/3990817/blog/3013624

總結(jié)

以上是生活随笔為你收集整理的做JAVA开发的同学一定遇到过的爆表问题，看这里解决的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問(wèn)題。

如果覺(jué)得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。