一次FGC致使CPU飆高的排查過程

    今天測試團隊反饋說，服務A的響應很慢，我在想，測試環境也會慢？因而我本身用postman請求了一下接口，真的很慢，居然要2s左右，正常就50ms左右的。

    因而去測試服務器看了一下，發現服務器負載很高，而且該服務A佔了很高的cpu。先用top命令，看了load average，發現都到了1.5左右（雙核cpu）了，而且有一個java進程（20798）佔用cpu一直很高，以下圖：

    因而，用命令jps -l看了一下java的20798，恰好就是服務A。

    究竟服務A在跑什麼，畢竟是測試環境。因而使用top -Hp 20798看一下是哪一個線程在跑，以下圖：

    

    發現線程20840佔用cpu很是高，其餘幾乎都是0。經過如下命令輸出該線程id（20840）的16進制：

printf "%x\n" 20840

　　

輸出以下：

    線程id（20840）的16進制是5186。

    而後使用如下命令打印出該線程的堆棧信息：

jstack -l 20798 | grep -A 20 5168

　　

    輸入以下：

    發現佔用cpu的進程是jvm的GC線程，因而猜想是否是因爲一直在進行FGC致使cpu飆高，因而使用如下命令看下FGC的頻率和耗時：

jstat -gc 20798 1000

　　

輸出以下：

    發現，果真是不斷地在進行着FGC，而且每次FGC的時間一直在升高。是什麼致使一直都在FGC呢？是有大對象一直在建立，回收不了？因而使用如下命令看下heap中的對象狀況：

jmap -histo:live 20798 | head -20

　　

輸出以下：

    發現一個業務類對象居然有150w+個，而且佔用了264M的堆大小，什麼狀況，而且這150w+個對象仍是存活的（注意jmap使用的時候，已經帶上了:live選項，只輸出存活的對象），嚇我一跳。因而趕忙使用如下命令打出線程堆棧來看一下：

jstack -l 20798 > jstack_tmp.txt

　　

輸出以下：

而後使用以下命令在輸出的線程堆棧中根據對象類查找一下：

grep -C 30 'omments' jstack_tmp.txt

　　

輸出以下：

    猜想是因爲一下次從db load出了太多的CommentsEntity。

    因而使用如下命令dump出heapdump出來重複確認一下：

jmap -dump:live,format=b,file=news_busy_live.hprof 20798

　　

    把heapdump文件news_busy_live.hprof下載到windows本地，使用mat工具進行分析，第一次打開發現打不開，畢竟news_busy_live.hprof有3G那麼大，mat直接報OOM打不開，發現mat的配置文件MemoryAnalyzer.ini裏面的配置-Xmx1024m，heap size才1G，過小了，因而改爲-Xmx4096m，保存，從新打開mat，再打開news_busy_live.hprof文件便可，以下圖：

    發現mat已經幫咱們分析出了內存泄漏的能夠對象，233w+個對象（前面經過jmap命令輸出的150W+個，是後面爲了寫文章而專門重現的操做，這裏的233w+個是當時真的出問題的時候dump出來的heap dump文件），太恐怖了。

    經過如下操做，查看

點擊exclude all ....，由於弱引用，軟引用，虛引用等均可以被GC回收的，因此exclude，輸出以下：

    發現一共有6個線程引用了那233w+個對象，因而去前面dump出來的線程堆棧跟蹤如下這幾個線程的狀況，發現堆棧裏面恰好這幾個線程也是在處理comments相關的邏輯，這個是恰好碰巧，通常線程id都對不上的，畢竟線程處理完以後就釋放了的。因此咱們仍是看回前面線程堆棧的信息，這裏貼出根據關鍵字"omment"搜索出來的線程堆棧的信息，以下：

"XNIO-5 task-77" #248 prio=5 os_prio=0 tid=0x00007fc4511be800 nid=0x8f7 runnable [0x00007fc3e5af2000]   java.lang.Thread.State: RUNNABLE       ...        at cn.xxxxxx.news.commons.redis.RedisUtil.setZSet(RedisUtil.java:1080)        at cn.xxxxxx.news.service.impl.CommentsServiceV2Impl.setCommentIntoRedis(CommentsServiceV2Impl.java:1605)        at cn.xxxxxx.news.service.impl.CommentsServiceV2Impl.loadCommentsFromDB(CommentsServiceV2Impl.java:386)        ...        at cn.xxxxxx.xxxs.controller.vxxx.xxxxController.getxxxxxx(NewsContentController.java:404)        at cn.xxxxxx.xxx.controller.vxxx.xxxxxController$$FastClassBySpringCGLIB$$e7968481.invoke(<generated>)        ...        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)        at java.lang.Thread.run(Thread.java:745)​   Locked ownable synchronizers:        - <0x00000000f671ecd0> (a java.util.concurrent.ThreadPoolExecutor$Worker)​

　　

    從上面的堆棧信息，結合前面的猜想（猜想是一次性從db load出太多的CommentsEntity），猜想應該是函數loadCommentsFromDB一次性從db load出太多CommentsEntity了。因而看了一下業務代碼，發現load出來的commentsEntity會放到redis的某一個zset，因而使用redis destopmanger看一下這個zset的數據，發現這個zset有22w的數據，從中找出幾條，發現對應的newsPk都是同一個，根據newsPk在db中找一下該newsPk的comments總記錄，發現該newsPk的comments記錄數是38w+條，那就是這個問題了，一次性從db中load了38w+的數據到內存。

    一次性load那麼多數據到內存，這確定是一個慢查詢，不論是db仍是網絡io，都確定很慢。而後發現業務代碼還會有一個for循環，把這個CommentsEntityList遍歷一遍，一條一條放到redis，這也是一個很是慢的過程。

    而後我去看了服務A的access log，發如今短期內，請求了該newsPk屢次數據，因此就致使了jvm的heap空間不夠，而後出現不斷FGC的現象，而且該newsPk的請求，因爲超時，都在網關超時返回了。

    爲了驗證這個問題，我把相關的redis緩存刪除，而後調用該newsPk的接口獲取數據，發現很慢，而且cpu馬上飈上去了，而後調多幾回，而且不斷地進行FGC，至此已經復現了該問題，和猜想的同樣。等數據load到redis以後，再訪問該接口，就很正常沒問題。

    上面發現問題的代碼，找時間作一下優化才行，先重啓服務A，讓服務可用先。

 

　　　　　　　　　　　　　　　　　　　 歡迎關注微信公衆號「ismallboy」，請掃碼並關注如下公衆號，並在公衆號下面回覆「FGC」，得到本文最新內容。