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

Fri Oct 20 09:30:57 UTC 2023

On Thu, 12 Oct 2023 10:17:56 GMT, Johan Sjölen <jsjolen 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...
>
> Hi Afshin!
> 
> PR output looks good, but I've got some comments on the code.

@jdksjolen and @gerard-ziemski ,
Is there any other comments on this PR?

> test/micro/org/openjdk/bench/vm/runtime/NMTAnalyze.java line 42:
> 
>> 40:     public String units;
>> 41:   }
>> 42:   public static class BenchmarkFields {
> 
> Could use an enum here.

Done.

> test/micro/org/openjdk/bench/vm/runtime/NMTAnalyze.java line 56:
> 
>> 54:   public static String fileName;
>> 55:   public static List<BenchmarkRecord> records = new ArrayList<>();
>> 56:   private static void skipUntilReport() {
> 
> Style: Missing newline to separate methods and properties.

Fixed.

> test/micro/org/openjdk/bench/vm/runtime/NMTAnalyze.java line 61:
> 
>> 59:       while (line != null) {
>> 60:         String ReportStartKeyword = "Benchmark";
>> 61:         if (!line.startsWith(ReportStartKeyword) || line.contains("#")) {
> 
> Are there lines which starts with `Benchmark` but contains a `#` that we need to skip?

Yes, there are. for each run there is a part like this. with `# Benchmark`:

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

> test/micro/org/openjdk/bench/vm/runtime/NMTAnalyze.java line 70:
> 
>> 68:     } catch (IOException ioe) {
>> 69:       System.out.println(ioe.getMessage());
>> 70:     }
> 
> Shouldn't the method itself just throw the `IOException`, since the caller handles it anyway? Otherwise, the rest of the body of `main` will execute.

Fixed.

> test/micro/org/openjdk/bench/vm/runtime/NMTAnalyze.java line 73:
> 
>> 71:   }
>> 72:   private static void readRecords() {
>> 73:     try {
> 
> Same thing here regarding `IOException` should be thrown

Fixed.

> test/micro/org/openjdk/bench/vm/runtime/NMTAnalyze.java line 74:
> 
>> 72:   private static void readRecords() {
>> 73:     try {
>> 74:       do {
> 
> Why not the same loop pattern as in `skipUntilReport`?

Done.

> test/micro/org/openjdk/bench/vm/runtime/NMTAnalyze.java line 82:
> 
>> 80:         BenchmarkRecord rec = new BenchmarkRecord();
>> 81:         List<String> __fields = Arrays.asList(_fields);
>> 82:         String[] fields = __fields.stream().filter(f -> f.length() > 0).collect(Collectors.toList()).toArray(new String[0]);
> 
> Could fold the fields handling into one line without loss of readability: `Arrays.asList(line.split(" ")).stream()`

Done.

> test/micro/org/openjdk/bench/vm/runtime/NMTAnalyze.java line 152:
> 
>> 150:     }
>> 151: 
>> 152:   }
> 
> Use try-with-resources here to not leak file descriptor in case of error https://docs.oracle.com/javase/tutorial/essential/exceptions/tryResourceClose.html

Done.

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

PR Comment: https://git.openjdk.org/jdk/pull/16070#issuecomment-1772302376
PR Review Comment: https://git.openjdk.org/jdk/pull/16070#discussion_r1357919948
PR Review Comment: https://git.openjdk.org/jdk/pull/16070#discussion_r1357920196
PR Review Comment: https://git.openjdk.org/jdk/pull/16070#discussion_r1357911739
PR Review Comment: https://git.openjdk.org/jdk/pull/16070#discussion_r1357920633
PR Review Comment: https://git.openjdk.org/jdk/pull/16070#discussion_r1357920764
PR Review Comment: https://git.openjdk.org/jdk/pull/16070#discussion_r1357920904
PR Review Comment: https://git.openjdk.org/jdk/pull/16070#discussion_r1357921149
PR Review Comment: https://git.openjdk.org/jdk/pull/16070#discussion_r1357921436