Techempower benchmark spends 9% of time in System.nanoTime()?

[jfrantzius]

Hi @franz1981 , following up to our previous discussion on profiling the Techempower benchmark, this is number 2 of the hotspots that JProfiler sees with async profiling (running the benchmark using Docker on x86 Linux), inbetween sending and receiving data, i.e. more time spent there than IO for reading data:

By comparing the calling Java code, this seem to be calls to System.nanoTime(). Again it's suprising that this should be expensive, given that clock_gettime() resides in vDSO and so should be running in user space. But then JProfiler doesn't report the number of invocations.

The JVM's code seems to be this:

Do you have an idea what we are seeing here?

[jfrantzius]

This is what one call path into System.nanoTime() looks like in async-profiler (using -e cycles):

[franz1981]

Did you tried outside of docker?
Docker still uses syscall-like banning, that could have some impact (on docker) and/or some skidding (search in the Intel site about what it is) could be in place that can cause blaming it while its nearest inlined methods could be the real guilty ones.

Sadly inlining and Intrinsics often makes profilers confused, including async profiler that indeed relies on AsyncGetCallTrace, that can be prone to point to the wrong method to blame in such cases.

[jfrantzius]

It turns out tsc is not available as clocksource on my host:

$ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
hpet acpi_pm 

I found this in /var/log/syslog:

tsc: Marking TSC unstable due to clocksource watchdog
TSC found unstable after boot, most likely due to broken BIOS. Use 'tsc=unstable'.

Am now trying to find out whether that can be fixed...

[jfrantzius]

This could really be a BIOS bug: https://bugzilla.kernel.org/show_bug.cgi?id=202525

The BIOS can only be updated from Windows, but I wiped out the Windows partition, doh!

[franz1981]

Doh!

[jfrantzius]

For the records, updating the BIOS wasn't enough, I also had to set the Kernel boot parameter processor.max_cstate=1.

Now that TSC is available as clocksource, System.nanoTime() doesn't show up anymore in profiling.