今天測試團隊反饋說，服務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”，獲得本文最新內容。

                                                          　

相關推薦