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

問題發現場景

某天忽然收到線上應用的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）以下圖，也沒發現什麼特殊的東西

   

   。
4. 而後看下ygc近期耗時的走勢圖，下圖縱座標每10分鐘gc總耗時(單位:s)，橫座標日期，能夠看到在2月22號應用重啓後gc總耗時降下來了，而後隨着時間推移，gc變得愈來愈慢，而且這個變慢的過程很是緩慢，正常狀況下重啓一次到應用觸發gc告警，須要1至2周才能出現。

   

   。

進一步排查

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腳本。

   

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對象中的，以下圖

   

6. 而後回到VisualVM的Classes欄目，直接搜索Source$RawData，能夠看到有241個實例，以下圖

   

   ，這241個，而後找了出現頻率比較高的幾個js腳本，而後看了對應腳本的調用方式，發現其中一個腳本每次執行都是經過ScriptEngine.eval這種方式來執行，就形成了``JNIHandleBlock```，不斷增加的問題，最終致使ygc時，處理JNI Weak Reference的時間愈來愈長。
7. 如何解決：修改了這個腳本的調用方式。不用每次執行eval方法，換成Bindings的方式調用。
8. 修改後，通過一週的觀察。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看了下，發現了奇怪的地方（以下圖）

       

       年輕代總容量才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的一系列流程，有所瞭解和掌握，纔可以快速的定位和排查問題。

參考文章

• zhuanlan.51cto.com/art/201706/…

版權聲明
做者：wycm
出處：juejin.im/post/5c8a5a…
您的支持是對博主最大的鼓勵，感謝您的認真閱讀。 本文版權歸做者全部，歡迎轉載，但未經做者贊成必須保留此段聲明，且在文章頁面明顯位置給出原文鏈接，不然保留追究法律責任的權利。