使用 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源創計劃”,歡迎正在閲讀的你也加入,一起分享。