gprofng如何幫助我們深入研究Java應(yīng)用程序的動(dòng)態(tài)行為？

首先，編寫(xiě)一個(gè)矩陣乘法程序（matrix multiplication program）。我寫(xiě)了一個(gè)完整的矩陣乘法程序，這比矩陣向量乘法（matrix-times-vector）要簡(jiǎn)單。主要有三種操作：

1

計(jì)算最內(nèi)層乘加操作（the inner-most multiply-add）

2

將乘加操作合并為結(jié)果中的單個(gè)元素

3

對(duì)最終結(jié)果的每個(gè)元素進(jìn)行迭代計(jì)算

我將矩陣乘法的計(jì)算過(guò)程放入一個(gè)簡(jiǎn)單的框架中，以便能夠重復(fù)地計(jì)算矩陣乘積，從而確保測(cè)量是可多次重復(fù)的（見(jiàn)附注 1）。該程序會(huì)在每次矩陣相乘開(kāi)始時(shí)（相對(duì)于 Java 虛擬機(jī)的啟動(dòng)時(shí)間）打印出信息，包括每次矩陣相乘所需的時(shí)間。我還運(yùn)行了一個(gè)測(cè)試，將兩個(gè) 8000x8000 的矩陣相乘，該框架會(huì)重復(fù)計(jì)算 11 次，并為了使后續(xù)不同行為的特征更突出，在每次重復(fù)之間設(shè)置休眠 920 毫秒：

$ numactl --cpunodebind=0 --membind=0 -- 
   java -XX:+UseParallelGC -Xms31g -Xmx31g -Xlog:gc -XX:-UsePerfData 
    MxV -m 8000 -n 8000 -r 11 -s 920

圖 1：矩陣乘法程序的運(yùn)行情況

第二次重復(fù)運(yùn)行的用時(shí)是第一次的 92%；到最后一次重復(fù)運(yùn)行時(shí)，用時(shí)僅為第一次的 89%。執(zhí)行時(shí)間的變化證明了Java 程序需要一段預(yù)熱的時(shí)間。

那么問(wèn)題來(lái)了：能否用 gprofng 來(lái)分析第一次與最后一次重復(fù)運(yùn)行之間的差異，從而促進(jìn)性能提升？

為了回答這個(gè)問(wèn)題，我們可以運(yùn)行程序并讓 gprofng 收集有關(guān)運(yùn)行的信息。方法非常簡(jiǎn)單，只需在命令行中添加 gprofng 命令前綴，即可收集 gprofng 稱之為 “experiment” 的信息。

$ numactl --cpunodebind=0 --membind=0 -- 
   gprofng collect app 
     java -XX:+UseParallelGC -Xms31g -Xmx31g -Xlog:gc --XX:-UsePerfData 
       MxV -m 8000 -n 8000 -r 11 -s 920

圖 2：在 gprofng 下運(yùn)行矩陣乘法程序

首先需要注意的是，與其它 profiling 工具一樣，gprofng 在收集 profiling 信息時(shí)也會(huì)為應(yīng)用程序帶來(lái)開(kāi)銷（overhead），好消息是，與不加 profiling 信息運(yùn)行相比，gprofng 所帶來(lái)的開(kāi)銷看起來(lái)并不顯著。

隨后，可以通過(guò) gprofng 深入了解整個(gè)應(yīng)用程序的時(shí)間消耗情況（見(jiàn)附注 2）。對(duì)于整個(gè)運(yùn)行過(guò)程，gprofng 顯示了24 個(gè)最耗時(shí)的函數(shù)調(diào)用，具體如下：

$ gprofng display text test.1.er -viewmode expert -limit 24 -functions

圖 3：Gprofng 展示了 24 個(gè)最耗時(shí)的函數(shù)調(diào)用

上面的函數(shù)視圖展示了每種方法的獨(dú)占 CPU 時(shí)間和總體 CPU 時(shí)間，均以秒為單位，并以總 CPU 時(shí)間的百分比表示。被命名的的函數(shù)是由 gprofng 生成的偽函數(shù)（pseudo function），其值為各種指標(biāo)的總和。從數(shù)據(jù)中可以看出，整個(gè)應(yīng)用程序消耗的總 CPU 時(shí)間為 1.201 秒。

其中，應(yīng)用程序中屬于 Matrix times Vector（MxV）類的方法占用了大部分 CPU 時(shí)間，但除此之外還有其它方法，如 JVM 的運(yùn)行時(shí)編譯器（Compilation::Compilation）和不屬于矩陣乘法的其他函數(shù)。此外，圖表在展示整體程序執(zhí)行情況的同時(shí)，還捕捉到了分配（MxV.allocate）和初始化（MxV.initialize）的代碼。不過(guò)，我對(duì)這些代碼不太感興趣，因?yàn)樗鼈兪菧y(cè)試框架的一部分，僅在啟動(dòng)期間使用，與矩陣乘法本身關(guān)聯(lián)不大。

