JMH（Java Microbenchmark Harness）で、-prof perfasmをすると、perfと-XX:+PrintAssemblyを使って、JITコンパイラ生成コードでのホットな部分を表示してくれるという機能があります。これが、思いの外すごい機能だったので、紹介します。
前提条件
- JMHを知っていて、動作させられる。
- perfコマンドをインストールしている。
- HSDISをセットアップしている。
動かす
JMHのサンプルプロジェクトがあります。
そこに、プロファイルを使うものがあります。それを動かします。JMHSample_35_Profilers.javaです。
クラス内に、いくつかのベンチマークがあります。Atomicという内部クラスを使います。実行方法は、コメントにあります。
/* * ============================== HOW TO RUN THIS TEST: ==================================== * * You can run this test: * * a) Via the command line: * $ mvn clean install * $ java -jar target/benchmarks.jar JMHSample_35.*Atomic -prof perf -f 1 (Linux) * $ java -jar target/benchmarks.jar JMHSample_35.*Atomic -prof perfnorm -f 3 (Linux) * $ java -jar target/benchmarks.jar JMHSample_35.*Atomic -prof perfasm -f 1 (Linux) * $ java -jar target/benchmarks.jar JMHSample_35.*Atomic -prof xperfasm -f 1 (Windows) * $ java -jar target/benchmarks.jar JMHSample_35.*Atomic -prof dtraceasm -f 1 (Mac OS X) * b) Via the Java API: * (see the JMH homepage for possible caveats when running from IDE: * http://openjdk.java.net/projects/code-tools/jmh/) */
java -jar target/benchmarks.jar JMHSample_35.*Atomic -prof perfasm -f 1を実行します。
Hottest code regions (>10.00% "cycles" events):以下に、JITコンパイラ生成コードでのホットな部分が表示されます。一部取り出してみます。
....[Hottest Region 1]..............................................................................
c2, level 4, com.sakatakoichi.generated.JMHSample_35_Profilers_Atomic_test_jmhTest::test_avgt_jmhStub, version 491 (52 bytes)
0x00007f45f0675c34: mov (%rsp),%r10
0x00007f45f0675c38: movzbl 0x94(%r10),%r11d ;*getfield isDone {reexecute=0 rethrow=0 return_oop=0}
; - com.sakatakoichi.generated.JMHSample_35_Profilers_Atomic_test_jmhTest::test_avgt_jmhStub@30 (line 234)
; implicit exception: dispatches to 0x00007f45f0675d2a
0x00007f45f0675c40: test %r11d,%r11d
0x00007f45f0675c43: jne 0x00007f45f0675cd6 ;*ifeq {reexecute=0 rethrow=0 return_oop=0}
; - com.sakatakoichi.generated.JMHSample_35_Profilers_Atomic_test_jmhTest::test_avgt_jmhStub@33 (line 234)
0x00007f45f0675c49: mov $0x1,%ebp
0x00007f45f0675c4e: xchg %ax,%ax ;*aload_1 {reexecute=0 rethrow=0 return_oop=0}
; - com.sakatakoichi.generated.JMHSample_35_Profilers_Atomic_test_jmhTest::test_avgt_jmhStub@36 (line 235)
3.93% ↗ 0x00007f45f0675c50: mov 0x40(%rsp),%r10
│ 0x00007f45f0675c55: mov 0xc(%r10),%r11d ;*getfield n {reexecute=0 rethrow=0 return_oop=0}
│ ; - com.sakatakoichi.JMHSample_35_Profilers$Atomic::test@1 (line 342)
│ ; - com.sakatakoichi.generated.JMHSample_35_Profilers_Atomic_test_jmhTest::test_avgt_jmhStub@17 (line 232)
│ 0x00007f45f0675c59: test %r11d,%r11d
│ 0x00007f45f0675c5c: je 0x00007f45f0675cc9
│ 0x00007f45f0675c5e: mov $0x1,%edx
3.54% │ 0x00007f45f0675c63: lock xadd %rdx,0x10(%r12,%r11,8) ;*invokevirtual getAndAddLong {reexecute=0 rethrow=0 return_oop=0}
│ ; - java.util.concurrent.atomic.AtomicLong::incrementAndGet@8 (line 231)
│ ; - com.sakatakoichi.JMHSample_35_Profilers$Atomic::test@4 (line 342)
│ ; - com.sakatakoichi.generated.JMHSample_35_Profilers_Atomic_test_jmhTest::test_avgt_jmhStub@17 (line 232)
65.18% │ 0x00007f45f0675c6a: add $0x1,%rdx ;*ladd {reexecute=0 rethrow=0 return_oop=0}
│ ; - java.util.concurrent.atomic.AtomicLong::incrementAndGet@12 (line 231)
│ ; - com.sakatakoichi.JMHSample_35_Profilers$Atomic::test@4 (line 342)
│ ; - com.sakatakoichi.generated.JMHSample_35_Profilers_Atomic_test_jmhTest::test_avgt_jmhStub@17 (line 232)
│ 0x00007f45f0675c6e: mov 0x38(%rsp),%rsi
4.06% │ 0x00007f45f0675c73: callq 0x00007f45e8ba4900 ; ImmutableOopMap{[48]=Oop [56]=Oop [64]=Oop [0]=Oop }
│ ;*invokevirtual consume {reexecute=0 rethrow=0 return_oop=0}
│ ; - com.sakatakoichi.generated.JMHSample_35_Profilers_Atomic_test_jmhTest::test_avgt_jmhStub@20 (line 232)
│ ; {optimized virtual_call}
│ 0x00007f45f0675c78: mov (%rsp),%r10
0.02% │ 0x00007f45f0675c7c: movzbl 0x94(%r10),%r11d ;*ifeq {reexecute=0 rethrow=0 return_oop=0}
│ ; - com.sakatakoichi.generated.JMHSample_35_Profilers_Atomic_test_jmhTest::test_avgt_jmhStub@33 (line 234)
3.77% │ 0x00007f45f0675c84: mov 0x108(%r15),%r10
│ 0x00007f45f0675c8b: add $0x1,%rbp ; ImmutableOopMap{[48]=Oop [56]=Oop [64]=Oop [0]=Oop }
│ ;*ifeq {reexecute=1 rethrow=0 return_oop=0}
│ ; - com.sakatakoichi.generated.JMHSample_35_Profilers_Atomic_test_jmhTest::test_avgt_jmhStub@33 (line 234)
│ 0x00007f45f0675c8f: test %eax,(%r10) ; {poll}
│ 0x00007f45f0675c92: test %r11d,%r11d
╰ 0x00007f45f0675c95: je 0x00007f45f0675c50 ;*aload_1 {reexecute=0 rethrow=0 return_oop=0}
; - com.sakatakoichi.generated.JMHSample_35_Profilers_Atomic_test_jmhTest::test_avgt_jmhStub@36 (line 235)
0x00007f45f0675c97: movabs $0x7f46083171c0,%r10
0x00007f45f0675ca1: callq *%r10 ;*invokestatic nanoTime {reexecute=0 rethrow=0 return_oop=0}
....................................................................................................
実行時間の割合も出ています。今回、65.18%がjava.util.concurrent.atomic.AtomicLong::incrementAndGetでした。AtomicLongなので、パフォーマンスとして、こうなりますね。
あと、ジャンプ命令のときに、そのジャンプの飛び先が矢印で示されています。すごいです。
単に-XX:+PrintAssemblyして見るよりも、圧倒的に見やすいです。JMHでのマイクロベンチマークまで、コードを落とし込められる場合は、よさそうです。
VirtualBox上のLinux
当初、VirtualBox上のUbuntuで試していたのですが、-prof perfasmがうまく動作しませんでした。
これは、VirtualBox上だと、perfの機能が一部サポートされないからでは、と考えています。
普通にセットアップしたLinuxと、VirtualBox上のLinuxでperf stat -d -d -d lsを実行します。
普通のLinux
$ perf stat -d -d -d ls
...
Performance counter stats for 'ls':
0.488301 task-clock (msec) # 0.727 CPUs utilized
0 context-switches # 0.000 K/sec
0 cpu-migrations # 0.000 K/sec
100 page-faults # 0.205 M/sec
1,941,085 cycles # 3.975 GHz
1,491,342 instructions # 0.77 insn per cycle
293,966 branches # 602.018 M/sec
12,839 branch-misses # 4.37% of all branches
405,733 L1-dcache-loads # 830.908 M/sec
29,258 L1-dcache-load-misses # 7.21% of all L1-dcache hits
<not counted> LLC-loads (0.00%)
<not counted> LLC-load-misses (0.00%)
<not supported> L1-icache-loads
<not counted> L1-icache-load-misses (0.00%)
<not counted> dTLB-loads (0.00%)
<not counted> dTLB-load-misses (0.00%)
<not counted> iTLB-loads (0.00%)
<not counted> iTLB-load-misses (0.00%)
<not supported> L1-dcache-prefetches
<not supported> L1-dcache-prefetch-misses
0.000671716 seconds time elapsed
VirtualBox上のLinux
$ perf stat -d -d -d ls
...
Performance counter stats for 'ls':
0.868631 task-clock (msec) # 0.222 CPUs utilized
23 context-switches # 0.026 M/sec
0 cpu-migrations # 0.000 K/sec
109 page-faults # 0.125 M/sec
<not supported> cycles
<not supported> instructions
<not supported> branches
<not supported> branch-misses
<not supported> L1-dcache-loads
<not supported> L1-dcache-load-misses
<not supported> LLC-loads
<not supported> LLC-load-misses
<not supported> L1-icache-loads
<not supported> L1-icache-load-misses
<not supported> dTLB-loads
<not supported> dTLB-load-misses
<not supported> iTLB-loads
<not supported> iTLB-load-misses
<not supported> L1-dcache-prefetches
<not supported> L1-dcache-prefetch-misses
0.003912732 seconds time elapsed
0.001099000 seconds user
0.000000000 seconds sys
VirtualBox上のLinuxでは、ほとんどの項目が<not supported>です。
perfasmでは、Hottest code regions (>10.00% "cycles" events)とあるので、cyclesを使っていると考えます。しかし、VirtualBox上のLinuxでは、cyclesは<not supported>ですので、表示されないのでしょう。
参考
JMHのプロファイラ
-profオプションは、プロファイラを指定するものです。perfasmは、org.openjdk.jmh.profile.LinuxPerfAsmProfilerクラスをプロファイラとして使います。
プロファイラでは、こういった設定をしています（スーパークラスでの設定も含む）。
Collection<String> opts = new ArrayList<>(); opts.addAll(Arrays.asList( "-XX:+UnlockDiagnosticVMOptions", "-XX:+LogCompilation", "-XX:LogFile=" + hsLog.getAbsolutePath(), "-XX:+PrintAssembly"));
JMHから、ベンチマークを実行する時に、適切なオプションが付与されます。
perfは、こういったオプションで実行しています。
Collection<String> failMsg = Utils.tryWith(PerfSupport.PERF_EXEC, "stat", "--log-fd", "2", "echo", "1");
perfnorm
他のプロファイラも実行してみます。java -jar target/benchmarks.jar JMHSample_35.*Atomic -prof perfnorm -f 3を実行します。
Benchmark Mode Cnt Score Error Units JMHSample_35_Profilers.Atomic.test avgt 15 6.114 ± 0.081 ns/op JMHSample_35_Profilers.Atomic.test:CPI avgt 3 0.838 ± 0.039 #/op JMHSample_35_Profilers.Atomic.test:L1-dcache-load-misses avgt 3 0.003 ± 0.041 #/op JMHSample_35_Profilers.Atomic.test:L1-dcache-loads avgt 3 14.114 ± 1.387 #/op JMHSample_35_Profilers.Atomic.test:L1-dcache-stores avgt 3 4.038 ± 0.333 #/op JMHSample_35_Profilers.Atomic.test:L1-icache-load-misses avgt 3 0.004 ± 0.032 #/op JMHSample_35_Profilers.Atomic.test:LLC-load-misses avgt 3 ≈ 10⁻⁴ #/op JMHSample_35_Profilers.Atomic.test:LLC-loads avgt 3 ≈ 10⁻³ #/op JMHSample_35_Profilers.Atomic.test:LLC-store-misses avgt 3 ≈ 10⁻⁴ #/op JMHSample_35_Profilers.Atomic.test:LLC-stores avgt 3 0.001 ± 0.018 #/op JMHSample_35_Profilers.Atomic.test:branch-misses avgt 3 0.001 ± 0.014 #/op JMHSample_35_Profilers.Atomic.test:branches avgt 3 5.061 ± 0.548 #/op JMHSample_35_Profilers.Atomic.test:cycles avgt 3 25.468 ± 2.533 #/op JMHSample_35_Profilers.Atomic.test:dTLB-load-misses avgt 3 ≈ 10⁻⁵ #/op JMHSample_35_Profilers.Atomic.test:dTLB-loads avgt 3 14.168 ± 1.931 #/op JMHSample_35_Profilers.Atomic.test:dTLB-store-misses avgt 3 ≈ 10⁻⁶ #/op JMHSample_35_Profilers.Atomic.test:dTLB-stores avgt 3 4.049 ± 0.522 #/op JMHSample_35_Profilers.Atomic.test:iTLB-load-misses avgt 3 ≈ 10⁻⁵ #/op JMHSample_35_Profilers.Atomic.test:iTLB-loads avgt 3 ≈ 10⁻⁴ #/op JMHSample_35_Profilers.Atomic.test:instructions avgt 3 30.377 ± 3.298 #/op
前述のperfコマンドの比較にあった内容、ロードやストア、サイクルなど詳細を出力できます。
perf
java -jar target/benchmarks.jar JMHSample_35.*Atomic -prof perf -f 1を実行します。
Perf stats:
--------------------------------------------------
4240.546824 task-clock (msec) # 0.414 CPUs utilized
228 context-switches # 0.054 K/sec
13 cpu-migrations # 0.003 K/sec
215 page-faults # 0.051 K/sec
17,343,775,811 cycles # 4.090 GHz (38.48%)
20,660,003,479 instructions # 1.19 insn per cycle (46.28%)
3,441,592,748 branches # 811.592 M/sec (46.38%)
883,479 branch-misses # 0.03% of all branches (46.47%)
9,620,830,543 L1-dcache-loads # 2268.771 M/sec (46.56%)
2,252,874 L1-dcache-load-misses # 0.02% of all L1-dcache hits (46.54%)
63,517 LLC-loads # 0.015 M/sec (30.71%)
26,657 LLC-load-misses # 41.97% of all LL-cache hits (30.61%)
<not supported> L1-icache-loads
487,676 L1-icache-load-misses (30.53%)
9,678,899,945 dTLB-loads # 2282.465 M/sec (30.55%)
4,697 dTLB-load-misses # 0.00% of all dTLB cache hits (30.55%)
15,214 iTLB-loads # 0.004 M/sec (30.55%)
1,951 iTLB-load-misses # 12.82% of all iTLB cache hits (30.55%)
<not supported> L1-dcache-prefetches
<not supported> L1-dcache-prefetch-misses
10.236014855 seconds time elapsed
perf statを出力できます。
