No assembly output for perfasm
Kristoffer Sjögren
stoffe at gmail.com
Sun Oct 25 20:51:51 UTC 2015
Hi
For some reason the assembly output is not showing for my tests when
running perfasm [1] with JMH 1.11.1 and perf version 3.16.0 on Linux
Debian Jessie.
I know PrintAssembly works because I can generate a log which is
perfectly parsable by JitWatch. I can also see the assembly output
from JMH by adding the -v EXTRA flag.
$ java -jar target/benchmarks.jar Decode.legacy
-jvmArgs="-XX:+UnlockDiagnosticVMOptions -XX:+TraceClassLoading
-XX:PrintAssemblyOptions=intel -XX:+LogCompilation -XX:+PrintAssembly
-XX:LogFile=hotspot.log"
Any ideas why jmh won't show me the assembly?
Cheers,
-Kristoffer
[1] Output
$ java -jar target/benchmarks.jar Decode.legacy -wi 20 -i 20 -r 1 -f 1
-prof perfasm
# JMH 1.11 (released 44 days ago)
# VM version: JDK 1.8.0_45, VM 25.45-b02
# VM invoker: /home/stoffe/Downloads/jdk1.8.0_45/jre/bin/java
# VM options: <none>
# Warmup: 20 iterations, 1 s each
# Measurement: 20 iterations, 1 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Benchmark: deephacks.Decode.legacy
# Run progress: 0.00% complete, ETA 00:00:40
# Fork: 1 of 1
# Preparing profilers: LinuxPerfAsmProfiler
# Profilers consume stdout and stderr from target VM, use -v EXTRA to
copy to console
# Warmup Iteration 1: 0.513 ops/s
# Warmup Iteration 2: 75.762 ops/s
# Warmup Iteration 3: 166.888 ops/s
# Warmup Iteration 4: 368.548 ops/s
# Warmup Iteration 5: 607.144 ops/s
# Warmup Iteration 6: 190.322 ops/s
# Warmup Iteration 7: 1159.049 ops/s
# Warmup Iteration 8: 1220.974 ops/s
# Warmup Iteration 9: 2412.146 ops/s
# Warmup Iteration 10: 4171.080 ops/s
# Warmup Iteration 11: 4590.409 ops/s
# Warmup Iteration 12: 8118.074 ops/s
# Warmup Iteration 13: 7864.901 ops/s
# Warmup Iteration 14: 7912.240 ops/s
# Warmup Iteration 15: 8886.517 ops/s
# Warmup Iteration 16: 8362.501 ops/s
# Warmup Iteration 17: 7436.626 ops/s
# Warmup Iteration 18: 7584.446 ops/s
# Warmup Iteration 19: 9531.862 ops/s
# Warmup Iteration 20: 9701.975 ops/s
Iteration 1: 7798.191 ops/s
Iteration 2: 8768.801 ops/s
Iteration 3: 9651.449 ops/s
Iteration 4: 8383.285 ops/s
Iteration 5: 10428.639 ops/s
Iteration 6: 8958.372 ops/s
Iteration 7: 8548.640 ops/s
Iteration 8: 9676.202 ops/s
Iteration 9: 8443.678 ops/s
Iteration 10: 8489.997 ops/s
Iteration 11: 9493.343 ops/s
Iteration 12: 9008.206 ops/s
Iteration 13: 8520.892 ops/s
Iteration 14: 9240.624 ops/s
Iteration 15: 9874.695 ops/s
Iteration 16: 8955.088 ops/s
Iteration 17: 9308.933 ops/s
Iteration 18: 8513.425 ops/s
Iteration 19: 9385.654 ops/s
Iteration 20: 8237.902 ops/s
# Processing profiler results: LinuxPerfAsmProfiler
Result "legacy":
8984.301 ±(99.9%) 561.016 ops/s [Average]
(min, avg, max) = (7798.191, 8984.301, 10428.639), stdev = 646.066
CI (99.9%): [8423.285, 9545.316] (assumes normal distribution)
Secondary result "·asm":
PrintAssembly processed: 417977 total address lines.
Perf output processed (skipped 24.372 seconds):
Column 1: cycles (28022 events)
Column 2: instructions (27858 events)
....[Hottest Regions]...............................................................................
5.41% 8.44% [0x7f1c1530b1e6:0x7f1c1530b62e] in
deephacks.Bin1Decoder::decodeStream
4.35% 7.29% [0x7f1c281b8760:0x7f1c281b88d8] in inflate_fast (libzip.so)
3.65% 7.04% [0x7f1c15338732:0x7f1c153389d6] in deephacks.Base64::decode
2.07% 3.55% [0x7f1c1530b00c:0x7f1c1530b110] in
deephacks.Bin1Decoder::decodeStream
1.80% 2.00% [0x7f1c1545ab86:0x7f1c1545af2e] in
deephacks.legacy.LegacyDecoder::decodeToBin1
1.74% 2.44% [0x7f1c15459ab5:0x7f1c15459f1c] in
deephacks.legacy.LegacyDecoder::decodeToBin1
1.68% 2.49% [0x7f1c15366907:0x7f1c15366b94] in deephacks.Crumbs::getCrumb
1.32% 1.69% [0x7f1c15314820:0x7f1c15314983] in java.util.HashMap::resize
1.23% 1.47% [0x7f1c281be31d:0x7f1c281be4e8] in adler32 (libzip.so)
1.01% 0.71% [0x7f1c29d2ee60:0x7f1c29d2ee69] in SpinPause (libjvm.so)
0.96% 1.40% [0x7f1c15389360:0x7f1c15389731] in java.math.BigInteger::or
0.91% 0.36% [0x7f1c281b9100:0x7f1c281b915a] in inflateEnd (libzip.so)
0.86% 0.29% [0x7f1c15361a60:0x7f1c15361b2c] in
org.joda.time.field.PreciseDateTimeField::set
0.85% 0.49% [0x7f1c2a584aa0:0x7f1c2a584bfa] in [unknown] (libc-2.19.so)
0.78% 1.43% [0x7f1c1530b9a9:0x7f1c1530bbf6] in
deephacks.Bin1Decoder::decodeStream
0.75% 0.14% [0x7f1c2a588010:0x7f1c2a5880cd] in malloc (libc-2.19.so)
0.71% 0.78% [0x7f1c1530bbe0:0x7f1c1530bdea] in
deephacks.Bin1Decoder::decodeStream
0.71% 0.18% [0x7f1c2a588980:0x7f1c2a588a81] in __libc_calloc
(libc-2.19.so)
0.69% 0.31% [0x7f1c15051dbe:0x7f1c15051e9d] in
StubRoutines::jshort_disjoint_arraycopy
0.69% 0.84% [0x7f1c15412022:0x7f1c1541230a] in
deephacks.legacy.LegacyDecoder::serializedCrumbsFromHash
67.78% 56.66% <...other 1877 warm regions...>
....................................................................................................
99.91% 99.99% <totals>
....[Hottest Methods (after
inlining)]..............................................................
9.39% 14.53% deephacks.Bin1Decoder::decodeStream
7.39% 6.82% deephacks.legacy.LegacyDecoder::decodeToBin1
5.34% 8.38% inflate_fast (libzip.so)
5.09% 3.35% [unknown] (libc-2.19.so)
3.96% 7.43% deephacks.Base64::decode
3.61% 3.58% org.joda.time.format.DateTimeParserBucket::computeMillis
3.37% 4.07% deephacks.Crumbs::getCrumb
2.20% 2.25% deephacks.legacy.LegacyDecoder::serializedCrumbsFromHash
1.77% 2.10% deephacks.crumbs.FrequencyCountingCrumb::deserializeFromBin1
1.77% 1.20% inflate (libzip.so)
1.53% 1.95% java.util.HashMap::resize
1.51% 1.56% adler32 (libzip.so)
1.37% 1.34% java.lang.ref.Finalizer$FinalizerThread::run
1.35% 1.14% java.util.AbstractCollection::addAll
1.33% 1.45% deephacks.Crumbs::cacheCrumb
1.26% 1.12% deephacks.Crumbs::getAllCrumbs
1.17% 1.12% org.joda.time.format.DateTimeFormatter::parseDateTime
1.15% 1.66% java.math.BigInteger::or
1.10% 0.85% deephacks.crumbs.TrackingCrumb::deserializeFromBin1
1.02% 0.73% deephacks.Bin1Helper::getStringFromHash
43.25% 32.71% <...other 587 warm methods...>
....................................................................................................
99.91% 99.36% <totals>
....[Distribution by
Area]..........................................................................
63.39% 68.97% <generated code>
13.38% 10.99% <native code in (libjvm.so)>
10.57% 12.05% <native code in (libzip.so)>
7.25% 4.33% <native code in (libc-2.19.so)>
4.64% 3.14% <native code in ([kernel.kallsyms])>
0.19% 0.19% <native code in (libpthread-2.19.so)>
0.15% 0.10% <native code in (perf-5881.map)>
0.12% 0.06% <native code in (jbd2.ko)>
0.09% 0.05% <native code in (hsdis-amd64.so)>
0.08% 0.08% <native code in (ext4.ko)>
0.01% 0.00% <native code in (uhci-hcd.ko)>
0.01% 0.01% <native code in (hid.ko)>
0.01% <native code in (nouveau.ko)>
0.01% <native code in (usbhid.ko)>
0.00% <native code in (ehci-hcd.ko)>
0.00% <native code in (libjava.so)>
0.00% <native code in (libnet.so)>
0.00% <native code in (sky2.ko)>
....................................................................................................
99.91% 99.99% <totals>
# Run complete. Total time: 00:00:59
Benchmark Mode Cnt Score Error Units
Decode.legacy thrpt 20 8984.301 ± 561.016 ops/s
Decode.legacy:·asm thrpt NaN ---
More information about the jmh-dev
mailing list