gprofng 可以讓我專注在感興趣的應(yīng)用程序部分上。它有一個(gè)奇妙之處是，在收集實(shí)驗(yàn)之后，我可以使用過(guò)濾器來(lái)處理收集到的數(shù)據(jù)。例如，查看在特定時(shí)間間隔內(nèi)發(fā)生了什么，或者查看特定方法在調(diào)用棧（call stack）上的情況。為了演示和方便進(jìn)行過(guò)濾，我在程序中添加了 Thread.sleep（ms）的策略性調(diào)用，這樣可以更容易地基于相隔一秒的程序階段編寫(xiě)過(guò)濾器。這就是為什么在圖 1 的程序輸出中，即使每個(gè)矩陣相乘只花費(fèi)約 0.1 秒，但每次重復(fù)之間仍相隔約 1 秒的原因。

gprofng 支持編寫(xiě)腳本。我用它編寫(xiě)了一個(gè)腳本，用于從 gprofng 實(shí)驗(yàn)中提取不同秒數(shù)的數(shù)據(jù)。第一秒主要與 Java 虛擬機(jī)的啟動(dòng)相關(guān)：

圖 4：篩選出第 1 秒內(nèi)最耗時(shí)的函數(shù)調(diào)用。為了能夠清楚地展示 JVM 的啟動(dòng)過(guò)程，我特意在矩陣乘法上制造了一些延遲。

即使應(yīng)用程序中的所有函數(shù)調(diào)用都尚未開(kāi)始運(yùn)行，運(yùn)行時(shí)編譯器（例如 Compilation::compile_java_method，占用了約 16% 的 CPU 時(shí)間）就已經(jīng)啟動(dòng)。（由于我插入了 sleep 調(diào)用，矩陣乘法調(diào)用被延遲了。）

第 1 秒之后，第 2 秒主要是分配函數(shù)和初始化函數(shù)的運(yùn)行，以及各種 JVM 函數(shù)的執(zhí)行。但此時(shí)，矩陣乘法的任何代碼都尚未開(kāi)始執(zhí)行：

圖 5：展示了第 2 秒內(nèi)最耗時(shí)的函數(shù)。矩陣的分配和初始化與 JVM 的啟動(dòng)互相競(jìng)爭(zhēng)。

此時(shí) JVM 啟動(dòng)以及數(shù)組的分配和初始化已完成。如圖 6 所示，第 3 秒是矩陣乘法代碼的第一次重復(fù)。但請(qǐng)注意，矩陣乘法代碼正在與 Java 運(yùn)行時(shí)編譯器爭(zhēng)奪機(jī)器資源（例如，圖 6 中的CompileBroker::invoke_compiler_on_method 占比 8%），這是由于矩陣乘法代碼耗時(shí)較多，這時(shí)仍在進(jìn)行編譯。

即便如此，矩陣乘法代碼（例如，在 MxV.main 方法中的“包含”時(shí)間占比 91%）占用了大部分 CPU 時(shí)間。包含時(shí)間顯示矩陣乘法（如 MxV.multiply）需要 0.100 CPU 秒，這與圖 2 中應(yīng)用程序報(bào)告的墻上時(shí)鐘一致。（收集和報(bào)告墻上時(shí)鐘需要一定的時(shí)間，但這不包括 gprofng 計(jì)算 MxV.multiply 方法所占用的 CPU 時(shí)間）。

圖 6：第 3 秒內(nèi)最耗時(shí)的函數(shù)，顯示了運(yùn)行時(shí)編譯器與矩陣乘法方法之間的資源競(jìng)爭(zhēng)。

在這個(gè)特定的示例中，矩陣乘法實(shí)際上并沒(méi)有參與爭(zhēng)奪 CPU 時(shí)間，因?yàn)闇y(cè)試是在具有大量空閑周期的多處理器系統(tǒng)上運(yùn)行，而運(yùn)行時(shí)編譯器則作為單獨(dú)的線程運(yùn)行。在某些特定的、受到限制的情況下，例如在負(fù)載較重的共享機(jī)器上，運(yùn)行時(shí)編譯器占用 8% 的時(shí)間可能會(huì)對(duì)整體性能造成影響。但另一方面，在運(yùn)行時(shí)編譯器上花費(fèi)時(shí)間會(huì)使得方法能夠更高效地執(zhí)行，因此，如果要計(jì)算多個(gè)矩陣乘法，我比較傾向于采取這種方法。

到第 5 秒時(shí)，矩陣乘法代碼就獨(dú)占了 Java 虛擬機(jī)的執(zhí)行時(shí)間：

圖 7：在第 5 秒內(nèi)運(yùn)行的所有函數(shù)，只有矩陣乘法函數(shù)是活躍的。

