一次ygc越來越慢的問題排查過程

臥顏沉默發表於2019-03-14
GC

問題發現場景

某天突然收到線上應用的gc時間過長的告警，剛開始只有一臺機器偶爾報一下，後續其他機器也紛紛告警，具體告警的閾值是應用10分鐘內ygc的總時長達到了6.6s。

初步排除過程

  1. 按照gc問題常規排查流程，還是先保留現場，jmap -dump:format=b,file=temp.dump pid。
  2. 檢視下gc日誌，發現出問題的時候的單次ygc耗時幾乎有200ms以上了。正常來說單次ygc在100ms以下，基本可以認為應用是比較健康的。所以這時候已經可以確定告警的原因就是ygc比較慢。
  3. jvisualvm開啟剛剛dump的檔案看下能不能發現什麼東西，看了下，也看不出什麼特殊的，因為本身dump的時候會觸發一次full gc，dump下來的堆裡面的內容只有1G左右（jvm引數堆記憶體配置的是4G）如下圖，也沒發現什麼特殊的東西
    一次ygc越來越慢的問題排查過程
    。
  4. 然後看下ygc近期耗時的走勢圖，下圖縱座標每10分鐘gc總耗時(單位:s)，橫座標日期，可以看到在2月22號應用重啟後gc總耗時降下來了，然後隨著時間推移，gc變得越來越慢，並且這個變慢的過程非常緩慢，正常情況下重啟一次到應用觸發gc告警，需要1至2周才能出現。
    一次ygc越來越慢的問題排查過程
    。

進一步排查

  1. 網上搜了下有沒有相關案例，相關資料也非常少，然後看到 了http://zhuanlan.51cto.com/art/201706/543485.htm 笨神的一篇文章，這篇文章簡單總結起來就是使用jdk中的1.8的nashorn js引擎使用不當觸發了底層JVM的一個缺陷。然後回到我這邊來，發現和我這邊的場景也挺類似的，應用也大量使用了nashorn 引擎來執行javascript指令碼，所以我初步猜測也是nashorn引擎使用不當導致。
  2. 為了驗證我以上的想法，找運維加了-XX:+PrintReferenceGC引數，經過一段時間觀察，應用重啟後，觀察了一段時間，發現gc日誌中JNI Weak Reference處理時長變得越來越長。而且佔用整個ygc時長的大部分。
  3. 再回到剛剛dump的那張圖裡面，能看到例項數排在前面的也有nashorn引擎相關的內容，如下圖，現在幾乎可以斷定問題出在的執行某個javascript指令碼。
    一次ygc越來越慢的問題排查過程
  4. 現在確認了出問題的大致方向。但是該應用執行的javascript指令碼也有10多個，所以還沒發直接定位到是哪個指令碼導致的。所以接下來就是定位具體的指令碼了。初步想法是直接根據上圖的中的jdk.nashorn.internal.ir.IdenNode通過引用鏈找到可疑的js指令碼對應的String，嘗試了很多次發現都失敗了。主要本身對jdk.nashorn包下類不是很熟悉，再加上引用鏈都比較長，所以找了很久都沒有找到這個類和指令碼的應用關係。
  5. 於是換了一種思路，記憶體中，指令碼肯定會以String物件存在，String底層採用char[]來儲存字元。所以直接找char[]例項中內容為js指令碼的，但是這裡又遇到一個問題，看上面的dump檔案圖，會發現char[]例項數當前記憶體有100w+，這裡就抓住了部分js指令碼長度比較長的一個特點。直接根據size正序排列，長度前10的字串，就直接就找到了一個指令碼，順著引用鏈會輕易發現，js指令碼的內容都是儲存在Source$RawData物件中的，如下圖
    一次ygc越來越慢的問題排查過程
  6. 然後回到VisualVM的Classes欄目，直接搜尋Source$RawData，可以看到有241個例項，如下圖
    一次ygc越來越慢的問題排查過程
    ，這241個，然後找了出現頻率比較高的幾個js指令碼，然後看了對應指令碼的呼叫方式，發現其中一個指令碼每次執行都是通過ScriptEngine.eval這種方式來執行，就造成了``JNIHandleBlock```，不斷增長的問題，最終導致ygc時，處理JNI Weak Reference的時間越來越長。
  7. 如何解決：修改了這個指令碼的呼叫方式。不用每次執行eval方法，換成Bindings的方式呼叫。
  8. 修改後，經過一週的觀察。ygc時間以及區域穩定了，如下圖
    一次ygc越來越慢的問題排查過程

總結

  1. 小插曲：其實這個問題在18年10月份左右都出現了，早期也考慮徹底解決過，也探索了不少方法。比如下：
    • 最開始的時候懷疑是G1 收集器的問題，直接把G1收集器改回CMS收集器，其中調整該引數的過程中也發生了一個小問題，具體如下。
      • 從G1改到CMS改回來的引數設定堆空間大小相關的引數變成了-Xms4000m -Xmx4000m -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=70 -XX:MaxDirectMemorySize=512m -XX:+UseCMSInitiatingOccupancyOnly -XX:SurvivorRatio=8 -XX:+ExplicitGCInvokesConcurrent -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m -XX:-OmitStackTraceInFastThrow -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/var/www/logs/gc-%t.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/var/www/logs -Djava.io.tmpdir=/var/www/tmp -Dio.netty.availableProcessors=4 -XX:ParallelGCThreads=4 -Dpinpoint.applicationName=crawler-worker.product-bank這樣，其中-Xms4000m是初始化堆大小，-Xmx4000m是最大堆大小，然後重啟應用，重啟後，就收到ygc頻繁的告警，然後用jstat -gc pid 3000看了下，發現了奇怪的地方（如下圖）
        一次ygc越來越慢的問題排查過程
        年輕代總容量才300多m(S0C+S1C+EC)，而年老大總容量(OC)有3700多m，這種情況就直接導致了，直接分配物件空間的eden區域很容易就佔滿了，而直接觸發ygc，而導致這個問題的原因呢，是忘記配置-Xmn1024m引數導致，這個引數就是制定年輕代的大小，這裡的大小配置成整個堆的1/4至1/2都是合理的，加上這個引數後，剛啟動應用就ygc時間過長的問題就得到了解決。
    • 後面發現也沒什麼效果，又懷疑是堆空間年輕代的空間設定小了。之前整個堆4000M，年輕代設定的1000M。後面把年輕代的空間調整至1200M，發現也沒什麼效果。在這個過程中，發現也沒什麼效果，再加上這個過程非常緩慢，重啟一次應用也能撐個1至2周，所以也拖到了現在也就是19年2月底，算是徹底解決了這個問題。
  2. 個人覺得ygc緩慢相關的問題不太好排查，相比full gc問題或者OOM的相關問題，本身ygc帶給我們的東西不夠多，並且dump下來的資訊，也不是保證有用的，可能也是問題被掩蓋後的一些無關資訊。
  3. 在排查gc相關問題，個人覺得需要對整個jvm堆記憶體的劃分，以及gc的一系列流程，有所瞭解和掌握，才能夠快速的定位和排查問題。

參考文章

版權宣告
作者：wycm
出處：juejin.im/post/5c8a5a…
您的支援是對博主最大的鼓勵，感謝您的認真閱讀。 本文版權歸作者所有，歡迎轉載，但未經作者同意必須保留此段宣告，且在文章頁面明顯位置給出原文連線，否則保留追究法律責任的權利。

一個程式設計師日常分享，包括但不限於爬蟲、Java後端技術，歡迎關注

相關文章