一次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”,獲得本文最新內容。

                                                           

本站聲明:網站內容來源於博客園,如有侵權,請聯繫我們,我們將及時處理

網頁設計公司推薦不同的風格,搶佔消費者視覺第一線

透過選單樣式的調整、圖片的縮放比例、文字的放大及段落的排版對應來給使用者最佳的瀏覽體驗,所以不用擔心有手機版網站兩個後台的問題,而視覺效果也是透過我們前端設計師優秀的空間比例設計,不會因為畫面變大變小而影響到整體視覺的美感。

您可能也會喜歡…