RFR: 8316814: NMT: A separate script or Java program is needed to analyze and make useful reports ouf of JMH benchmarks outputs.

[Gerard Ziemski]

On Fri, 6 Oct 2023 10:22:23 GMT, Afshin Zafari <azafari at openjdk.org> wrote:

> It reads the benchmark report file whose path is given as command line. Then extract percentage of overhead of NMT modes for different methods used in benchmarks.
> Locally tested with some sample report files.
> From an input benchmark report like this: 
> 
> # JMH version: 1.37
> # VM version: JDK 22-internal, OpenJDK 64-Bit Server VM,......in...
> # VM invoker:.....
> # VM options: -XX:NativeMemoryTracking=detail --add-exports java.base/jdk.internal.misc=ALL-UNNAMED -Djava.library.path=...
> # Blackhole mode: compiler (auto-detected, use -Djmh.blackhole.autoDetect=false to disable)
> # Warmup: 2 iterations, 1 s each
> # Measurement: 5 iterations, 1 s each
> # Timeout: 10 min per iteration
> # Threads: 1 thread, will synchronize iterations
> # Benchmark mode: Average time, time/op
> # Benchmark: org.openjdk.bench.vm.runtime.NMTBenchmark.NMTDetail.mixAallocateFreeMemory
> # Parameters: (N = 100000, THREADS = 4)
> 
> .
> .
> .
> 
> 
> Benchmark                                               (N)  (THREADS)  Mode  Cnt    Score    Error  Units
> NMTBenchmark.NMTDetail.mixAallocateFreeMemory        100000          0  avgt   10   87.010 ? 10.630  ms/op
> NMTBenchmark.NMTDetail.mixAallocateFreeMemory        100000          4  avgt   10    2.473 ?  0.728  ms/op
> NMTBenchmark.NMTDetail.mixAllocateReallocateMemory   100000          0  avgt   10  225.054 ?  4.381  ms/op
> NMTBenchmark.NMTDetail.mixAllocateReallocateMemory   100000          4  avgt   10    2.247 ?  0.599  ms/op
> NMTBenchmark.NMTDetail.onlyAllocateMemory            100000          0  avgt   10  147.346 ?  8.226  ms/op
> NMTBenchmark.NMTDetail.onlyAllocateMemory            100000          4  avgt   10    2.285 ?  0.611  ms/op
> NMTBenchmark.NMTOff.mixAallocateFreeMemory           100000          0  avgt   10   40.405 ?  8.115  ms/op
> NMTBenchmark.NMTOff.mixAallocateFreeMemory           100000          4  avgt   10    2.299 ?  0.658  ms/op
> NMTBenchmark.NMTOff.mixAllocateReallocateMemory      100000          0  avgt   10  158.700 ? 10.750  ms/op
> NMTBenchmark.NMTOff.mixAllocateReallocateMemory      100000          4  avgt   10    2.282 ?  0.723  ms/op
> NMTBenchmark.NMTOff.onlyAllocateMemory               100000          0  avgt   10  113.949 ? 21.257  ms/op
> NMTBenchmark.NMTOff.onlyAllocateMemory               100000          4  avgt   10    2.155 ?  0.682  ms/op
> NMTBenchmark.NMTSummary.mixAallocateFreeMemory       100000          0  avgt   10   50.436 ?  4.576  ms/op
> NMTBenchmark.NMTSummary.mixAallocateFreeMemory       100000          4  avgt   10    2.192 ?  0.7...

Can we add error values to the report please?

Would a layout like this be easier to parse (everything on one line)

                                  Method Threads   Off    Summary Diff     Detail Diff
                  mixAallocateFreeMemory     0     40.41    50.44 24.83%   87.01  115.34%
                  mixAallocateFreeMemory     4      2.30     2.19 -4.65%   2.47   7.57%
             mixAllocateReallocateMemory     0    158.70   170.41 7.38%    225.05 41.81%
             mixAllocateReallocateMemory     4      2.28     2.34 2.72%    2.25   -1.53%
                      onlyAllocateMemory     0    113.95   117.48 3.10%    147.35 29.31%
                      onlyAllocateMemory     4      2.16     2.37 9.84%    2.29   6.03%

I'm not sure myself yet which one I prefer, they both look a bit busy, but this one requires less vertical scanning, but more horizontal scanning...

I think we might need 3 decimal places to show to the user (like the original output).

When I try the numbers as shown say here:

                  mixAallocateFreeMemory     4      2.30   2.19    2.47
                                                          -4.65%   7.57%
  
20.19 - 2.30 == -0.11 --> -0.11 / 2.30 --> -0.047826086956522 * 100 --> -4.78%

I get quite a different number --> -4.78% vs -4.65%

Just noticed a small typo in mixAallocateFreeMemory, it should be mixAllocateFreeMemory I think.

-------------

Changes requested by gziemski (Committer).

PR Review: https://git.openjdk.org/jdk/pull/16070#pullrequestreview-1668529292
PR Comment: https://git.openjdk.org/jdk/pull/16070#issuecomment-1755983395
PR Comment: https://git.openjdk.org/jdk/pull/16070#issuecomment-1756024531
PR Comment: https://git.openjdk.org/jdk/pull/16070#issuecomment-1761726825