05.23 一場版本升級引發的性能血案的追凶過程

1. 故事的開始

上週 ActFramework 推出 act-1.8.8-RC4 版本 後, 我興致勃勃更新了 TFB 性能 PK 項目 到最新版, 經過漫長的 60 小時 ( TFB 的一次運行週期是 60 小時) 等待後終於等來了 .............................................. 噩耗: Act 這次的性能驟然下降, 不同測試的下降範圍從 60% 到 90% 不等!

不多說了, 說起來都是淚啊. 先上圖吧 (為了更加切合重點, 設置了測試過濾, 只顯示 Java 全棧框架, 且排除掉了直接用 JDBC 的測試項目):

1.1 JSON 測試

act-1.8.1

act-1.8.8-RC4

JSON 測試性能下降: 74%

1.2 單次數據庫查詢測試

act-1.8.1

act-1.8.8-RC4

單次數據庫查詢測試性能下降: 73%

1.3 20 次數據庫查詢測試

act-1.8.1

act-1.8.8-RC4

20 次數據庫更新測試性能下降: 76%

1.4 數據查詢帶後臺模板測試

act-1.8.1

act-1.8.8-RC4

數據查詢帶後臺模板測試下降: 60%

1.5 20 次數據庫更新性能測試

act-1.8.1

act-1.8.8-RC4

20 次數據庫更新測試下降: 50%

1.5 返回 helloworld 字串性能測試

act-1.8.1

act-1.8.8-RC4

返回 helloworld 字串測試下降: 90%

2. 追兇

這個結果直接把 ActFramework 扔進 Spring 的朋友圈去了, 這分明就是叔叔可以忍, 嬸嬸不能忍啊. 立馬拉響紅色警報, 開始緝拿兇手.

2.1 從簡單之處入手

既然所有測試結果都有所下降, 那就從最簡單的 Hello World 開始調查. 啟動項目先:

先看能不能訪問, 再拿出 wrk 壓測一萬年

2.2 被神器忽悠了

現在祭出白試不爽神器 JVisualVM, 開始抽樣 CPU

果然發現貓膩, <code>Router.getInvoker/<code> 居然吃掉大部分 CPU, 這是種麼回事? 創建一個 SNAPSHOT 來分析一把:

WTF! <code>binarySearch/<code> 居然會是 bottleneck !!! 我讀書雖少也不是隨便相信鬼話的人, 不過還是查看一下代碼先:

這裡面的 <code>targetMethods/<code> 是這樣的:

並沒有一萬個東西需要 search 啊, 這個 JDK 的二分查詢會是瓶頸, 打死老碼農也不會相信啊. 追兇時間迅速從七七四十九分鐘上升到了九九八十一分鐘, 還是沒有任何進展.

2.3 抓住頭號兇手

既然頭號嫌疑犯搞不清楚, 那就追查二號嫌犯吧. 回到 CPU 抽樣, 看到這個 <code>org.osgl.util.S$Buffer.<init>/<code> 比較射眼睛:

是什麼原因造成 Buffer 分配成為瓶頸的呢? 在創建一個 SNAPSHOT, 暫時掠過一號嫌疑, 從二號入手, 果然發現蹊蹺之處:

每個請求進來都會創建 <code>ActionContext/<code>, 毫無疑問這是兵家必爭之地, 絕對繞不過去的, 跑回去看代碼發現<code>ActionContext/<code> 的父類出現了這麼一條語句:

的確是在 act-1.8.2 的時候整進去的, 目的是搞這麼一個東西, 以後就不需要創建新的 <code>StringBuilder/<code>了,可以降低 GC 壓力. 可是當時不知道發什麼神經, 居然一開始就給 buffer 初始化最大限額的空間, 話說這個默認空間大小是這樣設定的:

而中間 <code>calc.calculate/<code> 的過程是這樣的:

用簡單的話來講就是默認大小是 JVM 可用內存大小的 128 分之一再除以線程數, 這個數字對於 TFB 測試 (給 JVM 分配了 2G) 來講差不多是 512K. 也就是說每次請求進來先分配幾百 k 的空間, 這個當然是不能忍受的. 當時的思路沒有問題, 不過殘酷的事實再次讓老碼農複習了 "理想是美好的 現實是骨感的" 這句箴言

立馬乾掉這個邏輯之後, 果然發現性能提升了至少 50%.

2.4 第二個兇犯暴露

回過頭來研究頭號嫌犯依舊沒有進展, 不過在整個過程中發現了第二個性能損耗的兇手, 在 act-1.8.8 中引入的新式武器, 允許開發人員使用 Query 參數來 overwrite HTTP Header, 比如直接在瀏覽器上模擬發起 JSON 類型請求可以這樣寫: <code>GET /url/?act_header_content_type=application%2Fjson&act_header_accept=application%2Fjson/<code> 可以讓 Act 將該請求的 <code>Content-Type/<code> 和 <code>Accept/<code> 頭當作 <code>application/json/<code> 處理. 這個過程需要做 Keyword 匹配, 單次消耗時間雖然可以忽略不及, 但是要上 TFB 這種殘酷擂臺, 這樣的消耗都是不能忽略的. 所以立馬發明了一個新的配置<code>act.header.overwrite/<code>, 當設置為 <code>true/<code> 的時候上面的特性才會生效. 這樣又能提高几個百分點了.

2.5 第三個兇犯

折騰了一整天的 JVisualVM 還是不能搞清楚 Router 裡面那個方法的問題. 最後老碼農發飆了, 放棄了神器, 經過研究下載了 JProfiler 來幫助搞清楚這個事情. 需要花錢的東西和白給的東西之間的差距不用說了, JProfiler 立馬把問題查的清清楚楚:

1.8.1 的情況:

1.8.8-RC4 的情況

非常明顯的區別, 在 plaintext 的測試中 1.8.1 走了捷徑, 沒有調用 before after callback, 也因此沒有設置 Content-Type 頭, 經過繼續追兇, 還發現 1.8.1 沒有 clear ActionContext. 這裡 1.8.8-RC4 並沒有大的問題, 其實是修復了 1.8.1 的邏輯錯誤. 這部分性能損耗是應該的, 無法避免. 當然老碼農也做了一些響應的優化, 比如允許開發人員指定某些請求處理器不參與 before, after 的 event trigger 過程. 這些都是題外話了.

3. 總結

對於 Java 系統遇到性能問題時的應對方式:

1. 從簡單情況入手

2. 學會使用 JVisualVM (JDK 自帶, 免費免費免費)

3. 當 JVisualVM 開始忽悠的時候要請出真正的高手, 就像 JProfiler 這樣的.