java - 为什么 Java CPU 配置文件(使用 visualvm)在一个什么都不做的方法上显示如此多的命中？

Question

这是我以前在其他环境中使用其他分析工具时见过的情况，但在这种情况下尤其引人注目。

我正在获取一个运行了大约 12 分钟的任务的 CPU 配置文件，它显示几乎一半的时间花费在一个实际上什么都不做的方法上:它有一个空体。什么会导致这个？我不认为该方法被调用的次数多得离谱，当然不会占执行时间的一半。

就其值(value)而言，所讨论的方法称为 startContent()，它用于通知解析事件。事件沿着过滤器链(可能有十几个)传递，每个过滤器上的 startContent() 方法除了调用链中下一个过滤器上的 startContent() 之外几乎什么都不做。

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

附件是 CPU 采样器输出的屏幕截图:

这是显示调用堆栈的示例:

(由于休假而延迟)这里有几张图片显示了分析器的输出。这些数字更符合我对个人资料的期望。探查器输出似乎完全有意义，而采样器输出是虚假的。

有些人可能已经猜到，所讨论的工作是运行 Saxon XML 模式 validator (在 9Gb 输入文件上)。该配置文件显示大约一半时间用于根据简单类型验证元素内容(发生在 endElement 处理期间)，大约一半时间用于测试关键约束的唯一性；两个分析器 View 突出显示了任务的这两个方面所涉及的 Activity 。

我无法提供来自客户的数据。

Answer 1

我没有使用过 VisualVM，但我怀疑这个问题可能是因为这种空方法的检测开销。 Here's the relevant passage in JProfiler's documentation (which I have used extensively):

If the method call recording type is set to Dynamic instrumentation, all methods of profiled classes are instrumented. This creates some overhead which is significant for methods that have very short execution times. If such methods are called very frequently, the measured time of those method will be far to high. Also, due to the instrumentation, the hot spot compiler might be prevented from optimizing them. In extreme cases, such methods become the dominant hot spots although this is not true for an uninstrumented run. An example is the method of an XML parser that reads the next character. This method returns very quickly, but may be invoked millions of times in a short time span.

基本上，探查器会添加它自己的“时间长度检测代码”，本质上，但是在一个空方法中，探查器将花费所有时间做那个而不是实际允许该方法运行。

如果可能的话，我建议告诉 VisualVM 停止检测该线程，如果它支持这样的过滤的话。