性能分析-java程序篇之案例-工具和方法

1. 背景說明

線上服務響應時間超過40秒，登陸服務器發現cpu將近100%了(以下圖)，針對此問題，本文說明排查過程、工具以定位具體的緣由。

2. 分析排查過程

此類問題的排查，有兩款神器可用，分別是async-profiler和arthas，async-profiler主要用於全局分析，經過此工具能夠找到熱點方法，
再用arthas對此熱點方法進行詳細的追蹤，trace命令能夠追蹤方法的具體耗時，watch命令能夠查看方法的出入參數，在結合源代碼能夠比較
方便定位到問題緣由。下面記錄排查過程：

2.1. 用async-profiler生成火焰圖

到下載後，解壓後以下所示：

執行命令生成火焰圖：
./profiler.sh -d 300 1485 -f ./test.svg
其中 -d 300 表示採集300s的數據，300s結束後，自動生成test.svg文件到當前目錄。

2.2. 火焰圖分析

用瀏覽器打開上面生成的svg文件，以下：

火焰圖中縱向表明調用棧，即方法的調用深度，橫向是方法佔用cpu的時間比率，所以火焰圖中若是出現平頂現象，說明相關方法耗時長（即爲熱點方法），是分析優化的對象；
從上圖可看出：java/util/ComparableTimSort.countRunAndMakeAscending方法爲熱點方法，能夠根據此方法的調用棧對相關方法進行追蹤：
io/micrometer/core/instrument/MeterRegistry.getMappedId
io/micrometer/core/instrument/Tags.and

2.3. 追蹤方法具體耗時和調用關係

此時可採用arthas工具，改工具的安裝和使用方法可參考：《arthas用戶指南》

2.3.1. 追蹤getMappedId

arthas控制檯中執行下面命令：
trace io.micromete/core.instrument.MeterRegistry getMappedId

io.micrometer.core.instrument.MeterRegistry#getMappedId耗時近40s，期間此方法中調用了2458次MeterFilter.map()方法: 該方法源代碼以下：

經過屢次執行該命令發現，filters數組會隨着請求增長而不斷上漲；那麼這個filters數組究竟是什麼內容呢？

2.3.2. 監控類的返回對象

watch MeterRegistry "{returnObj}" -x 3 -n 3

發現數組中儲存的都是相同內容的tag，繼續查看源代碼，io.micrometer.core.instrument.MeterRegistry類中成員變量賦值的相關代碼：

2.3.3. 監控Tags and方法的入參

watch io.micrometer.core.instrument.Tags and "{params}" -x 2 -b -n 4

2.4. 緣由

commonTags每調用一次，filters數組長度+1，會進行一次copy，不斷增加，getMappedId方法中循環對tag進行and操做、排序、去重致使cpu飆高；
下面是致使這個問題緣由精簡後的模擬代碼：

2.5. 解決方式

commonTags應在服務初始化的時候設置，如在spring boot的配置文件中設置：