本文最初由Ampere Computing發(fā)布

最近看到一篇關(guān)於gprofng（一款新的GNU性能分析工具）的博文。該博文中使用了一個(gè)用C語(yǔ)言編寫的矩陣向量乘法程序作為示例。我是一名Java?程序員，而使用為靜態(tài)編譯的C程序設(shè)計(jì)的工具來(lái)分析Java應(yīng)用程序往往很困難，因?yàn)镴ava程序是在運(yùn)行時(shí)編譯的。在這篇博文中，我將展示gprofng易於使用且對(duì)於深入研究Java應(yīng)用程序的動(dòng)態(tài)行為非常有用。

第一步是編寫一個(gè)矩陣乘法程序。我編寫了一個(gè)完整的矩陣乘矩陣程序，因?yàn)樗鼇K不比矩陣乘向量更難。主要有三個(gè)方法：一個(gè)方法計(jì)算最內(nèi)層的乘加運(yùn)算，一個(gè)方法將乘加運(yùn)算組合成結(jié)果的單個(gè)元素，一個(gè)方法迭代計(jì)算結(jié)果的每個(gè)元素。

我將計(jì)算包裝在一個(gè)簡(jiǎn)單的測(cè)試程序中，以重複計(jì)算矩陣乘積，以確保時(shí)間是可重複的。 （參見(jiàn)附註1。）程序打印出每次矩陣乘法開(kāi)始的時(shí)間（相對(duì)於Java虛擬機(jī)啟動(dòng)的時(shí)間），以及每次矩陣乘法花費(fèi)的時(shí)間。在這裡，我運(yùn)行了測(cè)試程序來(lái)乘以兩個(gè)8000×8000的矩陣。測(cè)試程序重複計(jì)算11次，為了更好地突出後面的行為，在重複之間休眠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)行矩陣乘法程序

請(qǐng)注意，第二次重複花費(fèi)的時(shí)間是第一次重複時(shí)間的92%，而最後一次重複只花費(fèi)了第一次重複時(shí)間的89%。執(zhí)行時(shí)間的這些變化證實(shí)了Java程序需要一些時(shí)間來(lái)預(yù)熱。

問(wèn)題是：我能否使用gprofng來(lái)查看第一次重複和最後一次重複之間發(fā)生了什麼，從而導(dǎo)致性能提升？

回答這個(gè)問(wèn)題的一種方法是運(yùn)行程序並讓gprofng收集運(yùn)行信息。幸運(yùn)的是，這很容易：我只需在命令行前加上一個(gè)gprofng命令來(lái)收集gprofng所謂的“實(shí)驗(yàn)”信息：

$ 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)行矩陣乘法程序

首先要注意的是，與任何性能分析工具一樣，收集性能分析信息會(huì)對(duì)應(yīng)用程序造成開(kāi)銷。與之前的未經(jīng)分析的運(yùn)行相比，gprofng似乎沒(méi)有造成明顯的開(kāi)銷。

然後，我可以詢問(wèn)gprofng整個(gè)應(yīng)用程序中時(shí)間是如何花費(fèi)的。 （參見(jiàn)附註2。）對(duì)於整個(gè)運(yùn)行過(guò)程，gprofng表示最熱的24個(gè)方法是：

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

圖3：gprofng顯示最熱的24個(gè)方法

上面顯示的函數(shù)視圖給出了每個(gè)方法的獨(dú)占和包含CPU時(shí)間，以秒和總CPU時(shí)間的百分比表示。命名的函數(shù)是由gprofng生成的偽函數(shù)，具有各種指標(biāo)的總值。在本例中，我看到整個(gè)應(yīng)用程序的總CPU時(shí)間為1.201秒。

應(yīng)用程序的方法（來(lái)自MxV類的那些方法）都在其中，佔(zhàn)據(jù)了絕大部分的CPU時(shí)間，但也有一些其他的方法，包括JVM的運(yùn)行時(shí)編譯器（Compilation::Compilation），以及其他不是矩陣乘法程序一部分的函數(shù)。整個(gè)程序執(zhí)行的此顯示捕獲了分配（MxV.allocate）和初始化（MxV.initialize）代碼，我對(duì)這些代碼不太感興趣，因?yàn)樗鼈兪菧y(cè)試程序的一部分，僅在啟動(dòng)期間使用，並且與矩陣乘法幾乎沒(méi)有關(guān)係。

