为什么Java CPU分析器(使用visualvm)会显示一个空方法有如此多的命中次数？

Question

这是我认为在其他环境中使用过的其他分析工具也存在的情况，但这种情况在这里尤其明显。 我正在对运行约12分钟的任务进行CPU分析，并且显示几乎一半的时间都花在了一个什么也不做的方法上：它的主体为空。 是什么原因导致了这种情况？ 我不相信该方法被调用了荒谬的次数，肯定不能解释一半的执行时间。

值得一提的是，涉及到的方法称为startContent()，用于通知解析事件。 该事件通过一系列过滤器（可能有十几个）传递下去，并且每个过滤器上的startContent()方法几乎什么也不做，只是在链中调用下一个过滤器上的startContent()。

这是纯Java代码，我在Mac上运行它。

附上CPU采样器输出的屏幕截图： 以下是显示调用堆栈的示例： （由于度假而延迟后）这里有几张图片显示了分析器的输出。 这些数字更符合我期望的配置文件外观。 分析器输出似乎完全有意义，而采样器输出是虚假的。 正如一些人猜测的那样，涉及到的工作是运行Saxon XML模式验证器（对9Gb输入文件）。 配置文件显示大约一半的时间用于根据简单类型验证元素内容（发生在endElement处理期间），另一半时间用于测试唯一性的关键约束； 两个分析器视图突出显示了该任务这两个方面中涉及的活动。

由于数据来自客户端，因此无法提供数据。

- Michael Kay

---

你能否改为采样调用栈，这样空方法中的开销就会小得多？ - Thorbjørn Ravn Andersen

这是包含时间还是排除时间？程序是否花费任何阻塞时间（IO、睡眠、锁等待等）？作为一位老手，我不敢告诉您有关分析的事情，但您有足够的声望可以查看此内容，这可能会让您更透彻地了解该主题。 - Mike Dunlavey

@Brandon - 这是一个高度多态的方法，但分析器输出清楚地区分了该方法的不同覆盖。 - Michael Kay

@Mike Dunlavey - 这是一个包容性时间，但由于这是一个不调用任何其他方法的方法，所以实际上没有任何区别。该过程确实具有一些I/O时间，但远远不到这个（所谓的）热点。我认为没有任何同步阻塞。 - Michael Kay

还有一件事——屏幕截图显示您没有使用分析器，而是采样器。因此，答案部分中提到的所有有关仪器开销的内容都是无效的。 - Tomas Hurka

Answer 1

我从未使用过VisualVM，但我猜测问题可能是由于这种空方法上的检测开销所致。JProfiler文档中有相关段落（我广泛使用），请看这里： 如果方法调用记录类型设置为动态插装，则对所有受监视类的方法进行插装。这会产生一些开销，对于执行时间非常短的方法而言，这种开销很大。如果这些方法被频繁地调用，那么这些方法的测量时间将远高于实际。此外，由于插装的原因，热点编译器可能无法对其进行优化。在极端情况下，这些方法成为支配热点，尽管在未插装运行时并非如此。一个例子就是XML解析器的方法，它读取下一个字符。这个方法返回得非常快，但在短时间内可能会被调用数百万次。

基本上，分析器添加了它自己的“时间长度检测代码”，但在空方法中，分析器将花费所有时间来执行“检测代码”，而不是让方法真正运行。

我建议，如果可能的话，请告诉VisualVM停止对该线程进行插装，如果它支持这样的过滤。

- durron597

---

这都是一个线程，因此不对该线程进行仪器测量将是相当无意义的。我怀疑你的想法是正确的，即时间实际上被用于执行仪器代码，但这引出了一个问题，为什么这种方法会显示这种效果而其他方法却没有。然而，T R Anderson建议采样调用堆栈似乎很有帮助，这似乎给出了合理的结果。 - Michael Kay

采样调用堆栈是很好的；在JProfiler中，您可以按方法而不是线程删除仪器。不知道在VisualVM中是否可以。但是，如果无法过滤方法，则调用堆栈采样可能是您最好的选择。 - durron597

Answer 2

通常认为，使用性能分析器比其他任何方法（特别是随机暂停）更好地发现性能问题。

这种假设只是普遍的观点，没有理论或实践依据。有许多关于分析器的学术同行评审论文，但我读过的没有一篇论文涉及到这个观点，更不用说证实它了。这是学术界的一个盲点，不是很大，但确实存在。

现在回答您的问题——在调用堆栈截图中，显示的是“热路线”，占线程 CPU 时间的大约 60%。假设您感兴趣的是名称中带有“saxon”的代码，则是以下代码：

net.sf.saxon.event.ReceivingContentHandler.startElement
net.sf.saxon.event.ProxyReceiver.startContent
net.sf.saxon.event.ProxyReceiver.startContent
net.sf.saxon.event.StartTagBuffer.startContent
net.sf.saxon.event.ProxyReceiver.startContent
com.saxonica.ee.validate.ValidationStack.startContent
com.saxonica.ee.validate.AttributeValidator.startContent
net.sf.saxon.event.TeeOutputter.startContent
net.sf.saxon.event.ProxyReceiver.startContent
net.sf.saxon.event.ProxyReceiver.startContent
net.sf.saxon.event.Sink.startContent

