GC Ergonomics間接引起的鎖等待超時問題排查分析

1. 問題背景

上週線上某模塊出現鎖等待超時，以下圖所示：

我雖然不是該模塊負責人，但出於好奇，也一塊兒幫忙排查定位問題。

這裏的業務背景就是在執行到某個地方時，須要去表中插入一批數據，這批數據須要根據數據類型分配流水號。這與個人select for update引起死鎖分析提到的流水號分配差很少：經過數據庫悲觀鎖實現多實例部署的流水號生成與分配。

2. 問題排查

那麼須要排查的問題很簡單，爲何獲取流水號的時候會發生鎖等待超時？
從上面截圖中的異常棧中，咱們也能夠看出：首先進入了帶有@Transactional註解的方法，進入業務事務。而在須要分配流水號的時候經過IdManager分配流水號。

這裏的getNextIdFromDb是由同一個類的getIdsBySize方法調用的，所以使用了編程式事務的方式來開啓一個新事務。
TransactionHelper是對Spring的TransactionTemplate的封裝，callInNewTransaction方法就是使用一個傳播行爲爲PROPAGATION_REQUIRES_NEW的TransactionTemplate。

很顯然，獲取流水號走的是一個很小的事務，與業務事務並無混在一塊兒。理論上來講不該該出現有線程鎖等待超時。

那麼線上鎖等待超時的時間是多少呢?

詢問dba，從給出結果來看是默認的50秒。

此時，陷入僵局。這看起來很不科學，那麼小的事務怎麼會有線程50秒拿不到鎖？線上的併發度不可能致使這樣的結果。

2.1 從新搜索

聯繫該模塊負責的同事，要了服務器host和部署路徑，登上去仔細查看日誌。

有一個重要的發現是，在上面的異常log前一些時候，有大量線程出現事務異常。其中包括文章一開始截圖中的pool-32-thread-1，但其中有一個線程pool-8-thread-1在2018-04-12 13:21:23,066打出了事務成功的日誌。

這裏就產生了一個猜測，這裏全部的線程都是在爭取流水號表上的鎖，而此刻大量的事務在大約77秒後失敗，只有一個事務成功了。這並不科學，由於線上數據庫的鎖等待超時時間爲50秒。

順藤摸瓜，往上面搜索pool-8-thread-1的日誌。

能夠看到在2018-04-12 13:20:05,146的時候pool-8-thread-1已經獲取到了id_record表的鎖。

而在2018-04-12 13:21:23,049的時候，pool-8-thread-1纔剛剛完成對id_record的更新。

MapperExecutionTimeLogger是項目中的mybatis攔截器，用於在日誌中打印sql執行耗時。

這裏發現兩個問題

• pool-8-thread-1更新流水號，很簡單的一個sql用了將近78秒。
• 大量其它線程一樣耗費78秒才完成sql語句的執行。

2.2 水落石出

這78秒到底發生了什麼？
繼續仔細翻閱，發現有兩條相鄰的日誌時間差了78秒左右，前一條時間戳爲2018-04-12 13:20:05,147，後一條爲2018-04-12 13:21:23,048。這78秒內沒有任何日誌。
此時，已基本能夠猜到多是Full GC，stop the world了。

經過公司的監控平臺，觀測該服務的堆內存使用狀況以下：

在13：20分先後確實發生了一次很誇張的Full GC：從50g清理到20g。更可怕的是從圖中能夠看出，Full GC的頻率至關高，大約每10多分鐘就要來一次。

而後登錄服務部署的服務器，翻閱GC日誌，肯定當時存在一次Full GC。log以下所示

2018-04-12T13:20:05.151+0800: 870750.291: [GC (Allocation Failure) 2018-04-12T13:20:05.151+0800: 870750.291: [ParNew (promotion failed): 1341118K->1337043K(1380160K), 0.6976067 secs]2018-04-12T13:20:05.849+0800: 870750.989: [CMS: 49443246K->19463735K(61381056K), 77.1977735 secs] 50784220K->19463735K(62761216K), [Metaspace: 78507K->78507K(81920K)], 77.8959574 secs] [Times: user=85.78 sys=0.13, real=77.89 secs]

耗時77.89秒，與前面的日誌排查中種種跡象吻合。

遂緊急聯繫同事，告知鎖等待超時緣由與事務生效、表的大小都無關，乃Full GC所致，趕忙分析下GC日誌調優。

3. 詳細分析

導出線上的JVM參數來看：

-XX:MaxHeapSize=64424509440 最大堆大小60G 
-XX:MaxNewSize=1570308096 最大新生代1.5G 
-XX:MaxTenuringThreshold=6 進入老年代的前Minor GC次數 
-XX:NewSize=528482304 新生代初始值大小

3.1 這新生代也過小了吧

新生代：
總大小爲1380160K（eden+一個survivor），其中eden區的大小爲1226816K，一個survivor區的大小爲153344K。
這裏eden+兩個survivor就構成了參數中的MaxNewSize=1570308096也就是1533504K。

老年代：
大小爲61381056K。

這裏已經能夠看出young和old的比例很是誇張。

