前段時間我們接入了 ELK 公司出品的 Elastic-APM 作為全鏈路監(jiān)控平臺内列，終結(jié)了我好幾年前擼的字節(jié)碼注入全鏈路監(jiān)控平臺沟使。前段時間有一個業(yè)務(wù)在啟動過程中，會概率性出現(xiàn)大量線程阻塞，導(dǎo)致可對外提供服務(wù)的 HTTP 線程非常少栽连，流量進(jìn)來以后馬上出現(xiàn) HTTP 線程耗盡，健康檢查接口請求失敗侨舆，服務(wù)被 k8s 殺死秒紧。
堆棧分析
既然是線程的問題，當(dāng)然想到的是 dump 線程堆棧挨下，人肉閱讀也可以熔恢，上傳到 PerfMa XSheepdog 會更加簡單。在鎖的這一欄的截圖如下所示臭笆。
可以看到 http-nio-18880-exec-44 線程持有了一個鎖叙淌，這個鎖被其它的 199 個線程等待秤掌。持有鎖的線程堆棧如下圖所示。
上層的調(diào)用方法是 co.elastic.apm.agent.bci.ElasticApmAgent#ensureInstrumented鹰霍，這段邏輯背后是在調(diào)用 bytebuddy 利用 ASM 進(jìn)行 class 的轉(zhuǎn)換注入闻鉴。
等待鎖的線程恰好 block 也在這個方法，如下圖所示茂洒。
通過堆棧分析孟岛，這個問題的出現(xiàn)與我們業(yè)務(wù)代碼用了 ParallelStream 有關(guān)。Java 中的 Stream 是一個比較好用的東西督勺，在函數(shù)式編程渠羞、流式數(shù)據(jù)處理上寫起來比較簡單。除了串行化的流式處理智哀，Java 也提供了并行流 parallelStream 可以使用多核多線程并行處理次询，如下圖所示。
我們的業(yè)務(wù)代碼是這樣的：
private List<TaskRule> getTaskRules(Task task, List<TaskRule> taskRules) {
return taskRules.parallelStream()
.filter(taskRule -> taskRule.getTaskId().equals(task.getId()))
.sorted(Comparator.comparing(TaskRule::getLower))
.collect(Collectors.toList());
}
parallelStream 背后的男人是 ForkJoin盏触，采用分治的方式將任務(wù)分解為小任務(wù)渗蟹，然后通過 ForkJoinPool 線程池來實現(xiàn)并行化。
ES-APM 為了突破跨線程鏈路追蹤赞辩，對多線程相關(guān)的類做了注入雌芽，apm-java-concurrent-plugin 插件會注入所有 ForkJoinTask 的子類，F(xiàn)orkJoin 底層實現(xiàn)用到的很多類都繼承了 ForkJoinTask辨嗽，比如下面這些：
- java.util.stream.Nodes$CollectorTask
- java.util.stream.Nodes
OfRef
- java.util.stream.ReduceOps$ReduceTask
- java.util.concurrent.CountedCompleter
- ...
在服務(wù)啟動后洪乍，大量的 HTTP 請求進(jìn)來調(diào)用 getTaskRules 這個方法怜瞒，HTTP 線程监婶、ForkJoinPool 中的線程都會調(diào)用到 ES-APM 的代碼览芳，判斷這些類有沒有被字節(jié)碼注入。ES-APM 判斷類有沒有被轉(zhuǎn)換的代碼如下：
上面的代碼有一個明顯的并發(fā)問題洲押，這里的邏輯是首先查詢類有沒有被轉(zhuǎn)換武花，如果沒有，則進(jìn)入到一個類鎖杈帐，做相關(guān)類的字節(jié)碼注入体箕。
在并發(fā)量高的情況下，HTTP 線程挑童、ForkJoinPool 中的線程調(diào)用了 getOrCreate 方法累铅，這時因為類還沒有轉(zhuǎn)換，返回了一個空的 set站叼，然后有一個幸運兒搶到了 ElasticApmAgent 類鎖娃兽，其它所有的線程都 block 住了。
當(dāng)幸運兒執(zhí)行完類的轉(zhuǎn)換尽楔，下一個搶到類鎖的線程還會再對類轉(zhuǎn)換一遍（可怕）投储。其它的沒搶到的還要繼續(xù) block第练。不僅如此，因為 ForkJoinPool 線程池中的線程也會 block 在這個轻要，導(dǎo)致 http 請求也會 block复旬，很快整個 tomcat 線程池就被耗盡了垦缅。
這還沒完冲泥，其實如果處理<typo id="typo-1785" data-origin="的" ignoretag="true">的</typo>非常快壁涎，也沒有什么太大的問題凡恍，只是同一個類，每經(jīng)過一次改寫怔球，就會變復(fù)雜嚼酝，文件變得更大，下次類的字節(jié)碼注入花的時間就更長竟坛。
使用 arthas 去注入 Bytebuddy 的 AgentBuilderExecutingTransformer.transform 方法闽巩，這個方法的簽名如下。
private byte[] transform(JavaModule module,
ClassLoader classLoader,
String internalTypeName,
Class<?> classBeingRedefined,
ProtectionDomain protectionDomain,
byte[] binaryRepresentation) {
}
其中 internalTypeName 表示要轉(zhuǎn)換的類的類名担汤，binaryRepresentation 表示當(dāng)前轉(zhuǎn)換類最新的字節(jié)碼數(shù)據(jù)涎跨。
啟動 arthas，開啟 unsafe：
options unsafe true
然后使用 watch 命令觀察<typo id="typo-2397" data-origin="入?yún)? ignoretag="true">入?yún)?lt;/typo>
watch co.elastic.apm.agent.shaded.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer transform "{params}" -x 2
ts=2020-10-22 03:41:52; [cost=0.358887ms] result=@ArrayList[
@Object[][
null,
null,
@String[java/util/concurrent/CountedCompleter],
@Class[class java.util.concurrent.CountedCompleter],
null,
@byte[][isEmpty=false;size=4379],
],
]
...
ts=2020-10-22 03:47:26; [cost=1021.689119ms] result=@ArrayList[
@Object[][
null,
@String[java/util/concurrent/CountedCompleter],
@Class[class java.util.concurrent.CountedCompleter],
null,
@byte[][isEmpty=false;size=88422],
],
]
ts=2020-10-22 03:50:27; [cost=1419.025166ms] result=@ArrayList[
@Object[][
null,
@String[java/util/concurrent/CountedCompleter],
@Class[class java.util.concurrent.CountedCompleter],
null,
@byte[][isEmpty=false;size=102910],
],
]
可以看到 CountedCompleter 類經(jīng)過多次轉(zhuǎn)換崭歧，從幾 k 大小變?yōu)榱?100k 以上隅很，繼續(xù)轉(zhuǎn)換還變得更大，代碼變得更復(fù)雜率碾，ASM 注入字節(jié)碼的時間會變得越來越長叔营，表現(xiàn)出來的現(xiàn)象就是：
- 持有鎖的線程花在轉(zhuǎn)換類的時間會越來越長
- 相應(yīng)的，等待鎖的線程將要等待更久的時間
我在代碼中加了一些打印所宰，time 后面的兩個數(shù)字绒尊，第一個是 ensureInstrumented 整個方法的耗時，第二個是 Bytebuddy 字節(jié)碼注入的耗時仔粥，單位都是毫秒婴谱。
[06:15:32][http-nio-18880-exec-49]done:class java.util.stream.Nodes$CollectorTask time:313 306
[06:15:33][http-nio-18880-exec-45]done:class java.util.stream.Nodes$ToArrayTask$OfRef time:496 233
...
[06:15:50][http-nio-18880-exec-17]done:class java.util.stream.Nodes$ToArrayTask$OfRef time:18317 1075
...
[06:16:54][http-nio-18880-exec-27]done:class java.util.stream.Nodes$ToArrayTask$OfRef time:81713 5481
...
[06:22:51][http-nio-18880-exec-59]done:class java.util.stream.Nodes$CollectorTask time:438733 24975
...
可以看到等鎖的線程，有的等了 400 多秒件炉，bytebuddy 字節(jié)碼注入的時間也在快速增大勘究，后面甚至要幾分鐘。
驗證
為了側(cè)面印證前面的分析過程斟冕，可以驗證這樣的情況：第一次只有一個請求口糕，沒有用戶造成的并發(fā)情況，讓并發(fā)相關(guān)的類都快速注入完成磕蛇，再來做壓測景描，看看還會不會出問題十办。步驟如下：
- 第一步，等服務(wù)啟動完超棺，使用 curl 請求向族，先請求一次接口。
- 然后使用 ab 或者 jmeter 瘋狂來壓那個接口棠绘，看看接口的響應(yīng)情況件相。
結(jié)果如預(yù)料中的一樣，接口響應(yīng)時間正常了氧苍，jstack 查看現(xiàn)場的堆棧夜矗，也沒有任何線程阻塞等在 ElasticApmAgent 的類鎖上了。
解決辦法
最簡單的解決是業(yè)務(wù)暫時去掉 parallelStream让虐，有坑先繞過紊撕。還有一個不成熟的改法，也不知道對不對：把 synchronized 同步塊里的雞肋二次判斷 contains 前面加一行獲取最新 appliedInstrumentations 的邏輯赡突，如下所示对扶，如果已經(jīng)轉(zhuǎn)換過了，就可以跳過后面的邏輯了惭缰。
經(jīng)過重新打包 ES-APM 進(jìn)行測試浪南，確實解決了這個場景下的問題。
小結(jié)
出問題的時候从媚，不要懷疑自己逞泄，大膽的懷疑框架吧，ES-APM 這個調(diào)用超級頻繁的代碼中有一個類鎖性能好不到哪里去拜效，有很大的改善空間喷众。好了，落班紧憾。
