jdk下載快速方法「jdk下載慢怎麼辦」

導語：

本文作者為解決一個JDK性能問題，從堆棧分析，到GC分析，再到Safepoint原因分析，最終定位到問題根因與所用的JDK版本有關。並整理成文，與所有Java相關開發的同學分享此次經驗。

01 問題來了

筆者近期在工作中遇到這樣一個問題：某客戶新上線了一個Elasticsearch應用，但運行一段時間後就變的特別慢，甚至查詢超時。重啟後服務恢復，但每隔3～4小時後問題重現。

針對這個問題，我身邊的同事也幫忙做了簡單分析，發現存在大量Merge的線程，應該怎麼辦呢？根據我之前定位問題的經驗，一般通過Thread Dump日誌分析，就能找到問題原因的正確方向，然後再分析該問題不斷重複的原因。按照這個思路，問題分析起來應該不算複雜。But，後來劇情還是出現了波折。

02 困惑的堆棧日誌

因網絡隔離原因，只能由客戶配合獲取Thread Dump日誌。並跟客戶強調了獲取Thread Dump日誌的技巧，每個節點每隔幾秒獲取一次，輸出到一個獨立的文件中。集群涉及到三個節點，我們暫且將這三個節點稱之為39，158， 211。問題復現後，拿到了第一批Thread Dump文件：

從文件的大小，可輕易看出39節點大概率是一個問題節點，它的Thread Dump日誌明顯大出許多：查詢變慢或者卡死，通常表現為大量的Worker Thread忙碌，也就是說，活躍線程數量顯著增多。而在ES(Elasticsearch，以下簡稱為ES)的默認查詢行為下，只要有一個節點出現問題，就會讓整個查詢受牽累。

那麼我們先對三個節點任選的1個Thread Dump文件的線程總體情況進行對比：

再按線程池進行分類統計：

可以發現：39節點上的Lucene Merge Thread明顯偏多，而其它兩個節點沒有任何Merge的線程。

再對39節點的Thread Dump文件進行深入分析，發現的異常點總結如下：

1. Lucene Merge Thread達到77個，其中一個線程的調用棧如下所示：

2. 有8個線程在競爭鎖定ExpiringCache：

3. 有8個線程都在做HashMap#hash計算：

現象1中提到了有77個同時在做Merge的線程，但無法確定這些Merge任務是同時被觸發的，還是因為系統處理過慢逐步堆積成這樣的狀態。無論如何這像是一條重要線索。再考慮到這是一個新上線的應用，關於環境信息與使用姿勢的調研同樣重要：

• 集群共有3個節點，目前共有500+個Indices。每個節點上寫活躍的分片數在70個左右。
• 按租戶創建Index，每個租戶每天創建3個Indices。上線初期，寫入吞吐量較低。每個索引在每分鐘Flush成的Segment在KB~數MB之間。

我開始懷疑這種特殊的使用方式：集群中存在多個寫活躍的索引，但每分鐘的寫入量都偏小，在KB至數MB級別。這意味着，Flush可能都是周期性觸發，而不是超過預設閾值後觸發。這種寫入方式，會導致產生大量的小文件。抽樣觀察了幾個索引中新產生的Segment文件，的確每一次生成的文件都非常小。

關於第2點現象，我認真閱讀了java.io.UnixFileSystem的源碼：

• UnixFileSystem中需要對一個新文件的路徑按照操作系統標準進行標準化。
• 標準化的結果存放在ExpiringCache對象中。

多個線程都在爭相調用ExpiringCache#put操作，這側面反映了文件列表的高頻變化，這說明系統中存在高頻的Flush和Merge操作。

這加劇了我關於使用姿勢的懷疑：”細雨綿綿”式的寫入，被動觸發Flush，如果周期相同，意味着同時Flush，多個Shard同時Merge的概率變大。

於是，我開始在測試環境中模擬這種使用方式，創建類似的分片數量，控制寫入頻率。計劃讓測試程序至少運行一天的時間，觀察是否可以復現此問題。在程序運行的同時，我繼續調查Thread Dump日誌。

第3點現象中，僅僅是做一次hash計算，卻表現出特別慢的樣子。如果將這三點現象綜合起來，可以發現所有的調用點都在做CPU計算。按理說，CPU應該特別的忙碌。

等問題在現場復現的時候，客戶協助獲取了CPU使用率與負載信息，結果顯示CPU資源非常閑。在這之前，同事也調研過IO資源，也是非常閑的。這排除了系統資源方面的影響。此時也發現，每一次復現的節點是隨機的，與機器無關。

