异步事件探查器显示错误的堆栈跟踪

问题描述

我正在尝试使用async profiler v.1.8.1对应用程序进行性能分析。

JVM是openjdk版本“ 15-ea”（2020年9月15日），但openjdk 14.0.1也是如此。

异步分析器运行时带有以下标志：-d 60 -t -i 10000 -o svg

显示非常奇怪的结果。

我们可以看到，硬件线程大部分时间都没有花费在java.lang.Thread :: run上，而是花费在一些奇怪的地方。怎么解释呢？我看到一个可能的解释，即异步事件探查器无法正确遍历堆栈跟踪，并将这些堆栈跟踪的一部分放在错误的位置。还有其他解释吗？怎么解决？

解决方法

我假设您想知道为什么配置文件中clock_gettime下没有Java框架。

如您所见，堆栈以[unknown_Java]帧结尾。这意味着该线程确实在运行一些Java代码，但是async-profiler无法获取Java堆栈跟踪，因为JVM无法找到顶部的Java框架。

发生这种情况是因为System.nanoTime()和System.currentTimeMillis()是JVM内在函数。它们被JIT编译为对相应C函数的直接调用，而无需将线程从in_java切换到in_native状态。这意味着，JVM在调用nanoTime或currentTimeMillis时不会保存指向最后一个Java帧的指针，因此在异步堆栈遍历期间发现最后一个Java帧时会遇到问题。

不幸的是，async-profiler不能做很多事情。一种可能的解决方法是禁用相应的JVM内部函数：

java -XX:+UnlockDiagnosticVMOptions -XX:DisableIntrinsic=_currentTimeMillis,_nanoTime

顺便说一句，在您的火焰图中，我发现奇怪的是clock_gettime调用了内核。通常不应该这样做，因为clock_gettime是在vDSO中实现的，它已映射到进程的用户空间。原因可能是时钟源错误/已禁用vDSO（1，2）。