使用GCViewer工具能夠分析GC日誌（從2018-04-09 14:19:23到2018-04-13 10:33:33大約4天不到）。

能夠看到有很是多的Full GC。

再來看一下致使鎖等待超時的那次Full GC。

圖中黑色的柱形表明的就是Full GC，橫軸表示持續時長，高度中能夠對應查看差很少在75-80秒之間。
藍色線表明了使用的堆大小。而上下兩塊染色區域分別表示新生代和老年代的大小，能夠看到比例很是誇張

另外，推薦一個分析GC的網站，很是好用。

3.2 誰動了參數？

查看build.gradle，配置的參數以下（和jcmd pid VM.flags相同）：

applicationDefaultJvmArgs = ['-Xmx60G', '-XX:MaxPermSize=512M', '-XX:+UseConcMarkSweepGC',
        '-XX:+PrintGCDetails', '-XX:+PrintGCDateStamps', '-Xloggc:log/gc.log', '-XX:+UseGCLogFileRotation',
        '-XX:NumberOfGCLogFiles=10', '-XX:GCLogFileSize=20M']

而查看gc日誌，能夠看到

CommandLine flags: -XX:CICompilerCount=12 -XX:GCLogFileSize=20971520 -XX:InitialHeapSize=1585446912 -XX:MaxHeapSize=64424509440 -XX:MaxNewSize=1570308096 -XX:MaxTenuringThreshold=6 -XX:MinHeapDeltaBytes=1
96608 -XX:NewSize=528482304 -XX:NumberOfGCLogFiles=10 -XX:OldPLABSize=16 -XX:OldSize=1056964608 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseConcMarkSweepGC -XX:+
UseFastUnorderedTimeStamps -XX:+UseGCLogFileRotation -XX:+UseParNewGC

• -XX:MaxHeapSize
  64424509440=60G，沒啥問題

• -XX:MaxNewSize
  1570308096=1.46G，什麼鬼

在調研以後發現，這個實際上是JVM Ergonomics自動調的參數。Ergonomics是一種自適應調節策略，能夠根據Java應用運行的系統自動的選擇GC收集器的類型和堆大小以及工做模式（client or server），還會自動調節垃圾收集的參數。

因爲咱們使用了CMS收集器，因此參考hotspot中src/share/vm/runtime/arguments.cpp中void Arguments::set_cms_and_parnew_gc_flags方法：

能夠看到MaxNewSize的計算大體分爲兩步：

• preferred_max_new_size_unaligned 等於 【堆內存/3（NewRatio默認是2）】與【young_gen_per_worker（通常是67108864也就是64M）*13/10與4(HeapWordSize)做一次下對齊】
  
• 再將preferred_max_new_size_unaligned與 os::vm_page_size()（虛擬內存的分頁大小，默認4K）做一次上對齊獲得preferred_max_new_size

其中下對齊和上對齊的函數定義以下:

#define align_size_up_(size, alignment) (((size) + ((alignment) - 1)) & ~((alignment) - 1))
#define align_size_down_(size, alignment) ((size) & ~((alignment) - 1))

經過jinfo -flag ParallelGCThreads [pid]和jinfo -flag CMSYoungGenPerWorker [pid]確認線上服務-XX:ParallelGCThreads=18以及-XX:CMSYoungGenPerWorker=67108864

那麼下面的計算就很顯然了：

preferred_max_new_size_unaligned = 1570347416
preferred_max_new_size = 1570349056
MaxNewSize = preferred_max_new_size = 1570349056

接下去在堆初始化的時候，還會再去作一次參數調整。

此時MaxNewSize與65536做一次下對齊，就算出最終MaxNewSize爲1570308096，這與前面貼的參數一致。

說到底，實際上是沒有顯示設置新生代大小，踩了JVM Ergonomics在使用CMS收集器時自動調參的坑，調出了一個過小的（相比整個60G的堆）新生代容量。而且MaxTenuringThreshold=6，也就是說會有兩個性能問題

1. 新生代過小，頻繁Minor GC
2. 大部分對象很快會進入老年代

整個GC日誌中出現大量的promotion failed 和concurrent mode failure。

4. 後記

模塊負責人已經修改啓動參數，顯式指定新生代大小，並進行調優效果觀察。目前已無Full GC的狀況出現。

5. 總結

回顧：
現象是鎖等待超時，而緣由卻與數據庫自己表大小、流水號事務是否生效全然無關。而是因爲Full GC致使。
從Full GC日誌來看，出現promotion failure，緣由無非兩點：新生代過小survivor放不下，老年代碎片太多也放不下，觸發Full GC。
再推一步，發現新生代大小實在太誇張，疑似是由於沒有設置。
再日後面推，發現實際上是JVM Ergonomics對於使用CMS收集器的狀況下自動進行參數設定所致。

啓示：

1. 要關注服務的內存使用與GC狀況，根據狀況進行調優
2. 要關注JVM啓動參數，能夠加上-XX:+PrintFlagsFinal觀察各類參數，看看是否有參數衝突、JVM做了什麼預期外的調整等

6. 參考

Java GC Guide
Java的Ergonomics
瞭解 CMS 垃圾回收日誌