性能报告解读答案

【问题标题】：Interpreting of perf report性能报告解读
【发布时间】：2018-02-23 23:06:45
【问题描述】：

我将使用perf -g -p 收集的样本提供perf report 的输出。我不知道如何实现第一列。有很多 Java_* 调用需要超过 90% 的时间。

如何解释？

在呈现的结果中有很多条目，我的意思是：

+ 98,78%     0,00%             java       libpthread-2.26.so
+ 95,77%     0,00%             java       libjvm.so 
...

我的问题是：

为什么这样的条目多于 1 个？每个条目都是一种堆栈跟踪。单线程进程只有一个堆栈跟踪。

【问题讨论】：

这看起来像是一个累积总数，所以（几乎？）所有东西的顶级父级（几乎）获得了（几乎）所有的 CPU 时间给它自己 + 子级。相关：请参阅 Chandler Carruth 的 CppCon 2015 演讲："Tuning C++: Benchmarks, and CPUs, and Compilers! Oh My!"，了解有关使用 perf 的一些提示/技巧。其中一些应该适用于 Java（例如关于解释输出的部分，而不是关于创建以您想要的方式编译的源代码而不优化您的微基准测试或在迭代之间进行优化的部分。）

标签： perf

【解决方案1】：

您在此处引用的列表：

+ 98,78%     0,00%             java       libpthread-2.26.so
+ 95,77%     0,00%             java       libjvm.so 
...

我的问题是：

为什么这样的条目多于 1 个？每个条目都是一种堆栈跟踪。单线程进程只有一个堆栈跟踪。

不是堆栈跟踪。它是在运行期间出现在任何样本的任何堆栈跟踪中的函数列表。只有当您展开该列表的一个元素时，您才能看到包含该函数的堆栈跟踪的组合树视图。

我不确定你所说的单线程进程只有一个堆栈跟踪是什么意思。任何进程在其生命周期内都会有各种堆栈跟踪，即使它只有一个线程。例如，在它开始的那一刻，堆栈跟踪只是main()，一旦main() 调用一个函数，堆栈跟踪就会更改为包含该函数等等。

现在在函数列表中，第一列显示总开销，包括所有子项（即，包括此函数调用的函数）。由于几乎所有有趣的工作都发生在一个调用链中，它们都共享相同的最外层函数，因此顶层是一种无用的列表，其中许多函数以 >90% 的开销显示。

第二列是“自己的”开销，表示在该方法中实际花费的时间¹，不是任何子方法。对于所有顶级方法，这接近于零，因此真正的工作发生在由这些方法调用的某个方法中，而不是在这些方法本身中。

您在顶部展开的树状视图确实告诉您需要了解的内容：~94% 的时间都花在radek.queue.wlQueue.writeBytes() 内部/下方，而那个人大部分时间都花在String.intern() .所以这里的瓶颈是所有的String.intern()调用，可能是因为字符串表太小，或者只是因为String.intern()只是generally sucks用于去重。我的一般规则是使用 Guava 的 Interner<String>，除非您特别需要文字字符串与实习字符串共享相同字符串池的属性（即 "foo" == new String("foo").intern()）。

¹ 我在这里松散地说“时间量” - 它实际上是您指定给 perf record 的任何事件的总样本的一小部分 - 但默认情况下应该大约是 CPU 时间。

【讨论】：

感谢您的精彩回答！ :) 为什么这样的输出中有任何条目？因为程序是多线程的？
@J.Doe - 不，它与多线程无关：只是这个列表显示了出现在任何函数的堆栈跟踪中的所有函数，并且有很多这样的函数，出现这么多行。它们加起来超过 100%，因为每个都包含在调用函数中的所有时间。因此，如果你有一个函数 A 调用了函数 B，而 B 又调用了 C，并且每个函数分别占用了总时间的 1%、1% 和 98%，那么你最终会得到一个类似的列表：100% A, 99% B, 98% C。
我试图添加到我的答案中以使其更清晰 - 您在图片底部看到的列表不是堆栈跟踪 - 是一个简单的函数列表，按“总开销”排序（第一列）。