Issues with dtraceasm, and a workaround
Henri Tremblay
henri.tremblay at gmail.com
Mon Feb 22 13:46:09 UTC 2021
Went out of my head. Trying now.
On Mon, 22 Feb 2021 at 07:06, Vipin Sharma <vipinsharma85 at gmail.com> wrote:
> Hi Aleksey,
>
> Performed following 3 tests on Mac OS:
> Before applying pull request #22
> After applying pull request #22
> After applying patch Paul shared
>
> This is result of test before applying pull request #22:
>
> sudo java -jar jmh-samples/target/benchmarks.jar Hello -wi 5 -i 5 -f 1 -w
> 1s -r 1s -prof dtraceasm
> Password:
> # JMH version: 1.28-SNAPSHOT
> # VM version: JDK 14.0.1, OpenJDK 64-Bit Server VM, 14.0.1+14
> # VM invoker:
> /usr/local/Cellar/openjdk/14.0.1/libexec/openjdk.jdk/Contents/Home/bin/java
> # VM options: <none>
> # Blackhole mode: full + dont-inline hint
> # Warmup: 5 iterations, 1 s each
> # Measurement: 5 iterations, 1 s each
> # Timeout: 10 min per iteration
> # Threads: 1 thread, will synchronize iterations
> # Benchmark mode: Throughput, ops/time
> # Benchmark: org.openjdk.jmh.samples.JMHSample_01_HelloWorld.wellHelloThere
>
> # Run progress: 0.00% complete, ETA 00:00:10
> # Fork: 1 of 1
> # Preparing profilers: DTraceAsmProfiler
> # Profilers consume stdout and stderr from target VM, use -v EXTRA to copy
> to console
>
> # Warmup Iteration 1: 1319033969.289 ops/s
> # Warmup Iteration 2: 1521121012.480 ops/s
> # Warmup Iteration 3: 1482985984.515 ops/s
> # Warmup Iteration 4: 1495900466.986 ops/s
> # Warmup Iteration 5: 1380605652.980 ops/s
> Iteration 1: 1419987109.014 ops/s
> Iteration 2: 1525874070.819 ops/s
> Iteration 3: 1405272398.362 ops/s
> Iteration 4: 1246884730.454 ops/s
> Iteration 5: 1283829539.582 ops/s
> # Processing profiler results: DTraceAsmProfiler Exception in thread
> "main" java.lang.IllegalStateException: [kill: 6412: No such process
> ]
> at
> org.openjdk.jmh.profile.DTraceAsmProfiler.afterTrial(DTraceAsmProfiler.java:94)
> at org.openjdk.jmh.runner.Runner.runSeparate(Runner.java:682)
> at org.openjdk.jmh.runner.Runner.runBenchmarks(Runner.java:565)
> at org.openjdk.jmh.runner.Runner.internalRun(Runner.java:317)
> at org.openjdk.jmh.runner.Runner.run(Runner.java:209)
> at org.openjdk.jmh.Main.main(Main.java:71)
>
>
>
> This is result of test after applying pull request #22:
>
> sudo java -jar jmh-samples/target/benchmarks.jar Hello -wi 5 -i 5 -f 1 -w
> 1s -r 1s -prof dtraceasm
> # JMH version: 1.28-SNAPSHOT
> # VM version: JDK 14.0.1, OpenJDK 64-Bit Server VM, 14.0.1+14
> # VM invoker:
> /usr/local/Cellar/openjdk/14.0.1/libexec/openjdk.jdk/Contents/Home/bin/java
> # VM options: <none>
> # Blackhole mode: full + dont-inline hint
> # Warmup: 5 iterations, 1 s each
> # Measurement: 5 iterations, 1 s each
> # Timeout: 10 min per iteration
> # Threads: 1 thread, will synchronize iterations
> # Benchmark mode: Throughput, ops/time
> # Benchmark: org.openjdk.jmh.samples.JMHSample_01_HelloWorld.wellHelloThere
>
> # Run progress: 0.00% complete, ETA 00:00:10
> # Fork: 1 of 1
> # Preparing profilers: DTraceAsmProfiler
> # Profilers consume stdout and stderr from target VM, use -v EXTRA to copy
> to console
>
> # Warmup Iteration 1: 1131667782.835 ops/s
> # Warmup Iteration 2: 1487563908.681 ops/s
> # Warmup Iteration 3: 1282855732.382 ops/s
> # Warmup Iteration 4: 1378199698.069 ops/s
> # Warmup Iteration 5: 1400383709.725 ops/s
> Iteration 1: 1355249548.484 ops/s
> Iteration 2: 1216663795.975 ops/s
> Iteration 3: 1597674804.332 ops/s
> Iteration 4: 1543645238.596 ops/s
> Iteration 5: 1625618415.691 ops/s
> # Processing profiler results: DTraceAsmProfiler Exception in thread
> "main" java.lang.IllegalStateException: [kill: 6508: No such process
> ]
> at
> org.openjdk.jmh.profile.DTraceAsmProfiler.afterTrial(DTraceAsmProfiler.java:94)
> at org.openjdk.jmh.runner.Runner.runSeparate(Runner.java:682)
> at org.openjdk.jmh.runner.Runner.runBenchmarks(Runner.java:565)
> at org.openjdk.jmh.runner.Runner.internalRun(Runner.java:317)
> at org.openjdk.jmh.runner.Runner.run(Runner.java:209)
> at org.openjdk.jmh.Main.main(Main.java:71)
>
>
>
> This is result of test for the patch Paul shared:
>
> sudo java -jar jmh-samples/target/benchmarks.jar Hello -wi 5 -i 5 -f 1 -w
> 1s -r 1s -prof dtraceasm
> Password:
> # JMH version: 1.28-SNAPSHOT
> # VM version: JDK 14.0.1, OpenJDK 64-Bit Server VM, 14.0.1+14
> # VM invoker:
> /usr/local/Cellar/openjdk/14.0.1/libexec/openjdk.jdk/Contents/Home/bin/java
> # VM options: <none>
> # Blackhole mode: full + dont-inline hint
> # Warmup: 5 iterations, 1 s each
> # Measurement: 5 iterations, 1 s each
> # Timeout: 10 min per iteration
> # Threads: 1 thread, will synchronize iterations
> # Benchmark mode: Throughput, ops/time
> # Benchmark: org.openjdk.jmh.samples.JMHSample_01_HelloWorld.wellHelloThere
>
> # Run progress: 0.00% complete, ETA 00:00:10
> # Fork: 1 of 1
> # Preparing profilers: DTraceAsmProfiler
> # Profilers consume stdout and stderr from target VM, use -v EXTRA to copy
> to console
>
> # Warmup Iteration 1: 1393344698.235 ops/s
> # Warmup Iteration 2: 1327737161.595 ops/s
> # Warmup Iteration 3: 1399485684.470 ops/s
> # Warmup Iteration 4: 796236291.612 ops/s
> # Warmup Iteration 5: 1168590989.118 ops/s
> Iteration 1: 1634338978.557 ops/s
> Iteration 2: 1650777380.046 ops/s
> Iteration 3: 1637344858.710 ops/s
> Iteration 4: 1548646684.051 ops/s
> Iteration 5: 1607923581.206 ops/s
> # Processing profiler results: DTraceAsmProfiler
>
>
> Result "org.openjdk.jmh.samples.JMHSample_01_HelloWorld.wellHelloThere":
> 1615806296.514 ±(99.9%) 156448224.819 ops/s [Average]
> (min, avg, max) = (1548646684.051, 1615806296.514, 1650777380.046),
> stdev = 40629107.163
> CI (99.9%): [1459358071.695, 1772254521.333] (assumes normal
> distribution)
>
> Secondary result
> "org.openjdk.jmh.samples.JMHSample_01_HelloWorld.wellHelloThere:·asm":
> PrintAssembly processed: 33216 total address lines.
> Perf output processed (skipped 9.763 seconds):
> Column 1: sampled_pc (0 events)
>
> WARNING: No hottest code region above the threshold (10.00%) for
> disassembly.
> Use "hotThreshold" profiler option to lower the filter threshold.
>
> ....[Hottest
> Regions]...............................................................................
>
> ....................................................................................................
> <totals>
>
> ....[Hottest Methods (after
> inlining)]..............................................................
>
> ....................................................................................................
> <totals>
>
> ....[Distribution by
> Source]........................................................................
>
> ....................................................................................................
> <totals>
>
> WARNING: The perf event count is suspiciously low (0). The performance
> data might be
> inaccurate or misleading. Try to do the profiling again, or tune up the
> sampling frequency.
> With some profilers on Mac OS X, System Integrity Protection (SIP) may
> prevent profiling.
> In such case, temporarily disabling SIP with 'csrutil disable' might help.
>
>
> # Run complete. Total time: 00:00:15
>
> REMEMBER: The numbers below are just data. To gain reusable insights, you
> need to follow up on
> why the numbers are the way they are. Use profilers (see -prof, -lprof),
> design factorial
> experiments, perform baseline and negative tests that provide experimental
> control, make sure
> the benchmarking environment is safe on JVM/OS/HW level, ask for reviews
> from the domain experts.
> Do not assume the numbers tell you what you want them to tell.
>
> Benchmark Mode Cnt Score
> Error Units
> JMHSample_01_HelloWorld.wellHelloThere thrpt 5 1615806296.514 ±
> 156448224.819 ops/s
> JMHSample_01_HelloWorld.wellHelloThere:·asm thrpt NaN
> ---
>
>
>
> Regards,
> Vipin
>
>
> > On Feb 22, 2021, at 3:01 PM, Aleksey Shipilev <shade at redhat.com> wrote:
> >
> > On 2/18/21 1:45 PM, Aleksey Shipilev wrote:
> >> On 2/18/21 1:24 PM, Aleksey Shipilev wrote:
> >>> Hold on. So if we call Process.destroy, then we also close all the
> streams at the same time?
> >>> https://bugs.openjdk.java.net/browse/JDK-8216990
> >>>
> >>> Whoa. So even the workaround above does not work reliably, as it races
> with the profiler process: if
> >>> we are lucky, profiler would succeed in dumping the output after the
> first SIGTERM, until
> >>> Process.destroy comes and closes everything. Hm.
> >> I do not have Mac OS to reproduce this, so can anyone else to give the
> following patch a spin on Mac
> >> OS and -prof dtraceasm?
> >> https://github.com/openjdk/jmh/pull/22
> >
> > Anyone? :)
> > --
> > Thanks,
> > -Aleksey
> >
>
>
More information about the jmh-dev
mailing list