本文最初由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中文网其他相关文章！