首先，我认为这似乎必须进行I/O操作，或者至少在等待某个其他进程提供内容。如果是这样的话，你应该看墙钟时间，而不是CPU时间。

其次，在任何一个调用下面函数的地方可能存在问题。如果任何这样的调用不是真正必要的，可以跳过或者减少执行次数，将会显著减少时间。我的怀疑集中在StartTagBuffer和validate上，但你最清楚。

还有其他一些点可以指出，但这些是主要的。

在你编辑问题后添加。 我倾向于假设你正在寻找优化代码的方法，而不仅仅是为了得到数字。

它仍然看起来只有CPU时间，没有I/O在热路径上。也许在你的情况下这没问题，但这意味着，在12分钟的墙钟时间中，11分钟可能花费在I/O等待上，1分钟在CPU上。如果是这样的话，你可以在CPU部分削减30秒的时间，但只能缩短30秒的时间。这就是为什么我更喜欢按墙钟时间采样，以便我有整体的视角。

仅仅看热点路径并不能得到真正的图片。 例如，如果热点路径显示函数F在其中40%的时间上是热点路径，那只意味着F的成本至少为40%。它可能会更多，因为它可能在其他不太热门的路径上。因此，您可能有一个很好的机会大大加快速度，但它在分析器选择向您显示的特定路径中没有得到充分的关注，因此您没有给予它太多注意。 实际上，一个耗时较长的程序可能根本不会显示出来，因为在任何特定的热点路径上总会有其他一些更大的东西，比如new，或者因为它有多个名称，比如模板化集合类构造函数。

它不会向您显示任何行分辨率信息。 如果您想检查一个被认为成本高昂的例程的原因，您必须查看其中的行。当查看一个例程时，人们往往会说“它只是在做它应该做的事情。”但是，如果您正在查看一个具体的代价高昂的代码行（通常是方法调用），您可以问“这个调用真的有必要吗？也许我已经拥有了这些信息。”这样更具体地建议您可以修复什么。

它实际上能展示给你一些原始的堆栈样本吗？在我的经验中，这比任何摘要更具信息量，例如热路径，这是分析器可以呈现的。要做的事情是检查样本并充分理解程序在那个时间点正在做什么以及原因。然后再重复几个样本。您将看到不需要执行的操作，可以修复以获得实质性的加速。（除非代码已经最优化，否则会很好知道。）关键是，您正在寻找问题，而不是测量。 从统计上讲，它非常粗略，但足够好，没有问题会逃脱。

- Mike Dunlavey

Answer 3

我的猜测是方法Sink.startContent被调用了很多次。

您的截图显示了Sampling选项卡，如果用户在足够长的时间内使用它，通常会得到真实的时间。如果改用Profiler选项卡，则还可以获得调用计数。（您也将获得更少的真实时间和非常缓慢的程序，但只需要几秒钟就可以获得有关调用计数的良好想法）。

很难预测HotSpot执行的优化，特别是内联，而采样分析器只能将内联方法的时间归因于调用站点。我怀疑saxon中的某些调用代码由于某种原因被归因于您的空回调函数。在这种情况下，您只是遭受了XML的成本，切换到其他解析器可能是唯一的选择。

- Chris

Answer 4

我从这个帖子中获得了很多有用的信息和指导，非常感谢。然而，我认为核心问题还没有得到回答：为什么在 VisualVM 中进行 CPU 抽样时，在一个什么也不做、调用频率并不比其他方法高的方法中，会出现荒谬的高命中数？

以后的调查中，我将依靠分析器而不是采样器，现在我已经对它们的区别有了一些了解。

从分析器中，我并没有真正获得关于这个特定任务的很多新信息，因为它基本上证实了我猜测的内容；但这本身就是有用的。它告诉我，没有什么灵丹妙药可以加速这个特定的过程，但它已经限制了通过一些严重的重新设计可能实现的范围，例如一个可能有一些前途的未来增强功能是为模式中的每个用户定义的简单类型生成字节码验证器。

- Michael Kay

---

我认为这里的问题在于我们无法看到分析器所做的字节码转换后真正的方法体是什么样子 - 但可以猜测它们不再是空的。我的直觉是你正在看到一个或多个Hotspot JIT工件（方法内联）、CPU缓存未命中、内存页面未对齐，这些可能会在此后的运行中在此主机或其他主机上显示或不显示。由于它是Netbeans分析器的独立版本，如果在Netbeans内部运行，您可能会获得更好的结果？ - Thorbjørn Ravn Andersen

调用计数并不等同于时间成本，关于分析器，当你说“它告诉我没有什么神奇的方法可以加速这个特定的过程”时，你大致上说的是我在这个网站上从许多分析器用户那里听到的话 - 这就是我的问题所在。分析器隐藏了加速，而且有一个含义：如果分析器没有发现太多问题，那么代码必须接近最优。自然而然，人们会被骗。好吧，我从来没有见过任何规模较大的代码不能被大幅压缩的例子。[示例]（https://dev59.com/mnNA5IYBdhLWcg3whuV_#927773）[*730x*]（http://scicomp.stackexchange.com/a/1870/1262） - Mike Dunlavey