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

開發十年，就只剩下這套架構體系了！ >>>

問題發現場景

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

初步排除過程

按照gc問題常規排查流程，還是先保留現場，jmap -dump:format=b,file=temp.dump pid。
檢視下gc日誌，發現出問題的時候的單次ygc耗時幾乎有200ms以上了。正常來說單次ygc在100ms以下，基本可以認為應用是比較健康的。所以這時候已經可以確定告警的原因就是ygc比較慢。

jvisualvm開啟剛剛dump的檔案看下能不能發現什麼東西，看了下，也看不出什麼特殊的，因為本身dump的時候會觸發一次full gc，dump下來的堆裡面的內容只有1G左右（jvm引數堆記憶體配置的是4G）如下圖，也沒發現什麼特殊的東西。
然後看下ygc近期耗時的走勢圖，下圖縱座標每10分鐘gc總耗時(單位:s)，橫座標日期，可以看到在2月22號應用重啟後gc總耗時降下來了，然後隨著時間推移，gc變得越來越慢，並且這個變慢的過程非常緩慢，正常情況下重啟一次到應用觸發gc告警，需要1至2周才能出現。。

進一步排查

網上搜了下有沒有相關案例，相關資料也非常少，然後看到了http://zhuanlan.51cto.com/art/201706/543485.htm

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

總結

小插曲：其實這個問題在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月底，算是徹底解決了這個問題。
個人覺得ygc緩慢相關的問題不太好排查，相比full gc問題或者OOM的相關問題，本身ygc帶給我們的東西不夠多，並且dump下來的資訊，也不是保證有用的，可能也是問題被掩蓋後的一些無關資訊。
在排查gc相關問題，個人覺得需要對整個jvm堆記憶體的劃分，以及gc的一系列流程，有所瞭解和掌握，才能夠快速的定位和排查問題。

參考文章

http://zhuanlan.51cto.com/art/201706/543485.htm

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

相關推薦

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

開發十年，就只剩下這套架構體系了！ >>>

MySQL-記一次備份失敗的排查過程

山竹來臨，窩在家裡整理個人文件。本篇文章主要講解排查問題的思路，涉及linux 刪除檔案的原理、例項誤刪資料恢復、MySQL例項初始化引數優先級別等，雖然涉及知識點比較淺，但是個人覺得挺有意思的，所以翻出筆記釋出出來。 1 備份出錯咯

一次 Java 記憶體洩漏排查過程，漲姿勢

人人都會犯錯，但一些錯誤是如此的荒謬，我想不通怎麼會有人犯這種錯誤。更沒想到的是，這種事竟發生在了我們身上。當然，這種東西只有事後才能發現真相。接下來，我將講述一系列最近在我們一個應用上犯過的這種錯誤。最有意思的是，一開始的跡象揭示的問題，與實際發生的問題完全不同。在一個淒涼的午夜午夜剛過，我就被一條

記一次線上問題的排查過程

問題描述前不久運維在例行釋出線上CS系統的時候，發現在服務啟動的過程中，後臺一直在報如下錯誤，同時導致使用者頁面訪問異常 2017-10-10 18:28:51,077 [ERROR] org.springframework.amqp.rabbit.l

一次CMS GC問題排查過程（理解原理+讀懂GC日誌）

這個是之前處理過的一個線上問題，處理過程斷斷續續，經歷了兩週多的時間，中間各種嘗試，總結如下。這篇文章分三部分： 1、問題的場景和處理過程；2、GC的一些理論東西；3、看懂GC的日誌先說一下問題吧問題場景：線上機器在半夜會推送一個700M左右的資料，這個時候有個資料置換

一次Mysql死鎖排查過程的全紀錄

前言之前接觸到的資料庫死鎖，都是批量更新時加鎖順序不一致而導致的死鎖，但是上週卻遇到了一個很難理解的死鎖。藉著這個機會又重新學習了一下mysql的死鎖知識以及常見的死鎖場景。在多方調研以及和同事們的討論下終於發現了這個死鎖問題的成因，收穫頗多。雖然是後端程式設計師，我們不需要

一次JobTracker擁堵問題排查過程

Hadoop版本 1.0.3 問題描述: 隨著每日MR作業數目漸增，使用者反映提交作業時經常阻塞，也就是JobTracker發生了擁堵。這種情況開始頻繁出現，我們調大JobTracker端的RPC Handler執行緒個數，並定時對JobTracker的棧資訊進行

記錄一次Mysql死鎖排查過程

知識 body ext 兩個 next ron 討論不一致 test 背景以前接觸到的數據庫死鎖，都是批量更新時加鎖順序不一致而導致的死鎖，但是上周卻遇到了一個很難理解的死鎖。借著這個機會又重新學習了一下mysql的死鎖知識以及常見的死鎖場景。在多方調研以及和同事們的

