本文最初由Ampere Computing發布
最近看到一篇關於gprofng（一款新的GNU性能分析工具）的博文。該博文中使用了一個用C語言編寫的矩陣向量乘法程序作為示例。我是一名Java™程序員，而使用為靜態編譯的C程序設計的工具來分析Java應用程序往往很困難，因為Java程序是在運行時編譯的。在這篇博文中，我將展示gprofng易於使用且對於深入研究Java應用程序的動態行為非常有用。
第一步是編寫一個矩陣乘法程序。我編寫了一個完整的矩陣乘矩陣程序，因為它並不比矩陣乘向量更難。主要有三個方法：一個方法計算最內層的乘加運算，一個方法將乘加運算組合成結果的單個元素，一個方法迭代計算結果的每個元素。
我將計算包裝在一個簡單的測試程序中，以重複計算矩陣乘積，以確保時間是可重複的。 （參見附註1。）程序打印出每次矩陣乘法開始的時間（相對於Java虛擬機啟動的時間），以及每次矩陣乘法花費的時間。在這裡，我運行了測試程序來乘以兩個8000×8000的矩陣。測試程序重複計算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：運行矩陣乘法程序
請注意，第二次重複花費的時間是第一次重複時間的92%，而最後一次重複只花費了第一次重複時間的89%。執行時間的這些變化證實了Java程序需要一些時間來預熱。
問題是：我能否使用gprofng來查看第一次重複和最後一次重複之間發生了什麼，從而導致性能提升？
回答這個問題的一種方法是運行程序並讓gprofng收集運行信息。幸運的是，這很容易：我只需在命令行前加上一個gprofng命令來收集gprofng所謂的“實驗”信息：
$ 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下運行矩陣乘法程序
首先要注意的是，與任何性能分析工具一樣，收集性能分析信息會對應用程序造成開銷。與之前的未經分析的運行相比，gprofng似乎沒有造成明顯的開銷。
然後，我可以詢問gprofng整個應用程序中時間是如何花費的。 （參見附註2。）對於整個運行過程，gprofng表示最熱的24個方法是：
$ gprofng display text test.1.er -viewmode expert -limit 24 -functions
圖3：gprofng顯示最熱的24個方法
上面顯示的函數視圖給出了每個方法的獨占和包含CPU時間，以秒和總CPU時間的百分比表示。命名的函數是由gprofng生成的偽函數，具有各種指標的總值。在本例中，我看到整個應用程序的總CPU時間為1.201秒。
應用程序的方法（來自MxV類的那些方法）都在其中，佔據了絕大部分的CPU時間，但也有一些其他的方法，包括JVM的運行時編譯器（Compilation::Compilation），以及其他不是矩陣乘法程序一部分的函數。整個程序執行的此顯示捕獲了分配（MxV.allocate）和初始化（MxV.initialize）代碼，我對這些代碼不太感興趣，因為它們是測試程序的一部分，僅在啟動期間使用，並且與矩陣乘法幾乎沒有關係。
我可以使用gprofng來關注我感興趣的應用程序部分。 gprofng的一個很棒的功能是，在收集實驗後，我可以將過濾器應用於收集到的數據。例如，查看特定時間間隔內發生的情況，或者在特定方法位於調用堆棧時發生的情況。為了演示目的並使過濾更容易，我添加了對Thread.sleep(ms)的策略性調用，以便更容易編寫基於程序階段（由一秒鐘間隔分開）的過濾器。這就是為什麼上面圖1中的程序輸出每個重複之間間隔大約一秒鐘，即使每個矩陣乘法只花費大約0.1秒的原因。
gprofng是可腳本化的，所以我編寫了一個腳本來從gprofng實驗中提取單個秒。第一秒全部是關於Java虛擬機啟動的。
圖4：過濾第一秒中最熱的方法。在此秒內，矩陣乘法已被人工延遲，以便我展示JVM啟動
我可以看到運行時編譯器正在啟動（例如，Compilation::compile_java_method，佔CPU時間的16%），即使應用程序的任何方法都尚未開始運行。 （矩陣乘法調用被我插入的sleep調用延遲了。）
第一秒之後是一秒鐘，在此期間分配和初始化方法與各種JVM方法一起運行，但矩陣乘法代碼尚未開始。
圖5：第二秒中最熱的方法。矩陣分配和初始化與JVM啟動競爭
現在JVM啟動和數組的分配和初始化已經完成，第三秒有矩陣乘法代碼的第一次重複，如圖6所示。但請注意，矩陣乘法代碼正在與Java運行時編譯器（例如，CompileBroker::invoke_compiler_on_method，在圖6中佔8%）競爭機器資源，該編譯器正在編譯方法，因為矩陣乘法代碼被發現很熱。
即便如此，矩陣乘法代碼（例如，MxV.main方法中的“包含”時間，91%）仍然獲得了大部分CPU時間。包含時間表明矩陣乘法（例如，MxV.multiply）花費了0.100 CPU秒，這與圖2中應用程序報告的實際時間一致。 （收集和報告實際時間需要一些實際時間，這在gprofng計入MxV.multiply的CPU時間之外。）
圖6：第三秒中最熱的方法，表明運行時編譯器正在與矩陣乘法方法競爭
在這個特定的例子中，矩陣乘法並沒有真正爭奪CPU時間，因為測試在一個多處理器系統上運行，該系統有大量的空閒週期，並且運行時編譯器作為單獨的線程運行。在更受限制的情況下，例如在負載很重的共享機器上，運行時編譯器花費的8%的時間可能是一個問題。另一方面，在運行時編譯器中花費的時間會產生更高效的方法實現，因此如果我計算許多矩陣乘法，那將是一項我願意做的投資。
到第五秒時，矩陣乘法代碼擁有了Java虛擬機。
圖7：第五秒期間運行的所有方法，表明只有矩陣乘法方法處於活動狀態
請注意MxV.oneCell、MxV.multiplyAdd和MxV.multiply之間在獨占CPU秒方面的60%/30%/10%的分配。 MxV.multiplyAdd方法只計算乘法和加法：但它是矩陣乘法中最內層的方法。 MxV.oneCell有一個循環調用MxV.multiplyAdd。我可以看到循環開銷和調用（評估條件和控制轉移）比MxV.multiplyAdd中的直接算術運算相對更多工作。 （MxV.oneCell的獨占時間為0.060 CPU秒，而MxV.multiplyAdd為0.030 CPU秒，這反映了這種差異。）MxV.multiply中的外循環執行頻率不夠高，以至於運行時編譯器尚未編譯它，但該方法正在使用0.010 CPU秒。
矩陣乘法繼續進行到第九秒，這時JVM運行時編譯器再次啟動，發現MxV.multiply已經變得很熱。
在最後一次重複中，矩陣乘法代碼充分利用了Java虛擬機。
圖9：矩陣乘法程序的最後一次重複，顯示了代碼的最終配置
我已經展示了通過使用gprofng進行性能分析來輕鬆深入了解Java應用程序運行時間的簡便性。使用gprofng的過濾功能按時間片檢查實驗，使我能夠檢查感興趣的程序階段。例如，排除應用程序的分配和初始化階段，並且只顯示運行時編譯器正在運行其魔術時程序的一次重複，這使我能夠突出顯示隨著熱代碼被逐步編譯而提高的性能。
對於想要了解gprofng的讀者，這裡有一篇博文，其中包含關於gprofng的介紹性視頻，包括如何在Oracle Linux上安裝它的說明。
感謝Ruud van der Pas、Kurt Goebel和Vladimir Mezentsev的建議和技術支持，並感謝Elena Zannoni、David Banman、Craig Hardy和Dave Neary鼓勵我撰寫這篇博文。
以上是Java虛擬機整天做什麼？的詳細內容。更多資訊請關注PHP中文網其他相關文章！
