Issues with dtraceasm, and a workaround
Vipin Sharma
vipinsharma85 at gmail.com
Mon Feb 22 12:05:57 UTC 2021
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