一天過去後，在本地測試環境中，問題沒能復現出來。儘管使用姿勢不優雅，但卻不像是問題的癥結所在。

03 詭異的STW中斷

通過jstack命令獲取Thread Dump日誌時，需要讓JVM進程進入Safepoint，相當於整個進程先被掛起。獲取到的Thread Dump日誌，也恰恰是進程掛起時每個線程的瞬間狀態。

所有忙碌的線程都剛好在做CPU計算，但CPU並不忙碌。這提示需要進一步調查GC日誌。

現場應用並未開啟GC日誌。考慮到問題當前尚未復現，通過jstat工具來查看GC次數與GC統計時間的意義不太大。讓現場人員在jvm.options中手動添加了如下參數來開啟GC日誌：

 8:-XX:+PrintGCDetails
8:-XX:+PrintGCDateStamps
8:-XX:+PrintTenuringDistribution
8:-XX:+PrintGCApplicationStoppedTime
8:-Xloggc:logs/gc.log
8:-XX:+UseGCLogFileRotation
8:-XX:NumberOfGCLogFiles=32
8:-XX:GCLogFileSize=32m

添加
PrintGCApplicationStoppedTime是為了將每一次JVM進程發生的STW(Stop-The-World)中斷記錄在GC日誌中。通常，此類STW中斷都是因GC引起，也可能與偏向鎖有關。

剛剛重啟，現場人員把GC日誌tail的結果發了過來，這是為了確認配置已生效。詭異的是，剛剛重啟的進程居然在不停的打印STW日誌：

關於STW日誌(”…Total time for which application threads were stopped…”)，這裡有必要簡單解釋一下：

JVM有時需要執行一些全局操作，典型如GC、偏向鎖回收，此時需要暫停所有正在運行的Thread，這需要依賴於JVM的Safepoint機制，Safepoint就好比一條大馬路上設置的紅燈。JVM每一次進入STW（Stop-The-World）階段，都會打印這樣的一行日誌：

2020-09-10T13:59:43.210+0800: 73032.559: Total time for which application threads were stopped: 0.0002853 seconds, Stopping threads took: 0.0000217 seconds

在這行日誌中，提示了STW階段持續的時間為0.0002853秒，而叫停所有的線程(Stopping threads)花費了0.0000217秒，前者包含了後者。通常，Stopping threads的時間佔比極小，如果過長的話可能與代碼實現細節有關，這裡不過多展開。

回到問題，一開始就打印大量的STW日誌，容易想到與偏向鎖回收有關。直到問題再次復現時，拿到了3個節點的完整的GC日誌，發現無論是YGC還是FGC，觸發的頻次都很低，這排除了GC方面的影響。

出現的大量STW日誌，使我意識到該現象極不合理。有同學提出懷疑，每一次中斷時間很短啊？寫了一個簡單的工具，對每一分鐘的STW中斷頻次、中斷總時間做了統計：

統計結果顯示：

• 正常每分鐘都有5秒左右的中斷。
• 在11:29～11:30之間，中斷頻次陡增，這恰恰是問題現象開始出現的時間段。每分鐘的中斷總時間甚至高達20～30秒。

這就好比，一段1公里的馬路上，正常是遇不見任何紅綠燈的，現在突然增加了幾十個紅綠燈，實在是讓人崩潰。這些中斷很好的解釋了“所有的線程都在做CPU計算，然而CPU資源很閑”的現象。

04 關於Safepoint的調查

Safepoint有多種類型，為了確認Safepoint的具體類型，繼續讓現場同學協助，在jvm.options中添加如下參數，打開JVM日誌：

-XX:+PrintSafepointStatistics
-XX:PrintSafepointStatisticsCount=10
-XX:+UnlockDiagnosticVMOptions
-XX:-DisplayVMOutput
-XX:+LogVMOutput
-XX:LogFile=<vm_log_path>

等待問題再次復現的過程中，我基於ES運行日誌中統計了每一分鐘的讀寫請求頻次：

讀寫請求次數是相對平穩的，這排除了用戶請求陡增方面的原因。

拿到JVM日誌時，看到大量的Safepoint類型為ForceSafepoint：

而偏向鎖回收相關的Safepoint卻應該是長這樣的：

這讓我疑惑了。開始在網上搜索ForceSafepoint的觸發原因，結果，一無所獲。