請(qǐng)注意，MxV.oneCell、MxV.multiplyAdd 和 MxV.multiply 之間獨(dú)占 CPU 秒數(shù)的占比分別為60%、30% 和 10%。MxV.multiplyAdd 方法僅計(jì)算乘法和加法，但它是矩陣乘法中最內(nèi)層的方法。MxV.oneCell 方法有一個(gè)調(diào)用 MxV.multiplyAdd 的循環(huán)，循環(huán)的開(kāi)銷和調(diào)用（評(píng)估條件和控制轉(zhuǎn)移）比 MxV.multiplyAdd 中的直接算術(shù)更加繁重（這種差異反映在兩者的獨(dú)占時(shí)間中，MxV.oneCell 為 0.060 CPU 秒，而 MxV.multiplyAdd 為 0.030 CPU 秒）。MxV.multiply 中的外層循環(huán)執(zhí)行頻率不夠高，以至于運(yùn)行時(shí)編譯器尚未對(duì)其進(jìn)行編譯，但該方法僅用了 0.010 CPU 秒。

矩陣乘法持續(xù)進(jìn)行到第 9 秒，此時(shí) JVM 運(yùn)行時(shí)編譯器再次啟動(dòng)，我們發(fā)現(xiàn) MxV.multiply 已頻繁執(zhí)行，占用了較多的執(zhí)行時(shí)間：

圖 8：第 9 秒內(nèi)最耗時(shí)的函數(shù)，顯示運(yùn)行時(shí)編譯器已再次啟動(dòng)。

到最后一次重復(fù)之前，矩陣乘法代碼完全占用了Java 虛擬機(jī)的執(zhí)行資源：

圖 9：矩陣相乘程序的最后一次重復(fù)，展示了代碼在整個(gè)程序執(zhí)行結(jié)束時(shí)的最終配置。

結(jié) 論

我通過(guò)對(duì)運(yùn)行時(shí)的 Java 程序使用 gprong 進(jìn)行深入分析了解到了它的易用性。利用 gprofng 的過(guò)濾功能，我可以進(jìn)行時(shí)間片段檢查實(shí)驗(yàn)，從而專注于自己感興趣的程序階段。例如，通過(guò)排除應(yīng)用程序的分配和初始化階段，并在運(yùn)行時(shí)編譯器工作時(shí)僅顯示一次程序重復(fù)，我能夠清晰地觀察到熱代碼在編譯過(guò)程中性能不斷提升的情況。

附注

①程序命令行的各個(gè)組成部分的原因解釋：

(1) numactl --cpunodebind=0 --membind=0 --

將 Java 虛擬機(jī)使用的內(nèi)存限制為一個(gè) NUMA 節(jié)點(diǎn)的內(nèi)核和內(nèi)存。將 JVM 限制在一個(gè)節(jié)點(diǎn)，可以減少程序在運(yùn)行過(guò)程中的變化，使程序在運(yùn)行中的表現(xiàn)更加穩(wěn)定。

(2) java

所使用的是適用于 aarch64 架構(gòu)的 OpenJDK 版本 jdk-17.0.4.1。

(3)-XX:+UseParallelGC

啟用并行垃圾回收器（parallel garbage collector），它在所有可用回收器中執(zhí)行的后臺(tái)工作最少。

(4)-Xms31g -Xmx31g

提供足夠的 Java 對(duì)象內(nèi)存溢出（heap space），以確保不需要進(jìn)行垃圾回收。

(5)-Xlog:gc

記錄 GC 活動(dòng)，以核實(shí)確實(shí)不需要進(jìn)行收集。（正如那句名言所說(shuō)：“信任是必須的，但核實(shí)也是必要的?！保?/p>

(6)-XX:-UsePerfData

降低 Java 虛擬機(jī)的開(kāi)銷。

②gprofng 選項(xiàng)的原因：

(1) limit 24

僅顯示占用 CPU 時(shí)間最多的 24 個(gè)函數(shù)（并按獨(dú)占 CPU 時(shí)間進(jìn)行排序）。這使我能夠了解哪些函數(shù)幾乎不花費(fèi)時(shí)間，從而集中關(guān)注那些在程序執(zhí)行期間占用最多 CPU 時(shí)間的函數(shù)。后續(xù)，我還將在某些情況下使用 limit 16，以便掌握哪些函數(shù)占用極少 CPU 時(shí)間。有時(shí) gprofng 工具本身也可能限制顯示的數(shù)量，因?yàn)椴⒉皇撬械暮瘮?shù)都能累計(jì)出大量的時(shí)間。

(2) viewmode expert

顯示所有累計(jì) CPU 時(shí)間的函數(shù)，而不僅僅是 Java 函數(shù)，還包括 JVM 本身固有的函數(shù)，使用此標(biāo)記可以讓我查看運(yùn)行時(shí)編譯器函數(shù)等。

審核編輯：劉清