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

Question

这是我以前在其他环境中使用其他分析工具时所看到的,但在这种情况下它尤其引人注目.

我正在运行一个运行大约12分钟的任务的CPU配置文件,并且它显示了几乎一半的时间花费在一个字面上什么都不做的方法:它有一个空体.是什么导致这个？我不相信这种方法被称为荒谬的次数,当然不会占用执行时间的一半.

对于它的价值,所讨论的方法称为startContent(),它用于通知解析事件.事件沿着一系列过滤器传递(可能是十几个),并且每个过滤器上的startContent()方法除了在链中的下一个过滤器上调用startContent()之外几乎没有任何作用.

这是纯Java代码,我在Mac上运行它.

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

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

(因休假而延误)以下是一些显示探查器输出的图片.这些数字远远超出我期望的配置文件的样子.探查器输出似乎完全有意义,而采样器输出是虚假的.

正如你们中的一些人已经猜到的那样,有问题的工作是Saxon XML模式验证器的运行(在9Gb输入文件上).该配置文件显示大约一半的时间用于验证元素内容与简单类型(在endElement处理期间发生),大约一半用于测试关键约束的唯一性; 两个探查器视图显示了该任务的这两个方面所涉及的活动.

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

Answer 1

我没有使用VisualVM,但我怀疑问题可能是因为这种空方法的检测开销.这是JProfiler文档中的相关段落(我已广泛使用):

如果方法调用记录类型设置为动态检测,则会检测所有已分析类的方法.这会产生一些开销,这对于执行时间非常短的方法很重要.如果非常频繁地调用这些方法,那么这些方法的测量时间将会很高.此外,由于仪器,可能会阻止热点编译器优化它们.在极端情况下,这种方法成为主要的热点,尽管对于未经检测的运行不是这样.一个例子是读取下一个字符的XML解析器的方法.此方法返回非常快,但可以在短时间内调用数百万次.

基本上,分析器基本上添加了它自己的"时间长度检测代码",但是在一个空方法中,分析器将花费所有时间来做这些而不是实际允许该方法运行.

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