我可以使用gprofng來(lái)關(guān)注我感興趣的應(yīng)用程序部分。 gprofng的一個(gè)很棒的功能是，在收集實(shí)驗(yàn)後，我可以將過(guò)濾器應(yīng)用於收集到的數(shù)據(jù)。例如，查看特定時(shí)間間隔內(nèi)發(fā)生的情況，或者在特定方法位於調(diào)用堆棧時(shí)發(fā)生的情況。為了演示目的並使過(guò)濾更容易，我添加了對(duì)Thread.sleep(ms)的策略性調(diào)用，以便更容易編寫基於程序階段（由一秒鐘間隔分開(kāi)）的過(guò)濾器。這就是為什麼上面圖1中的程序輸出每個(gè)重複之間間隔大約一秒鐘，即使每個(gè)矩陣乘法只花費(fèi)大約0.1秒的原因。

gprofng是可腳本化的，所以我編寫了一個(gè)腳本來(lái)從gprofng實(shí)驗(yàn)中提取單個(gè)秒。第一秒全部是關(guān)於Java虛擬機(jī)啟動(dòng)的。

圖4：過(guò)濾第一秒中最熱的方法。在此秒內(nèi)，矩陣乘法已被人工延遲，以便我展示JVM啟動(dòng)

我可以看到運(yùn)行時(shí)編譯器正在啟動(dòng)（例如，Compilation::compile_java_method，佔(zhàn)CPU時(shí)間的16%），即使應(yīng)用程序的任何方法都尚未開(kāi)始運(yùn)行。 （矩陣乘法調(diào)用被我插入的sleep調(diào)用延遲了。）

第一秒之後是一秒鐘，在此期間分配和初始化方法與各種JVM方法一起運(yùn)行，但矩陣乘法代碼尚未開(kāi)始。

圖5：第二秒中最熱的方法。矩陣分配和初始化與JVM啟動(dòng)競(jìng)爭(zhēng)

現(xiàn)在JVM啟動(dòng)和數(shù)組的分配和初始化已經(jīng)完成，第三秒有矩陣乘法代碼的第一次重複，如圖6所示。但請(qǐng)注意，矩陣乘法代碼正在與Java運(yùn)行時(shí)編譯器（例如，CompileBroker::invoke_compiler_on_method，在圖6中佔(zhàn)8%）競(jìng)爭(zhēng)機(jī)器資源，該編譯器正在編譯方法，因?yàn)榫仃嚦朔ùa被發(fā)現(xiàn)很熱。

即便如此，矩陣乘法代碼（例如，MxV.main方法中的“包含”時(shí)間，91%）仍然獲得了大部分CPU時(shí)間。包含時(shí)間表明矩陣乘法（例如，MxV.multiply）花費(fèi)了0.100 CPU秒，這與圖2中應(yīng)用程序報(bào)告的實(shí)際時(shí)間一致。 （收集和報(bào)告實(shí)際時(shí)間需要一些實(shí)際時(shí)間，這在gprofng計(jì)入MxV.multiply的CPU時(shí)間之外。）

圖6：第三秒中最熱的方法，表明運(yùn)行時(shí)編譯器正在與矩陣乘法方法競(jìng)爭(zhēng)

在這個(gè)特定的例子中，矩陣乘法並沒(méi)有真正爭(zhēng)奪CPU時(shí)間，因?yàn)闇y(cè)試在一個(gè)多處理器系統(tǒng)上運(yùn)行，該系統(tǒng)有大量的空閒週期，並且運(yùn)行時(shí)編譯器作為單獨(dú)的線程運(yùn)行。在更受限制的情況下，例如在負(fù)載很重的共享機(jī)器上，運(yùn)行時(shí)編譯器花費(fèi)的8%的時(shí)間可能是一個(gè)問(wèn)題。另一方面，在運(yùn)行時(shí)編譯器中花費(fèi)的時(shí)間會(huì)產(chǎn)生更高效的方法實(shí)現(xiàn)，因此如果我計(jì)算許多矩陣乘法，那將是一項(xiàng)我願(yuàn)意做的投資。