Kafka 非同步訊息也會阻塞？記一次 Dubbo 頻繁超時排查過程

線上某服務 A 呼叫服務 B 介面完成一次交易，一次晚上的生產變更之後，系統監控發現服務 B 介面頻繁超時，後續甚至返回執行緒池耗盡錯誤 Thread pool is EXHAUSTED。因為服務 B 依賴外部介面，剛開始誤以為外部介面延時導致，所以臨時增加服務 B dubbo 執行緒池執行緒數量。配置變

解Bug之路-記一次儲存故障的排查過程

# 解Bug之路-記一次儲存故障的排查過程高可用真是一絲細節都不得馬虎。平時跑的好好的系統，在相應硬體出現故障時就會引發出潛在的Bug。偏偏這些故障在應用層的表現稀奇古怪，很難讓人聯想到是硬體出了問題，特別是偶發性出現的問題更難排查。今天，筆者就給大家帶來一個儲存偶發性故障的排查過程。 ## Bug現場我

原創記錄一次線上Mysql慢查詢問題排查過程

背景前段時間收到運維反饋，線上Mysql資料庫凌晨時候出現慢查詢的報警，並把原始sql發了過來： --去除了業務含義的sql update test_user set a=1 where id=1; 表資料量200W左右，不是很大，而且是根據主鍵更新。問題排查排查Mysql資料庫我看到sql後第一

記錄一次抽獎超發排查問題過程

緩存控制緩存騰訊雲領導通過 redis 不知道服務更新接到運營方提出的bug，說是移動端優惠券超發，通過拉取線上數據，確實存在超發現象，而且恰好是設定的兩倍。通過在測試和仿真環境新建一個活動頁面添加優惠券進行測試，又不會出現超發現象，想到

記一次改造react腳手架的過程

lease nts rule 加載過程 npm req ems ner comm 公司突然組織需要重新搭建一個基於node的論壇系統，前端采用react，上網找了一些腳手架，或多或少不能滿足自己的需求，最終在基於YeoMan的react腳手架generator-react-

一次網站性能排查實錄

linux性能調整排查接到一個求助電話，說是有個阿裏雲上的服務器，有性能瓶頸，但又沒有什麽具體的數據，只是說偶爾客戶端有少數連接不上，或者連接會突然中斷。我的天，最怕這種狀況了，還得自己去找問題表現是什麽，再去找什麽原因所致。----懶人可直接點此處，不必辛苦看文字因為是線上的環境，得分兩步進行。

一次差異備份拿shell過程

shadow 寫入一次科普 table 正文 blog 條件目前 0x00 前言掃描器掃到了某個網站存在目錄瀏覽，於是便有了本文。。。知識點科普： 1. 目錄瀏覽目錄瀏覽在我個人看來是危害較大的一個漏洞，該漏洞是指“在沒有默認文檔的目錄下，列出該目錄下所有文

一次完整的 HTTP 請求過程

net first 直接 orm gin 端口 add static 1.2 一次完整的HTTP請求過程從TCP三次握手建立連接成功後開始，客戶端按照指定的格式開始向服務端發送HTTP請求，服務端接收請求後，解析HTTP請求，處理完業務邏輯，最後返回一個HTTP的響應給客戶

記錄一次郵件容災恢復過程

數據庫修改 Eseutil Exchange容災恢復背景介紹客戶目前使用的是Exchange Server 2013,兩前兩後，數據盤是存儲掛載過來的，郵件備份使用的是NBU，由於機房漏水，導致存儲服務器宕機。導致絕大部分數據丟失。 Exchange恢復過程使用新存儲重新劃分磁盤，並使用N

一次“驚險”的系統修復過程

str 問題修復過程 tmg miss 菜單 r文件解決辦法 mage 1，問題的出現某個早上開機，突然發現無法正常開機。顯示界面出現“OEM7GRUB 0.4.4 2009-11-18,Memory：”等提示，以及“grub>”命令輸入提示符。趕緊

一次完整的http請求過程

網關 persist trac 頁面都沒有 wan 服務器 modified 虛擬機當我們在瀏覽器的地址欄輸入 www.linux178.com ，然後回車，回車這一瞬間到看到頁面到底發生了什麽呢？以下過程僅是個人理解：域名解析 --> 發

【BUG記錄】記一次遊戲越來越卡的BUG

U3D的MOBA專案，測試過程中，10分鐘以後，遊戲幀率開始緩慢下降，約3-5分鐘後，由60幀下降到小於10幀，編輯器模式。開啟profiler，看到CPU佔用非常高，每幀都有24K的GC, 時間佔用曲線上看是script大量佔用CPU時間。第一印象，應該是洩漏造成的。定位辦法，profil