No assembly output for perfasm
Kristoffer Sjögren
stoffe at gmail.com
Sun Oct 25 22:00:32 UTC 2015
I figured it out. The hotThreshold was too high for the test to
generate the detailed assembly output.
Took me a while to figure out how to provide the options, but here it is.
java -jar target/benchmarks.jar Decode.legacy -prof perfasm:hotThreshold=0.01
Cheers,
-Kristoffer
On Sun, Oct 25, 2015 at 9:51 PM, Kristoffer Sjögren <stoffe at gmail.com> wrote:
> 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