Async-profiler: Different results of profiling on JDK 11 and JDK 14

[stsypanov]

Steps to reproduce:

1. Checkout project https://github.com/stsypanov/spring-benchmark
2. Change springVersion in build.gradle to '5.1.3.RELEASE' and build project
3. Run this benchmark on JDK 11

@State(Scope.Thread)
@OutputTimeUnit(TimeUnit.MICROSECONDS)
@BenchmarkMode(value = Mode.AverageTime)
@Fork(jvmArgsAppend = {"-Xms2g", "-Xmx2g"})
public class ConcurrentReferenceHashMapBenchmark {
  @Benchmark
  public Object instantiate() {
    return new ConcurrentReferenceHashMap<>();
  }
}

1. While the benchmark is running take it's profile with $ ./profiler.sh -d 60 -i 10 -f CRHM_11.txt pid
2. Rerun same benchmark with JDK 14 and take it's profile with $ ./profiler.sh -d 60 -i 10 -f CRHM_14.txt pid
3. Compare results:

JDK 11
         ns  percent  samples  top
 ----------  -------  -------  ---
35611202541   87.14%  3538654  o.s.u.ConcurrentReferenceHashMap.calculateShift
 2043305050    5.00%   195176  o.s.u.ConcurrentReferenceHashMap.<init>
  988612869    2.42%    97805  SpinPause
  206492541    0.51%    19738  org.springframework.util.Assert.isTrue
  135142017    0.33%    12841  org.openjdk.jmh.infra.Blackhole.consume

JDK 14
         ns  percent  samples  top
 ----------  -------  -------  ---
20480205440   49.56%  2033284  o.s.u.ConcurrentReferenceHashMap.calculateShift
18323018910   44.34%  1817853  o.s.u.ConcurrentReferenceHashMap.<init>
  211271318    0.51%    20992  o.s.u.Assert.isTrue
  119008949    0.29%    11824  o.s.u.ConcurrentReferenceHashMap.<init>
   99063002    0.24%     9831  org.openjdk.jmh.infra.Blackhole.consume

In case of JDK 11 the share of ConcurrentReferenceHashMap.calculateShift is twice as higher as in case of JDK 14, which is apparently wrong, compare output of LinuxPerfAsmProfiler:

• JDK 11 https://gist.github.com/stsypanov/b552366103d100f57c6f8df9b1f2458a
• JDK 14 https://gist.github.com/stsypanov/2e4bd73c39d7465cbdd75ba26d4bc217

In both cases we see that LinuxPerfAsmProfiler finds hot places related to instantiation of ConcurrentReferenceHashMap: private volatile int count = 0;, assignment of ConcurrentReferenceHashMap$Segment.references, access to ConcurrentReferenceHashMap.segments etc., but they are not reflected in asyn-profiler's profile collected for JDK 11.

[apangin]

JVM compiled code does not include debug information.
Use one of the following options:

1. add -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints JVM flags, or
2. attach profiler at JVM startup: -agentpath:/path/to/libasyncProfiler.so, or
3. use JMH 1.24+ which has built-in support for async-profiler: -prof async.

Also, please specify units for the interval option: -i 10ms. Otherwise it is treated as 10 nanoseconds, which is not a good value for profiling.

Here is how the top will look like:

          ns  percent  samples  top
  ----------  -------  -------  ---
 21706298181   72.16%     2170  org.springframework.util.ConcurrentReferenceHashMap$Segment.<init>
  2877573403    9.57%      289  org.springframework.util.ConcurrentReferenceHashMap.<init>
  2114026626    7.03%      211  org.springframework.util.ConcurrentReferenceHashMap.calculateShift
  1311829690    4.36%      131  java.util.concurrent.locks.ReentrantLock.<init>
   520239560    1.73%       52  java.lang.ref.ReferenceQueue.<init>
   515454199    1.71%       52  org.springframework.util.ConcurrentReferenceHashMap.createReferenceManager
   202095442    0.67%       20  org.springframework.util.ConcurrentReferenceHashMap$Segment.createReferenceArray

[stsypanov]

@apangin thanks for detailed explanation! Can I ask two more questions:

• why 10 ns is a bad value for profiling?
• I din't use -XX:+UnlockDiagnosticVMOptions and -XX:+DebugNonSafepoints either for JDK 11 or JDK 14, still got so different results. What's the cause?

[franz1981]

@stsypanov

I din't use -XX:+UnlockDiagnosticVMOptions and -XX:+DebugNonSafepoints either for JDK 11 or JDK 14, still got so different results. What's the cause?

The cause is that you didn't use it. You should use them if you don't want to depend by the inlining decisions/different policies of the JDK version used.

[apangin]

@stsypanov As you already discovered, the shape of the compiled code and the mapping between instructions and bci changes from one JDK version to anothers. An address in the JITted code is resolved to the nearest location with the debug info (which is by default generated only for safepoints). Without extra debug info, this "nearest location" can be quite inaccurate within large compilations with lots of inlined methods.

As to the profiling interval, 10 ns is roughly 20-50 cpu instructions. It's literally impossible to take samples at such rate. The process will do nothing but spending all time inside the profiler.

The default sampling interval in cpu mode is 10ms. This choice is good enough for profiling in production: for an average application the profiling overhead will be negligible, while the number of samples will be enough to collect a meaningful profile.

1ms interval is usually fine for benchmarks and for profiling real applications for a short period of time. Lower intervals are rarely useful - maybe, only for capturing a profile of a short running piece of code.

[stsypanov]

@apangin thanks for detailed explanation!