查看hotspot的源碼，發現至少有5種相關場景：

可見，ForceSafepoint是一個“雜燴”，就像統計圖中的“Others”一項。從這裡開始，我將JDK加入到了“重點嫌疑人”清單中。

繼續分析JVM日誌。在每一條Safepoint日誌中，同時記錄了當時的線程總數(threads: total一列)：

回顧一下，出現問題時，三個節點的線程總數有明顯出入，問題發生後，線程總數是增多的，尤其是Lucene Merge Threads。

“多個Lucene Merge任務”與“陡增的ForceSafepoint/STW中斷”，哪個是“因”哪個是“果”？

依據JVM日誌中統計了每一分鐘的ForceSafepoint次數，以及線程總數的變化。將兩條曲線疊加在一起，得到下圖：

從圖中來看，似乎是ForceSafepoint逐步增多在先，後面的線程才逐步增多。也就是說，STW中斷變多在先，然後多個Merge任務線程才開始逐步積累，就好比，一條目錄上突然增設了多個紅綠燈，然後這條目錄逐步變得擁堵。

此時，開始請教Kona JDK團隊的同學，我把GC日誌以及thread dump日誌分享給了他，並把我目前為止的發現都告訴了他，最大的懷疑點就是這些不正常的ForceSafepoints，我需要了解ForceSafepoints的原因。

過了一段時間後，他回復我：這個是arm版本的jdk。因缺乏arm編譯機應急櫃，暫時沒法給我提供一個debug版本的arm jdk。

突然明白，我犯了”先入為主”的錯誤，儘管一開始就意識到需要對環境進行調查。

難怪在本地X86環境中始終無法復現。難怪網上搜索ForceSafepoint時一無所獲。

接下來和客戶電話會議溝通時，獲知：

1. 類似的業務，在另外一套X86環境中，沒有發現此類問題。
2. 在這套arm環境中，還有另外一個Elasticsearch集群，請求量更低，但沒有發現此類問題。
3. 環境中使用的arm jdk是從網上下載的，背後支持的廠商未知。

關於第2點提到的這套環境中的另外一個Elasticsearch集群，我更關心的是它的GC日誌中是否存在類似的現象。至於沒有發生此類問題，容易理解，因為這類問題往往是業務負載特點與環境多重因素疊加下的系統性問題。現場同學配合打開了這個Elasticsearch集群的GC與JVM日誌，現象同在，只是ForceSafepoint的頻次低於出問題的集群。

至此，問題原因清晰的指向了arm環境與JDK版本。

後來，微服務平台TSF團隊的臧琳同學介入，他提供了一個添加了debug信息的Kona JDK版本，儘管這個版本比正常版本慢了許多，更換以後，我們發現問題重現的周期明顯變長。

拿到最新的JVM日誌後，臧琳同學分析這些ForceSafepoint都與Inline Cache Buffer有關。當然，這可能是arm環境下所有JDK版本的共性問題，也可能僅僅是之前下載的JDK版本存在問題。

接下來，我們將環境中的JDK版本替換成正式Release的Kona JDK。再後來，問題始終沒有復現。也就是說，替換成Kona JDK後，問題解決了。

我統計了一下使用KonaJ DK後的STW中斷次數與中斷時間，發現有數量級的提升：

• 原JDK版本：每分鐘STW中斷5000次～18000次，每分鐘中斷總數據可能達到10秒～30秒。
• Kona JDK： 每分鐘STW中斷在個位數，每分鐘中斷總時間在100～200ms之間。

可見，Kona JDK比原來的問題JDK版本在性能上有了數量級的提升。

05 總結回顧

我們再來梳理一下整個問題的分析思路：

1. 通過堆棧分析，發現大量的線程都在做CPU計算，但 CPU資源較閑。關於大量Merge Threads的現象帶有一定的迷惑性，但它是問題的“果”而非“因”。

2. 通過GC日誌分析，發現GC頻次與GC時間都很低，但GC日誌中存在大量的STW相關日誌，需要確認關聯的Safepoint類型。

3. 通過VM/Safepoint日誌分析，確認了Safepoint的類型為ForceSafepoint。通過不同環境與不同集群的現象對比，開始懷疑JDK版本存在問題。

4. 更換Kona JDK後，ForceSafepoints頻次由每分鐘5000多次降低到個位數，問題解決。

通過本次問題的分析，得到一個教訓：問題分析初期應該認真調研集群環境。當然，最大的教訓是：千萬不要亂下載JDK啊！