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

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

第一步是編寫一個(gè)矩陣乘法程序。我編寫了一個(gè)完整的矩陣乘矩陣程序，因?yàn)樗⒉槐染仃嚦讼蛄扛y。主要有三個(gè)方法：一個(gè)方法計(jì)算最內(nèi)層的乘加運(yùn)算，一個(gè)方法將乘加運(yùn)算組合成結(jié)果的單個(gè)元素，一個(gè)方法迭代計(jì)算結(jié)果的每個(gè)元素。

我將計(jì)算包裝在一個(gè)簡(jiǎn)單的測(cè)試程序中，以重復(fù)計(jì)算矩陣乘積，以確保時(shí)間是可重復(fù)的。（參見附注1。）程序打印出每次矩陣乘法開始的時(shí)間（相對(duì)于Java虛擬機(jī)啟動(dòng)的時(shí)間），以及每次矩陣乘法花費(fèi)的時(shí)間。在這里，我運(yùn)行了測(cè)試程序來乘以兩個(gè)8000×8000的矩陣。測(cè)試程序重復(fù)計(jì)算11次，為了更好地突出后面的行為，在重復(fù)之間休眠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ù)花費(fèi)的時(shí)間是第一次重復(fù)時(shí)間的92%，而最后一次重復(fù)只花費(fèi)了第一次重復(fù)時(shí)間的89%。執(zhí)行時(shí)間的這些變化證實(shí)了Java程序需要一些時(shí)間來預(yù)熱。

問題是：我能否使用gprofng來查看第一次重復(fù)和最后一次重復(fù)之間發(fā)生了什么，從而導(dǎo)致性能提升？

回答這個(gè)問題的一種方法是運(yùn)行程序并讓gprofng收集運(yùn)行信息。幸運(yùn)的是，這很容易：我只需在命令行前加上一個(gè)gprofng命令來收集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)用程序造成開銷。與之前的未經(jīng)分析的運(yùn)行相比，gprofng似乎沒有造成明顯的開銷。

然后，我可以詢問gprofng整個(gè)應(yīng)用程序中時(shí)間是如何花費(fèi)的。（參見附注2。）對(duì)于整個(gè)運(yùn)行過程，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)用程序的方法（來自MxV類的那些方法）都在其中，占據(jù)了絕大部分的CPU時(shí)間，但也有一些其他的方法，包括JVM的運(yùn)行時(shí)編譯器（Compilation::Compilation），以及其他不是矩陣乘法程序一部分的函數(shù)。整個(gè)程序執(zhí)行的此顯示捕獲了分配（MxV.allocate）和初始化（MxV.initialize）代碼，我對(duì)這些代碼不太感興趣，因?yàn)樗鼈兪菧y(cè)試程序的一部分，僅在啟動(dòng)期間使用，并且與矩陣乘法幾乎沒有關(guān)系。

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

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

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

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

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

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

現(xiàn)在JVM啟動(dòng)和數(shù)組的分配和初始化已經(jīng)完成，第三秒有矩陣乘法代碼的第一次重復(fù)，如圖6所示。但請(qǐng)注意，矩陣乘法代碼正在與Java運(yùn)行時(shí)編譯器（例如，CompileBroker::invoke_compiler_on_method，在圖6中占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è)特定的例子中，矩陣乘法并沒有真正爭(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è)問題。另一方面，在運(yùn)行時(shí)編譯器中花費(fèi)的時(shí)間會(huì)產(chǎn)生更高效的方法實(shí)現(xiàn)，因此如果我計(jì)算許多矩陣乘法，那將是一項(xiàng)我愿意做的投資。

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

圖7：第五秒期間運(yùn)行的所有方法，表明只有矩陣乘法方法處于活動(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)開銷和調(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)變得很熱。

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

圖9：矩陣乘法程序的最后一次重復(fù)，顯示了代碼的最終配置

結(jié)論

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

進(jìn)一步閱讀

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

致謝

感謝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ī)的開銷。

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)闆]有那么多方法會(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)文章！