做JAVA开发的同学一定遇到过的爆表问题，看这里解决
2019獨角獸企業(yè)重金招聘Python工程師標準>>>
背景：Java線上服務運行一周后，某個周六晚上CPU使用率突然持續(xù)99%，Java進程處于假死狀態(tài)，不響應請求。秉著先恢復服務再排查問題的原則，在我連接VPN采用重啟大法后，CPU使用率恢復正常，服務也正常響應了，如下圖一所示：
如果想學習Java工程化、高性能及分布式、深入淺出。微服務、Spring，MyBatis，Netty源碼分析的朋友可以加我的Java高級交流：854630135，群里有阿里大牛直播講解技術(shù)，以及Java大型互聯(lián)網(wǎng)技術(shù)的視頻免費分享給大家。
?
（圖一）CPU使用率圖
但是，當晚的并發(fā)量也沒有比平時高出許多，為什么會突然出現(xiàn)這種CPU爆表的情況？帶著這個疑問，我走上了問題排查的道路。
首先，我查了相關的錯誤日志，發(fā)現(xiàn)故障的時間段內(nèi)有大量的ckv請求超時，但請求超時并不是ckv server的問題，而是ckv client的請求并沒有發(fā)出去。那么，為什么ckv client的請求沒有發(fā)出去呢？日志并沒有提供更多的信息給我。
于是，我在Java服務上開啟了JMX，本地采用jvisualvm來觀察Java進程運行時的堆棧內(nèi)存、線程使用情況。JMX（Java Management Extensions，即Java管理擴展）是Java平臺上為應用程序、設備、系統(tǒng)等植入管理功能的框架；jvisualvm是JDK內(nèi)置的性能分析工具，位于JDK根目錄的bin文件夾下面，它可以通過JMX從Java程序獲取運行時的實時數(shù)據(jù)，從而進行動態(tài)的性能分析，如圖二所示：
?
（圖二）jvisualvm
通過觀察Heap內(nèi)存的使用情況，發(fā)現(xiàn)其是緩慢增加的，每隔一小段時間被GC回收，圖形呈鋸齒狀，似乎沒有什么問題；Threads也沒有存在死鎖的問題，線程運行良好；在Sampler查看Thread CPU Time的時候發(fā)現(xiàn)，log4j的異步日志線程占用的CPU時間是最多的。于是，初步懷疑這是log4j的鍋。接著，我對項目代碼進行了review，發(fā)現(xiàn)某些接口打印了大量的無用日志，日志級別使用也不規(guī)范。最后，我對項目的日志進行了整體的梳理，優(yōu)化后發(fā)布上線，并繼續(xù)觀察。
我本以為問題已經(jīng)解決了。然而，幾天后又出現(xiàn)了CPU爆表的情況，這時，我才發(fā)現(xiàn)自己錯怪了log4j。與上次爆表的情況不同，這次我在公司（表示很淡定），于是我機智地保留了一臺機器來做觀察，其他機器做重啟處理。現(xiàn)在，要開始我的表演了，具體如下：
（1）登陸機器，用 top 命令查看進程資源占用情況。不出所料，Java進程把CPU撐爆了，如下圖三所示：
?
（圖三）進程資源占用情況
（2）Java進程把CPU都占用完了，那么具體是進程內(nèi)的哪些線程占用的呢？于是，我用了 top -H -p6902 （6902是Java進程的PID）命令找出了具體的線程資源占用情況，如下圖四所示：
?
（圖四）Java線程資源占用情況
圖四中的PID為Java線程的id，可以看到id為6904、6905、6906、6907這四個線程基本把CPU資源全部吃完了。
（3）現(xiàn)在，我們已經(jīng)拿到耗盡CPU資源的線程id了。這時，我們就可以使用jstack來查找這些id對應的具體線程堆棧信息了。jstack是JDK內(nèi)置的堆棧跟蹤工具，位于JDK根目錄的bin文件夾下面，可用于打印的Java堆棧信息。我用命令 jstack 6902 > jstack.txt （6902是Java進程的PID）打印出了Java進程的堆棧信息放到jstack.txt文件了；由于堆棧打印的線程的native id是十六機制的，所以，我把十進制的線程id（6904、6905、6906、6907）轉(zhuǎn)化成十六進制（0x1af8、0x1af9、0x1afa、0x1afb）；最后，通過 cat jstack.txt | grep -C 20 0x1af8 命令找到了具體的線程信息，如下圖五所示：
?
（圖五）線程堆棧信息
如果想學習Java工程化、高性能及分布式、深入淺出。微服務、Spring，MyBatis，Netty源碼分析的朋友可以加我的Java高級交流：854630135，群里有阿里大牛直播講解技術(shù)，以及Java大型互聯(lián)網(wǎng)技術(shù)的視頻免費分享給大家。
通過圖五可以發(fā)現(xiàn)，把CPU占滿的線程是GC的線程，Java的垃圾回收把CPU的資源耗盡了。
（4）現(xiàn)在，我們已經(jīng)定位到是GC的問題了。那么，我們就來看看GC的回收情況，我們可以通過jstat來觀察。jstat是JDK內(nèi)置的JVM檢測統(tǒng)計工具，位于JDK根目錄的bin文件夾下面，可以對堆內(nèi)存的使用情況進行實時統(tǒng)計。我使用了命令 jstat -gcutil 6902 2000 10 （6902是Java進程的PID）來觀察GC的運行信息，如下圖六所示：
?
（圖六）GC運行信息
通過圖六可以知道，E（Eden區(qū)）跟O（Old區(qū)）的內(nèi)存已經(jīng)被耗盡了，FGC（Full GC）的次數(shù)高達6989次，FGCT（Full GC Time）的時間高達36453秒，即平均每次FGC的時間為：36453/6989 ≈ 5.21秒。也就是說，Java進程都把時間花在GC上了，所以就沒有時間來處理其他事情。
（5）GC出現(xiàn)圖六的這種情況，基本可以確認是在程序中存在內(nèi)存泄露的問題。那么，如何確定是哪些代碼導致的這個問題呢？這時候，我們就可以使用jmap查看Java的內(nèi)存占用信息。jmap是JDK內(nèi)置的內(nèi)存映射工具，位于JDK根目錄的bin文件夾下面，可用于獲取java進程的內(nèi)存映射信息。通過命令 jmap -histo 6902 （6902是Java進程的PID）打印出了Java的內(nèi)存占用信息，如下圖七所示：
?
（圖七）Java內(nèi)存占用信息
由圖七可以得到，占用內(nèi)存資源的TOP10類（[C 是指char[]，String類內(nèi)部使用char[]來保存數(shù)據(jù)）的名稱、實例數(shù)以及占用內(nèi)存大小（單位：byte），于是問題排查就變得非常簡單了。最后，通過review代碼確定了問題所在：
解決以上兩個問題后，Heap內(nèi)存的占用維持在2.5G左右，已經(jīng)沒有持續(xù)增長的跡象了，業(yè)務已正常運行。
以上就是我排查問題的整個過程，以及在這個過程中用到的一些Java性能監(jiān)測工具。除了本文提及的jvisualvm、jstack、jstat、jmap這些工具，在JDK根目錄的bin文件夾下面還有其他許多非常有用的工具，例如：使用 jinfo 查看Java進程相關信息，感興趣的童鞋可以去研究下。
如果想學習Java工程化、高性能及分布式、深入淺出。微服務、Spring，MyBatis，Netty源碼分析的朋友可以加我的Java高級交流：854630135，群里有阿里大牛直播講解技術(shù)，以及Java大型互聯(lián)網(wǎng)技術(shù)的視頻免費分享給大家。
轉(zhuǎn)載于:https://my.oschina.net/u/3990817/blog/3013624
總結(jié)
以上是生活随笔為你收集整理的做JAVA开发的同学一定遇到过的爆表问题，看这里解决的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： K8S使用dashboard管理集群
- 下一篇： 烟雨江湖蛇胆在哪