使用 perf 解決 JDK8 小版本升級後效能下降的問題【畢昇JDK技術剖析 · 第 1 期】

語言: CN / TW / HK

編者按:在升級 JDK8U 的小版本後(從 8u74 升級到 8u202),遇到效能劇烈下降的問題(效能下降 13 倍)。該應用是一個非常簡單的 Web 應用,且應用在 JDK 升級前後並無任何釋出修復。通常來說 JDK 小版本升級都是問題修改,不影響功能和效能使用,而應用效能劇烈下降一定是 JDK 的內部 bug。對於這樣明確由 JDK 引起的效能問題,該如何解決?最常見的方法是通過工具分析 JVM 執行過程,檢查函式執行的情況是否發生變化,如果找到變化,則可以深入分析哪些因素引起了變化,並進一步得到根因。筆者使用 perf 工具分析 JVM 執行時的熱點函式,並對出現問題的函式進行剖析,使用函式插樁來分析函式的執行次數,發現不同版本行為差異的根源,並找到了引起問題的根因。希望讀者遇到效能問題時可以參照本文使用 perf 工具對問題進行定位。

工欲善其事,必先利其器。程式設計師在定位效能瓶頸的時候,要是有一個趁手的效能調優工具,能一針見血地指出程式的效能問題,可謂事半功倍。

Linux 中最常用的效能調優工具 Perf(Linux 系統原生提供的效能分析工具),使用 perf 先對應用(假設要取樣的應用為 JavaApp)進行取樣,使用 record 命令,如下:

perf record java JavaApp

另外 perf 能按出現的百分比降序列印 CPU 正在執行的函式名以及呼叫棧,如命令:

perf report -n

可打印出:

這種結果的輸出還是不直觀的,Linux 效能優化大師 Brendan Gregg 發明了火焰圖(因整個圖形看起來像燃燒的火焰而得名),以全域性的方式來看各個函式的呼叫時間分佈,以圖形化的方式列出呼叫棧。

初識火焰圖

火焰圖是基於 perf 的結果生成的圖形,我們先了解一下怎麼去看火焰圖。以下圖為例:

X 軸表示被抽樣到的次數。理解 X 軸的含義,需先了解取樣資料的原理。Perf 是在指定時間段內,每隔一段時間採集一次資料,被採集到的次數越多,說明該函式的執行總時間長,可能的原因有:呼叫次數多,或者單次執行時間長。因此,X 軸的寬度不能簡單的認為是執行時長。Y 軸表示呼叫棧。

如何從火焰圖看出效能的瓶頸在哪裡?最有理由懷疑的地方,頂層的“平頂”。關於 perf 和火焰圖使用方法可以參官網http://www.brendangregg.com/FlameGraphs/cpuflamegraphs.html。

下面是我們利用火焰圖來定位問題的一次實戰。

火焰圖定位問題的實戰

問題場景

問題發生的場景是客戶端向伺服器發起 http 請求,伺服器返回資料給客戶端(這是一個非常簡單的服務互動)。我們發現使用 JDK 8u74 的效能要遠優於 JDK 8u202 的效能,下表中統計了 20 次伺服器的響應時長。

從響應時間來看,8u202 相比 8u74 效能下降 13 倍之多,由於應用本身並未做任何修改,所以考慮使用火焰圖來定位效能消耗的問題點。在 8u74 和 8u202 分別執行應用,並用 perf 的 record 抓取資料並生成火焰圖。

火焰圖定位

對比兩張火焰圖,使用 8u74 時 ClientHandshaker.processMessage 佔比為 1.15%,而在 8u202 中這個函式佔比為 23.98%,很明顯在 ClientHandshaker.processMessage 帶來了效能差異。

根因定位

兩者在這個 ClientHandshaker.processMessage 上的 cpu 消耗差異很大,繼續分析這個函式找到根因。

void processMessage(byte handshakeType, int length) throws IOException {
    if(this.state >= handshakeType && handshakeType != 0) {
        //... 異常
    } else {
        label105:
        switch(handshakeType) {
        case 0://hello_request
            this.serverHelloRequest(new HelloRequest(this.input));
            break;
        //...
        case 2://sever_hello
            this.serverHello(new ServerHello(this.input, length));
            break;
        case 11:///certificate
            this.serverCertificate(new CertificateMsg(this.input));
            this.serverKey = this.session.getPeerCertificates()[0].getPublicKey();
            break;
        case 12://server_key_exchange 該訊息並不是必須的,取決於協商出的key交換演算法
            //...
        case 13: //certificate_request 客戶端雙向驗證時需要
            //...
        case 14://server_hello_done
            this.serverHelloDone(new ServerHelloDone(this.input));
            break;
        case 20://finished
            this.serverFinished(new Finished(this.protocolVersion, this.input, this.cipherSuite));
        }
        if(this.state < handshakeType) {//握手狀態
            this.state = handshakeType;
        }
    }
}

