2

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. enter image description here 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?

apangin
  • 92,924
  • 10
  • 193
  • 247
Vadim
  • 576
  • 1
  • 4
  • 13
  • 2
    Alhough the question lacks a reproducible example (please add it if possible), the main point of the question is understood and makes sense. I think it does not deserve downvotes / close votes. – apangin Oct 10 '20 at 15:14
  • Do you run Java in a virtualized environment, in a container, or on the real hardware? What is the kernel version? – apangin Oct 10 '20 at 15:42
  • Yes, it is a Ubuntu VM in AWS EC2. I've just updated the kernel to 5.8.0-050800-generic (as advised in your link), but after the reboot the problem remains. I will dig further. Anyway, it already has nothing to do with async profiler per se. – Vadim Oct 10 '20 at 18:25
  • Thanks a lot for help! It turned out that default clock source was xen. Changing it to tsc has fixed the issue. I used this instruction, in case someone needs it. https://aws.amazon.com/ru/premiumsupport/knowledge-center/manage-ec2-linux-clock-source/ – Vadim Oct 10 '20 at 19:02

1 Answers1

3

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).

apangin
  • 92,924
  • 10
  • 193
  • 247
  • Thank you Andrei! Disabling these intrinsics really helped to make profile look reasonable. – Vadim Oct 10 '20 at 18:21