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，也就是說會有兩個性能問題
- 新生代太小，頻繁Minor GC
- 大部分對象很快會進入老年代
整個GC日志中出現大量的promotion failed 和concurrent mode failure。
4. 后記
模塊負責人已經修改啟動參數，顯式指定新生代大小，並進行調優效果觀察。目前已無Full GC的情況出現。
5. 總結
回顧：
現象是鎖等待超時，而原因卻與數據庫本身表大小、流水號事務是否生效全然無關。而是由於Full GC導致。
從Full GC日志來看，出現promotion failure，原因無非兩點：新生代太小survivor放不下，老年代碎片太多也放不下，觸發Full GC。
再推一步，發現新生代大小實在太誇張，疑似是因為沒有設置。
再往后面推，發現其實是JVM Ergonomics對於使用CMS收集器的情況下自動進行參數設定所致。
啟示：
- 要關注服務的內存使用與GC情況，根據情況進行調優
- 要關注JVM啟動參數，可以加上-XX:+PrintFlagsFinal觀察各種參數，看看是否有參數沖突、JVM作了什么預期外的調整等