processMessage()主要是通過不同的資訊型別進行不同的握手訊息的處理。而在火焰圖中可以看到,JDK8u74 圖中,主要消耗在函式 serverFinished()和 serverHello()上,而 JDK8u202 主要消耗在函式 serverHelloDone()和 serverKeyExchange()。在介紹火焰圖的時候,我們有提到,X 軸的長度是映射了被取樣到的次數。因此需要進一步確定消耗:函式單次執行耗時過長而成為熱點,還是因為頻繁呼叫函式導致函式耗時過長而成為熱點。可通過位元組碼插樁(通過 Instrument 技術實現對函式的計數,然後編譯成 agent,執行應用時載入 agent,具體使用 Instrument 的方法可以參考官方文件)檢視函式 serverHelloDone()的呼叫次數及執行時間。

JDK8u202 資料
Execute count : 253
Execute count : 258
Execute count : 649
Execute count : 661
serverHelloDone execute time [1881195 ns]
Execute count : 1223
Execute count : 1234
Execute count : 1843
Execute count : 1852
serverHelloDone execute time [1665012 ns]
Execute count : 2446
Execute count : 2456
serverHelloDone execute time [1686206 ns]
JDK8u74 資料
Execute count : 56
Execute count : 56
Execute count : 56
Execute count : 56
Execute count : 56
Execute count : 56

Execute time 是取了每 1000 次呼叫的平均值,Execute count 每 5000ms 輸出一次總執行次數。很明顯使用 JDK8u202 時在不斷呼叫 serverHelloDone,而 74 在呼叫 56 次後沒有再呼叫過這個函式。

初始化握手時,serverHelloDone 方法中,客戶端會根據服務端返回加密套件決定加密方式,構造不同的 Client Key Exchange 訊息;伺服器如果允許重用該會話,則通過在 Server Hello 訊息中設定相同的會話 ID 來應答。這樣,客戶端和伺服器就可以利用原有會話的金鑰和加密套件,不必重新協商,也就不再走 serverHelloDone 方法。從現象來看, JDK8u202 沒有複用會話,而是建立的新的會話。

水落石出

檢視 JDK8u 161 的 release notes,添加了 TLS 會話雜湊和擴充套件主金鑰擴充套件支援,找到引入的一個還未修復的 issue,對於帶有身份驗證的 TLS 的客戶端,支援 UseExtendedMasterSecret 會破壞 TLS-Session 的恢復,導致不使用現有的 TLS-Session,而執行新的 Handshake。

JDK8u161 之後的版本(含 JDK8u161),若複用會話時不能成功恢復 Session,而是建立新的會話,會造成較大效能消耗,且積壓的大量的不可複用的 session 造成 GC 壓力變大;如果業務場景存在不變更證書金鑰,需要複用會話,且對效能有要求,可通過新增引數-Djdk.tls.useExtendedMasterSecret=false 來解決這個問題。

後記

如果遇到相關技術問題(包括不限於畢昇 JDK),可以通過畢昇 JDK 社群求助。畢昇 JDK 社群每雙週週二舉行技術例會,同時有一個技術交流群討論 GCC、LLVM 和 JDK 等相關編譯技術,感興趣的同學可以新增如下微信小助手入群(請備註:Complier)。

------------------------------------------------------------------------

畢昇JDK技術剖析系列博文:

第1期:使用 perf 解決 JDK8 小版本升級後效能下降的問題

第2期:JVM 鎖 bug 導致 G1 GC 掛起問題分析和解決

畢昇JDK資訊:

2021年畢昇 JDK 的第一個重要更新來了

畢昇 JDK 8u292、11.0.11 釋出!

------------------------------------------------------------------------

 

本文分享自微信公眾號 - openEuler(openEulercommunity)。
如有侵權,請聯絡 [email protected] 刪除。
本文參與“OSC源創計劃”,歡迎正在閱讀的你也加入,一起分享。