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

1

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

2

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

3

對最終結(jié)果的每個元素進行迭代計算

我將矩陣乘法的計算過程放入一個簡單的框架中，以便能夠重復(fù)地計算矩陣乘積，從而確保測量是可多次重復(fù)的（見附注 1）。該程序會在每次矩陣相乘開始時（相對于 Java 虛擬機的啟動時間）打印出信息，包括每次矩陣相乘所需的時間。我還運行了一個測試，將兩個 8000x8000 的矩陣相乘，該框架會重復(fù)計算 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：矩陣乘法程序的運行情況

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

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

為了回答這個問題，我們可以運行程序并讓 gprofng 收集有關(guā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 下運行矩陣乘法程序

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

結(jié) 論

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

附注

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

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

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

(2) java

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

(3)-XX:+UseParallelGC

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

(4)-Xms31g -Xmx31g

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

(5)-Xlog:gc

記錄 GC 活動，以核實確實不需要進行收集。（正如那句名言所說：“信任是必須的，但核實也是必要的?！保?/p>

(6)-XX:-UsePerfData

降低 Java 虛擬機的開銷。

②gprofng 選項的原因：

(1) limit 24

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

(2) viewmode expert

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

審核編輯：劉清