async profiler displays wrong stacktraces

Question

I am trying to use async profiler v.1.8.1 for profiling my application.

JVM is openjdk version "15-ea" 2020-09-15, but same happened with openjdk 14.0.1 as well.

async profiler is run with flags: -d 60 -t -i 10000 -o svg

It shows extremely strange results. We can see that hardware thread spends most of the time not in java.lang.Thread::run, but in some weird place. How can it be explained? I see a possible explanation that async profiler fails to properly traverse stack traces and puts part of these stack traces in a wrong place. Is there another explanation? How can it be fixed?

Answer 1

I assume you wonder why there are no Java frames underneath clock_gettime in the profile.

As you can see, the stack ends with [unknown_Java] frame. This means, the thread indeed runs some Java code, but async-profiler cannot get Java stack trace, because the JVM fails to find the top Java frame.

This happens because System.nanoTime() and System.currentTimeMillis() are JVM intrinsics. They are JIT-compiled as a direct call of a corresponding C function without switching thread from in_java to in_native state. This means, the JVM does not save a pointer to the last Java frame when calling nanoTime or currentTimeMillis, and thus has problems discovering the last Java frame during asynchronous stack walking.

Unfortunately, async-profiler cannot do much about it. One possible workaround is to disable the corresponding JVM intrinsics:

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

BTW, what I find strange in your flame graph is that clock_gettime calls into the kernel. Typically it should not, since clock_gettime is implemented in vDSO which is mapped into the process' user space. The reason could be a wrong clock source / disabled vDSO (1, 2).