到第五秒時(shí)，矩陣乘法代碼擁有了Java虛擬機(jī)。

圖7：第五秒期間運(yùn)行的所有方法，表明只有矩陣乘法方法處?kù)痘顒?dòng)狀態(tài)

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

矩陣乘法繼續(xù)進(jìn)行到第九秒，這時(shí)JVM運(yùn)行時(shí)編譯器再次啟動(dòng)，發(fā)現(xiàn)MxV.multiply已經(jīng)變得很熱。

在最後一次重複中，矩陣乘法代碼充分利用了Java虛擬機(jī)。

圖9：矩陣乘法程序的最後一次重複，顯示了代碼的最終配置

結(jié)論

我已經(jīng)展示了通過(guò)使用gprofng進(jìn)行性能分析來(lái)輕鬆深入了解Java應(yīng)用程序運(yùn)行時(shí)間的簡(jiǎn)便性。使用gprofng的過(guò)濾功能按時(shí)間片檢查實(shí)驗(yàn)，使我能夠檢查感興趣的程序階段。例如，排除應(yīng)用程序的分配和初始化階段，並且只顯示運(yùn)行時(shí)編譯器正在運(yùn)行其魔術(shù)時(shí)程序的一次重複，這使我能夠突出顯示隨著熱代碼被逐步編譯而提高的性能。

進(jìn)一步閱讀

對(duì)於想要了解gprofng的讀者，這裡有一篇博文，其中包含關(guān)於gprofng的介紹性視頻，包括如何在Oracle Linux上安裝它的說(shuō)明。

致謝

感謝Ruud van der Pas、Kurt Goebel和Vladimir Mezentsev的建議和技術(shù)支持，並感謝Elena Zannoni、David Banman、Craig Hardy和Dave Neary鼓勵(lì)我撰寫這篇博文。

附註

1. 程序命令行組件的動(dòng)機(jī)是：

• numactl --cpunodebind=0 --membind=0 --。將Java虛擬機(jī)使用的內(nèi)存限制在一個(gè)NUMA節(jié)點(diǎn)的核心和內(nèi)存中。將JVM限制在一個(gè)節(jié)點(diǎn)上可以減少程序的運(yùn)行間差異。
• java。我使用的是aarch64的jdk-17.0.4.1的OpenJDK版本。
• -XX: UseParallelGC。啟用並行垃圾收集器，因?yàn)樗诳捎檬占髦羞M(jìn)行的後臺(tái)工作最少。
• -Xms31g -Xmx31g。提供足夠的Java對(duì)象堆空間，永遠(yuǎn)不需要垃圾收集。
• -Xlog:gc。記錄GC活動(dòng)以驗(yàn)證確實(shí)不需要收集。 （“信任但要驗(yàn)證?！保?/li>
• -XX:-UsePerfData。降低Java虛擬機(jī)的開(kāi)銷。

2. gprofng選項(xiàng)的解釋是：

• -limit 24。僅顯示前24個(gè)方法（此處按獨(dú)占CPU時(shí)間排序）。我可以看到，顯示24個(gè)方法可以讓我很好地了解幾乎不使用時(shí)間的那些方法。稍後，我將在某些地方使用limit 16，其中16個(gè)方法可以降低到貢獻(xiàn)微不足道的CPU時(shí)間的那些方法。在某些示例中，gprofng本身會(huì)限制顯示，因?yàn)闆](méi)有那麼多方法會(huì)累積時(shí)間。
• -viewmode expert。顯示所有累積CPU時(shí)間的那些方法，而不僅僅是Java方法，包括JVM本身的那些方法。使用此標(biāo)誌可以讓我看到運(yùn)行時(shí)編譯器方法等。

以上是Java虛擬機(jī)整天做什麼？的詳細(xì)內(nèi)容。更多資訊請(qǐng)關(guān)注PHP中文網(wǎng)其他相關(guān)文章！