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

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

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

WTF! binarySearch 居然會是 bottleneck !!! 我讀書雖少也不是隨便相信鬼話的人, 不過還是檢視一下程式碼先:

這裡面的 targetMethods 是這樣的:

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

2.3 抓住頭號凶手

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

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

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

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

而中間 calc.calculate 的過程是這樣的:

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

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

2.4 第二個凶犯暴露

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

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 這樣的.

4. 題外話

TFB (TechEmpower Framework Benchmark) 平臺不僅僅是一個展示框架實力的 T 型臺, 更重要的是能夠幫助框架作者發現自己框架一些潛在的問題, 是一個極好的測試反饋工具. 對於框架使用者來講則是提供了一個相對客觀的參考, 不僅框架效能可以通過 TFB 直接拿到 , 框架的易用性也可以通過參加框架的測試專案反映出來.

目前在國內已經有多個開源產品登陸 TFB, 包括 Java 陣營的 ActFramework, blade 和 redkale; Go 陣營的 beego, revel; D 語言陣營的 hunt 還有宇宙語言 PHP 陣營中的 swoole 最近也加入了 TFB, 而且表現出非常強勁的實力, 值得圍觀

公眾號推薦: