ムーアの法則の終わり、そして最近の分岐予測について
ムーアの法則の終わり、そして最近の分岐予測について
序
僕らx86の大地の上に生きるものは、この10年Intelが告げるTick-Tockの鐘の音にあわせてムーアの法則の恩恵を享受してきた。*1 *2 しかし、Kaby Lakeの14nmプロセス採用つまり、2年おきのプロセスルール刷新を諦めたことを持って、ムーアの法則は終焉を迎えたとされる。が、この認識は本当に正しいのだろうか。
ムーアの1965年の論文では、後のムーアの法則を”The complexity for minimum component costs has increased at a rate of roughly a factor of two per year"と表現している。人々はこの”complexity"は単位面積あたりのトランジスタ数のことだとこの50年間理解してきた。もっと言えばこの10年はプロセス・ルールのことだったかもしれない。だが、CPUがその内に集積してきたものはトランジスタだけだったのだろうか。
前述の論文のタイトルは"Cramming more components onto integrated circuits”という。Intelは様々なものをCPUという集積回路に詰め込んできた。しかし、このタイトルとムーアの法則の記述をあわせれば、真にCPUが集積したものが何かは明らかだろう。それは「複雑さ」だ。多数のSIMD命令も、AVXの奇怪なVEXエンコーディングも、すべてこの世界の複雑さを小さな魔法の石に封じ込めた結果なのだ。
分岐予測の進化
さて、高度なCPUにはブラックボックスが多数含まれますが、分岐予測はその中の最たるものの一つでしょう。CPUの最適化情報豊富なIntel® 64 and IA-32 Architectures Optimization Reference Manualを見ても毎度"Improved branch predictor."としか書かれていません。
とはいえ、手元にCPUはあるわけで、実際に動かしてその実力を測ることは出来るので測ってみましょう。
計測に使ったのはSpeed of various interpreter dispatch techniques V2のthreading.tar.gzの./directです。現代においてこれが適切なベンチマークだとは思わないのですが、間接分岐については多少参考にはなるんじゃないかな……。
SandyBridge
naruse@chkbuild008:~/threading$ grep -m1 'model name' /proc/cpuinfo model name : Intel(R) Xeon(R) CPU E5-2630L 0 @ 2.00GHz naruse@chkbuild008:~/threading$ perf stat ./direct-gcc48 Performance counter stats for './direct': 277.440861 task-clock (msec) # 0.998 CPUs utilized 5 context-switches # 0.018 K/sec 0 cpu-migrations # 0.000 K/sec 112 page-faults # 0.404 K/sec 650,780,115 cycles # 2.346 GHz [82.74%] 365,836,274 stalled-cycles-frontend # 56.22% frontend cycles idle [82.72%] 377,885,001 stalled-cycles-backend # 58.07% backend cycles idle [67.70%] 423,892,636 instructions # 0.65 insns per cycle # 0.89 stalled cycles per insn [84.15%] 208,884,768 branches # 752.898 M/sec [84.14%] 12,251,769 branch-misses # 5.87% of all branches [82.71%] 0.278114864 seconds time elapsed naruse@chkbuild008:~/threading$ perf stat ../direct-gcc54 Performance counter stats for '../direct-gcc54': 155.542201 task-clock (msec) # 0.996 CPUs utilized 3 context-switches # 0.019 K/sec 0 cpu-migrations # 0.000 K/sec 113 page-faults # 0.726 K/sec 352,393,558 cycles # 2.266 GHz [82.03%] 141,991,479 stalled-cycles-frontend # 40.29% frontend cycles idle [82.23%] 160,691,365 stalled-cycles-backend # 45.60% backend cycles idle [69.17%] 379,813,966 instructions # 1.08 insns per cycle # 0.42 stalled cycles per insn [84.58%] 160,216,299 branches # 1030.050 M/sec [84.57%] 3,933 branch-misses # 0.00% of all branches [82.03%] 0.156168350 seconds time elapsed
Ivy Bridge
% grep -m1 'model name' /proc/cpuinfo model name : Intel(R) Xeon(R) CPU E5-2650 v2 @ 2.60GHz % perf stat ../direct-gcc48 Performance counter stats for '../direct-gcc48': 238.146900 task-clock (msec) # 0.982 CPUs utilized 37 context-switches # 0.155 K/sec 0 cpu-migrations # 0.000 K/sec 42 page-faults # 0.176 K/sec 689162737 cycles # 2.894 GHz 403352479 stalled-cycles-frontend # 58.53% frontend cycles idle <not supported> stalled-cycles-backend 430913321 instructions # 0.63 insns per cycle # 0.94 stalled cycles per insn 210172241 branches # 882.532 M/sec 14205738 branch-misses # 6.76% of all branches 0.242429416 seconds time elapsed % perf stat ./direct-gcc54 Performance counter stats for './direct-gcc54': 120.812507 task-clock (msec) # 0.996 CPUs utilized 0 context-switches # 0.000 K/sec 0 cpu-migrations # 0.000 K/sec 41 page-faults # 0.339 K/sec 355605784 cycles # 2.943 GHz 170213145 stalled-cycles-frontend # 47.87% frontend cycles idle <not supported> stalled-cycles-backend 380562594 instructions # 1.07 insns per cycle # 0.45 stalled cycles per insn 160106383 branches # 1325.247 M/sec 9808 branch-misses # 0.01% of all branches 0.121333298 seconds time elapsed
Haswell
% grep -m1 'model name' /proc/cpuinfo model name : Intel(R) Xeon(R) CPU E5-2660 v3 @ 2.60GHz % perf stat ./direct Performance counter stats for './direct': 159.226456 task-clock:u (msec) # 0.996 CPUs utilized 0 context-switches:u # 0.000 K/sec 0 cpu-migrations:u # 0.000 K/sec 35 page-faults:u # 0.220 K/sec 321780650 cycles:u # 2.021 GHz 380085245 instructions:u # 1.18 insn per cycle 160015808 branches:u # 1004.957 M/sec 5206 branch-misses:u # 0.00% of all branches 0.159844405 seconds time elapsed % perf stat ../direct-gcc48 Performance counter stats for '../direct-gcc48': 205.179841 task-clock:u (msec) # 0.995 CPUs utilized 0 context-switches:u # 0.000 K/sec 0 cpu-migrations:u # 0.000 K/sec 36 page-faults:u # 0.175 K/sec 448041978 cycles:u # 2.184 GHz 430085324 instructions:u # 0.96 insn per cycle 210015836 branches:u # 1023.570 M/sec 4887 branch-misses:u # 0.00% of all branches 0.206141759 seconds time elapsed % perf stat ../direct-gcc54 Performance counter stats for '../direct': 158.532437 task-clock:u (msec) # 0.995 CPUs utilized 0 context-switches:u # 0.000 K/sec 0 cpu-migrations:u # 0.000 K/sec 35 page-faults:u # 0.221 K/sec 315471369 cycles:u # 1.990 GHz 380085288 instructions:u # 1.20 insn per cycle 160015810 branches:u # 1009.357 M/sec 6829 branch-misses:u # 0.00% of all branches 0.159275797 seconds time elapsed
Skylake
% grep -m1 'model name' /proc/cpuinfo model name : Intel(R) Xeon(R) CPU E3-1245 v5 @ 3.50GHz % perf stat ./direct Performance counter stats for './direct': 84.458565 task-clock (msec) # 0.996 CPUs utilized 0 context-switches # 0.000 K/sec 0 cpu-migrations # 0.000 K/sec 38 page-faults # 0.450 K/sec 300759565 cycles # 3.561 GHz 380503237 instructions # 1.27 insn per cycle 160093203 branches # 1895.524 M/sec 9349 branch-misses # 0.01% of all branches 0.084794713 seconds time elapsed % perf stat ../direct-gcc54 Performance counter stats for '../direct': 101.940704 task-clock (msec) # 0.996 CPUs utilized 0 context-switches # 0.000 K/sec 0 cpu-migrations # 0.000 K/sec 37 page-faults # 0.363 K/sec 361064330 cycles # 3.542 GHz 380540900 instructions # 1.05 insn per cycle 160100883 branches # 1570.530 M/sec 18006 branch-misses # 0.01% of all branches 0.102305561 seconds time elapsed
訂正: 初出の記事ではSkylakeの値が-O3にしたものになっていました。-Oだと以上の通りです。
考察
所要時間はCPUの周波数も影響するのでその分は差し引いてみてくださいね。（本当はTurbo Boostオフにするべきなんだけど、手元のマシンじゃないんだゴメンな……）
考察と言ってもそこまで詳しいわけではないので実のあることは言えないのですが、今でもその進化が続いていることは見ればわかるでしょう。また、分岐予測に詳しい人ほど最近のIntel CPUの分岐予測的中率には驚かれるのではないかと思いました。
まとめ
あんまり賢い解説もないまま締めに入りますが、あんまり最近のIntel CPUの分岐予測について言及した記事って英語含めてもないと思うので、これで盛り上がって誰か解説してくれるといいなと思います！
追記
Sandy Bridgeが著しく悪かったのはgcc5.4以降が賢いからっぽい。
gcc (Ubuntu 4.8.4-2ubuntu1~14.04.3) 4.8.4 Copyright (C) 2013 Free Software Foundation, Inc. This is free software; see the source for copying conditions. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. 000000000040052d <main>: 40052d: 48 8b 35 2c 0b 20 00 mov 0x200b2c(%rip),%rsi # 601060 <prog.1723> 400534: 48 89 f2 mov %rsi,%rdx 400537: b9 80 96 98 00 mov $0x989680,%ecx 40053c: b8 68 10 60 00 mov $0x601068,%eax 400541: ff e2 jmpq *%rdx 400543: 48 8b 10 mov (%rax),%rdx 400546: 48 8d 40 08 lea 0x8(%rax),%rax 40054a: eb f5 jmp 400541 <main+0x14> 40054c: 48 8b 10 mov (%rax),%rdx 40054f: 48 8d 40 08 lea 0x8(%rax),%rax 400553: eb ec jmp 400541 <main+0x14> 400555: 48 8b 10 mov (%rax),%rdx 400558: 48 8d 40 08 lea 0x8(%rax),%rax 40055c: eb e3 jmp 400541 <main+0x14> 40055e: 48 8b 10 mov (%rax),%rdx 400561: 48 8d 40 08 lea 0x8(%rax),%rax 400565: eb da jmp 400541 <main+0x14> 400567: 48 8b 10 mov (%rax),%rdx 40056a: 48 8d 40 08 lea 0x8(%rax),%rax 40056e: eb d1 jmp 400541 <main+0x14> 400570: 85 c9 test %ecx,%ecx 400572: 7e 0d jle 400581 <main+0x54> 400574: 83 e9 01 sub $0x1,%ecx 400577: 48 89 f2 mov %rsi,%rdx 40057a: b8 68 10 60 00 mov $0x601068,%eax 40057f: eb c0 jmp 400541 <main+0x14> 400581: 48 83 ec 08 sub $0x8,%rsp 400585: bf 00 00 00 00 mov $0x0,%edi 40058a: e8 a1 fe ff ff callq 400430 <exit@plt> 40058f: 90 nop
% gcc --version gcc (Ubuntu 5.4.0-6ubuntu1~16.04.2) 5.4.0 20160609 Copyright (C) 2015 Free Software Foundation, Inc. This is free software; see the source for copying conditions. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. 0000000000400526 <main>: [37/1887] 400526: 48 8b 35 33 0b 20 00 mov 0x200b33(%rip),%rsi # 601060 <prog.1832> 40052d: 48 89 f2 mov %rsi,%rdx 400530: b9 80 96 98 00 mov $0x989680,%ecx 400535: b8 68 10 60 00 mov $0x601068,%eax 40053a: eb 07 jmp 400543 <main+0x1d> 40053c: 48 8b 10 mov (%rax),%rdx 40053f: 48 8d 40 08 lea 0x8(%rax),%rax 400543: ff e2 jmpq *%rdx 400545: 48 8b 10 mov (%rax),%rdx 400548: 48 8d 40 08 lea 0x8(%rax),%rax 40054c: eb f5 jmp 400543 <main+0x1d> 40054e: 48 8b 10 mov (%rax),%rdx 400551: 48 8d 40 08 lea 0x8(%rax),%rax 400555: eb ec jmp 400543 <main+0x1d> 400557: 48 8b 10 mov (%rax),%rdx 40055a: 48 8d 40 08 lea 0x8(%rax),%rax 40055e: eb e3 jmp 400543 <main+0x1d> 400560: 48 8b 10 mov (%rax),%rdx 400563: 48 8d 40 08 lea 0x8(%rax),%rax 400567: eb da jmp 400543 <main+0x1d> 400569: 85 c9 test %ecx,%ecx 40056b: 7e 0d jle 40057a <main+0x54> 40056d: 83 e9 01 sub $0x1,%ecx 400570: 48 89 f2 mov %rsi,%rdx 400573: b8 68 10 60 00 mov $0x601068,%eax 400578: eb c9 jmp 400543 <main+0x1d> 40057a: 48 83 ec 08 sub $0x8,%rsp 40057e: bf 00 00 00 00 mov $0x0,%edi 400583: e8 88 fe ff ff callq 400410 <exit@plt> 400588: 0f 1f 84 00 00 00 00 nopl 0x0(%rax,%rax,1) 40058f: 00
追記2
かと思われたが、HaswellだとGCC4.8で作ったバイナリでも分岐予測ミスは0.00%だった。なお、GCC4.8バイナリをIvy Bridgeマシンで実行するとSandyと大差ない結果なので、分岐予測能力はSandyでもそれなりにすごくて、Haswellはもっとすごいってことかな。
追記3
Intel CPUの分岐予測の進化面白いです。 https://t.co/y1t7zEEJn7
— suzaki (@KuniSuzaki) 2016年8月16日
更に求めるとコンパイラによる PGO: Profile Guided Optimization との効果との比較がないものでしょうか。 https://t.co/JWwHZvcvmR
なんか前にやろうとしてできなかった気がしたんだけど、今改めてGCCのマニュアル見たら-fprofile-generateつけて-fprofile-useつけるだけだった。
% perf stat ./direct
Performance counter stats for './direct':
121.760309 task-clock (msec) # 0.993 CPUs utilized
2 context-switches # 0.016 K/sec
0 cpu-migrations # 0.000 K/sec
42 page-faults # 0.345 K/sec
353933863 cycles # 2.907 GHz
167429077 stalled-cycles-frontend # 47.31% frontend cycles idle
<not supported> stalled-cycles-backend
380553084 instructions # 1.08 insns per cycle
# 0.44 stalled cycles per insn
160104472 branches # 1314.915 M/sec
7542 branch-misses # 0.00% of all branches
0.122630111 seconds time elapsed
0000000000400526 <main>:
400526: 48 8b 0d 33 0b 20 00 mov 0x200b33(%rip),%rcx # 601060 <prog.1832>
40052d: 48 89 ca mov %rcx,%rdx
400530: be 80 96 98 00 mov $0x989680,%esi
400535: b8 68 10 60 00 mov $0x601068,%eax
40053a: eb 07 jmp 400543 <main+0x1d>
40053c: 48 8b 10 mov (%rax),%rdx
40053f: 48 8d 40 08 lea 0x8(%rax),%rax
400543: ff e2 jmpq *%rdx
400545: 48 8b 10 mov (%rax),%rdx
400548: 48 8d 40 08 lea 0x8(%rax),%rax
40054c: eb f5 jmp 400543 <main+0x1d>
40054e: 48 8b 10 mov (%rax),%rdx
400551: 48 8d 40 08 lea 0x8(%rax),%rax
400555: eb ec jmp 400543 <main+0x1d>
400557: 48 8b 10 mov (%rax),%rdx
40055a: 48 8d 40 08 lea 0x8(%rax),%rax
40055e: eb e3 jmp 400543 <main+0x1d>
400560: 48 8b 10 mov (%rax),%rdx
400563: 48 8d 40 08 lea 0x8(%rax),%rax
400567: eb da jmp 400543 <main+0x1d>
400569: 85 f6 test %esi,%esi
40056b: 7e 0d jle 40057a <main+0x54>
40056d: 83 ee 01 sub $0x1,%esi
400570: 48 89 ca mov %rcx,%rdx
400573: b8 68 10 60 00 mov $0x601068,%eax
400578: eb c9 jmp 400543 <main+0x1d>
40057a: 48 83 ec 08 sub $0x8,%rsp
40057e: bf 00 00 00 00 mov $0x0,%edi
400583: e8 88 fe ff ff callq 400410 <exit@plt>
400588: 0f 1f 84 00 00 00 00 nopl 0x0(%rax,%rax,1)
40058f: 00
あんまかわりませんね。
ちなみに-O3だと以下のような調子なので、最適化レベルを上げると意味がある模様。
% gcc -O3 -fomit-frame-pointer direct.c -o direct
direct.c:4:1: warning: return type defaults to 'int' [-Wimplicit-int]
main()
^
direct.c: In function 'main':
direct.c:32:3: warning: implicit declaration of function 'exit' [-Wimplicit-function-declaration]
exit(0);
^
direct.c:32:3: warning: incompatible implicit declaration of built-in function 'exit'
direct.c:32:3: note: include '<stdlib.h>' or provide a declaration of 'exit'
# 1471360659 0:17:39 naruse@tk2-243-31075:~/threading
% perf stat ./direct
Performance counter stats for './direct':
46.157782 task-clock (msec) # 0.980 CPUs utilized
0 context-switches # 0.000 K/sec
0 cpu-migrations # 0.000 K/sec
41 page-faults # 0.888 K/sec
135493298 cycles # 2.935 GHz
49319786 stalled-cycles-frontend # 36.40% frontend cycles idle
<not supported> stalled-cycles-backend
320446132 instructions # 2.37 insns per cycle
# 0.15 stalled cycles per insn
110085385 branches # 2384.980 M/sec
6551 branch-misses # 0.01% of all branches
0.047097047 seconds time elapsed
0000000000400430 <main>:
400430: 48 8b 35 29 0c 20 00 mov 0x200c29(%rip),%rsi # 601060 <prog.1832>
400437: b9 80 96 98 00 mov $0x989680,%ecx
40043c: b8 68 10 60 00 mov $0x601068,%eax
400441: ff e6 jmpq *%rsi
400443: 0f 1f 44 00 00 nopl 0x0(%rax,%rax,1)
400448: 85 c9 test %ecx,%ecx
40044a: 7e 64 jle 4004b0 <main+0x80>
40044c: 83 e9 01 sub $0x1,%ecx
40044f: b8 68 10 60 00 mov $0x601068,%eax
400454: ff e6 jmpq *%rsi
400456: 66 2e 0f 1f 84 00 00 nopw %cs:0x0(%rax,%rax,1)
40045d: 00 00 00
400460: 48 8b 10 mov (%rax),%rdx
400463: 48 83 c0 08 add $0x8,%rax
400467: ff e2 jmpq *%rdx
400469: 0f 1f 80 00 00 00 00 nopl 0x0(%rax)
400470: 48 8b 10 mov (%rax),%rdx
400473: 48 83 c0 08 add $0x8,%rax
400477: ff e2 jmpq *%rdx
400479: 0f 1f 80 00 00 00 00 nopl 0x0(%rax)
400480: 48 8b 10 mov (%rax),%rdx
400483: 48 83 c0 08 add $0x8,%rax
400487: ff e2 jmpq *%rdx
400489: 0f 1f 80 00 00 00 00 nopl 0x0(%rax)
400490: 48 8b 10 mov (%rax),%rdx
400493: 48 83 c0 08 add $0x8,%rax
400497: ff e2 jmpq *%rdx
400499: 0f 1f 80 00 00 00 00 nopl 0x0(%rax)
4004a0: 48 8b 10 mov (%rax),%rdx
4004a3: 48 83 c0 08 add $0x8,%rax
4004a7: ff e2 jmpq *%rdx
4004a9: 0f 1f 80 00 00 00 00 nopl 0x0(%rax)
4004b0: 48 83 ec 08 sub $0x8,%rsp
4004b4: 31 ff xor %edi,%edi
4004b6: e8 55 ff ff ff callq 400410 <exit@plt>
4004bb: 0f 1f 44 00 00 nopl 0x0(%rax,%rax,1)
% gcc -O3 -fprofile-use -fomit-frame-pointer direct.c -o direct
direct.c:4:1: warning: return type defaults to 'int' [-Wimplicit-int]
main()
^
direct.c: In function 'main':
direct.c:32:3: warning: implicit declaration of function 'exit' [-Wimplicit-function-declaration]
exit(0);
^
direct.c:32:3: warning: incompatible implicit declaration of built-in function 'exit'
direct.c:32:3: note: include '<stdlib.h>' or provide a declaration of 'exit'
# 1471360636 0:17:16 naruse@tk2-243-31075:~/threading
% perf stat ./direct
Performance counter stats for './direct':
46.108716 task-clock (msec) # 0.981 CPUs utilized
0 context-switches # 0.000 K/sec
0 cpu-migrations # 0.000 K/sec
41 page-faults # 0.889 K/sec
123812228 cycles # 2.685 GHz
39859092 stalled-cycles-frontend # 32.19% frontend cycles idle
<not supported> stalled-cycles-backend
320466395 instructions # 2.59 insns per cycle
# 0.12 stalled cycles per insn
110090077 branches # 2387.620 M/sec
6079 branch-misses # 0.01% of all branches
0.046992565 seconds time elapsed
0000000000400430 <main>:
400430: 48 8b 0d 29 0c 20 00 mov 0x200c29(%rip),%rcx # 601060 <prog.1832>
400437: be 80 96 98 00 mov $0x989680,%esi
40043c: b8 68 10 60 00 mov $0x601068,%eax
400441: ff e1 jmpq *%rcx
400443: 0f 1f 44 00 00 nopl 0x0(%rax,%rax,1)
400448: 48 8b 10 mov (%rax),%rdx
40044b: 48 83 c0 08 add $0x8,%rax
40044f: ff e2 jmpq *%rdx
400451: 0f 1f 80 00 00 00 00 nopl 0x0(%rax)
400458: 4c 8b 18 mov (%rax),%r11
40045b: 48 83 c0 08 add $0x8,%rax
40045f: 41 ff e3 jmpq *%r11
400462: 66 0f 1f 44 00 00 nopw 0x0(%rax,%rax,1)
400468: 85 f6 test %esi,%esi
40046a: 7e 3e jle 4004aa <main+0x7a>
40046c: 83 ee 01 sub $0x1,%esi
40046f: b8 68 10 60 00 mov $0x601068,%eax
400474: ff e1 jmpq *%rcx
400476: 66 2e 0f 1f 84 00 00 nopw %cs:0x0(%rax,%rax,1)
40047d: 00 00 00
400480: 4c 8b 00 mov (%rax),%r8
400483: 48 83 c0 08 add $0x8,%rax
400487: 41 ff e0 jmpq *%r8
40048a: 66 0f 1f 44 00 00 nopw 0x0(%rax,%rax,1)
400490: 4c 8b 08 mov (%rax),%r9
400493: 48 83 c0 08 add $0x8,%rax
400497: 41 ff e1 jmpq *%r9
40049a: 66 0f 1f 44 00 00 nopw 0x0(%rax,%rax,1)
4004a0: 4c 8b 10 mov (%rax),%r10
4004a3: 48 83 c0 08 add $0x8,%rax
4004a7: 41 ff e2 jmpq *%r10
4004aa: 50 push %rax
4004ab: 31 ff xor %edi,%edi
4004ad: e8 5e ff ff ff callq 400410 <exit@plt>
4004b2: 66 2e 0f 1f 84 00 00 nopw %cs:0x0(%rax,%rax,1)
4004b9: 00 00 00
4004bc: 0f 1f 40 00 nopl 0x0(%rax)
YARV命令ごとの実行コストを知るには
プログラムのボトルネックを探すには大きく分けて二つの方法があります。心眼を研ぎ澄ましていきなり最適化してみてから考えるのと、何かしらのツールでサイクル数やCPU時間を計測して地道に探す方法ですね。皆さん普通は前者だと思うんですが、それが行き詰まってしまうこともあります。
後者のようにprofileを取っていく場合、手軽にCレベルでのprofileがとれて今わたしの中で一大ブームを巻き起こしているのがperf(3)なわけですが、Rubyのprofileを取ると往々にして以下のような結果になるわけです。（よい子のみんなはCレベルでのprofileではなく、stackprofを使ってRubyレベルでのprofileをとろうな！）
sudo perf report --stdio --no-children -g none -d miniruby
# To display the perf.data header info, please use --header/--header-only options.
#
# dso: miniruby
#
# Total Lost Samples: 0
#
# Samples: 19K of event 'cycles'
# Event count (approx.): 15175910905
#
# Overhead Command Symbol
# ........ ........ ....................................................
#
52.76% miniruby [.] vm_exec_core
4.07% miniruby [.] rb_vm_cref_replace_with_duplicated_cref
3.02% miniruby [.] rb_callable_method_entry_with_refinements
2.70% miniruby [.] rb_ary_unshift
2.66% miniruby [.] rb_clear_method_cache_by_class
2.25% miniruby [.] vm_call_iseq_setup_normal_0start_1params_4locals
1.91% miniruby [.] ary_ensure_room_for_push
1.43% miniruby [.] match_at
1.12% miniruby [.] st_init_strtable_with_size
1.06% miniruby [.] vm_call_iseq_setup_normal_0start_0params_2locals
0.95% miniruby [.] rb_ary_tmp_new_fill
0.82% miniruby [.] st_init_strtable
0.80% miniruby [.] rb_ary_transpose
0.80% miniruby [.] rb_ary_modify
0.78% miniruby [.] rb_ary_rotate_bang
0.77% miniruby [.] vm_call_iseq_setup_normal_0start_0params_1locals
0.64% miniruby [.] int_and
0.64% miniruby [.] rb_respond_to
0.58% miniruby [.] vm_call_iseq_setup
0.56% miniruby [.] rb_ary_free
0.56% miniruby [.] flo_eql
0.48% miniruby [.] st_init_numtable_with_size
0.46% miniruby [.] vm_exec
0.46% miniruby [.] rb_iv_set
0.44% miniruby [.] gc_mark_children
0.31% miniruby [.] rb_free_method_entry
0.29% miniruby [.] rb_check_convert_type
0.28% miniruby [.] rb_ary_splice
0.27% miniruby [.] rb_mod_protected_method_defined
0.26% miniruby [.] rb_int_rshift
0.25% miniruby [.] ruby_yyparse
0.23% miniruby [.] gc_mark_maybe
0.23% miniruby [.] forward_search_range
0.23% miniruby [.] gc_sweep_step
0.20% miniruby [.] st_foreach
0.19% miniruby [.] rb_ary_initialize
vm_exec_coreというのはYARVの中核である命令ディスパッチ部分ですね。まぁ、そりゃそうなるかという感じではあるのですが、アセンブラで7000命令ほどある関数にぱらぱらと0.xx%の負荷を出されてもどこがボトルネックかわかりません。
そもそも知りたいのはYARV命令ごとの負荷なのですから、その通り集計すればいいはずですね。命令のアドレスとコストは既にあります。insns.defやそれから生成するvm.incとYARV命令との紐付けはソースコードを上から順に正規表現マッチして見ていくだけですから、あとは命令アドレスとソースコードを紐付けるだけです。
この一見絶望的に困難に思われる仕事ですが、実際はそれほどでもありません。gdbでデバッグする際や、RubyがSEGVした時のバックトレースにソースコードのファイル名と行数が出ているのを見た人も多いでしょう。実行バイナリには各種デバッグ用の情報が格納されているので、それを参照すればよいのです。
さぁ、道具は全て揃いました。あとはつなげるだけです。つなげたものは以下の通り。
% ./yarv-profile.rb
opt_aref: 17.75
opt_minus: 13.45
opt_newarray_min: 11.16
opt_newarray_max: 8.40
opt_aset: 6.01
: 5.82
setinstancevariable: 5.45
splatarray: 4.96
checkkeyword: 4.69
opt_plus: 3.73
getinlinecache: 3.13
leave: 2.48
duparray: 2.31
newarray: 2.27
once: 1.97
opt_size: 1.22
adjuststack: 1.07
getlocal: 0.89
branchnil: 0.84
defineclass: 0.80
getglobal: 0.51
invokeblock: 0.48
nop: 0.39
branchif: 0.25
setinlinecache: 0.22
branchunless: 0.12
opt_ge: 0.11
setclassvariable: 0.11
opt_arefで時間を食っているのはまぁよいとして、opt_minusでの時間が多いのはちょっと気になりますね。絶対数が多いだけかな。まぁ今までわかりづらかったことが数値で見えるようになりました。
めでたしめでたし
CRubyとVisual Studio 15
先月「Visual Studio “15” Preview リリース」というニュースがありましたがみなさんはもう試してみましたか?
おそらくCRuby的な意味で試した人は世界でも稀なんじゃないかと思います。MSVC14のときもcl.exeの起動でつまづいていましたが、今回はさらにその前、開発用の環境変数をセットするためのvcvarsall.batが動きません。以下のような感じで適当にレジストリを追加すると動くようになります。
[HKEY_LOCAL_MACHINE\SOFTWARE\WOW6432Node\Microsoft\VisualStudio\SxS] [HKEY_LOCAL_MACHINE\SOFTWARE\WOW6432Node\Microsoft\VisualStudio\SxS\VC7] "15.0"="C:\\Program Files (x86)\\Microsoft Visual Studio\\VS15Preview\\Common7\\IDE\\VC\\" "FrameworkDIR64"="C:\\Program Files (x86)\\Microsoft Visual Studio\\VS15Preview\\" "FrameworkVer64"="4.0" [HKEY_LOCAL_MACHINE\SOFTWARE\WOW6432Node\Microsoft\VisualStudio\SxS\VS7] "15.0"="C:\\Program Files (x86)\\Microsoft Visual Studio\\VS15Preview\\"
これで"\Program Files (x86)\Microsoft Visual Studio\VS15Preview\Common7\IDE\VC\vcvarsall.bat" x64とすれば諸々の環境変数がセットされます。
あとはPATH=\git-sdk-64\usr\bin;\git-sdk-64\cmd;%PATH%して、C:\Program Files (x86)\Microsoft Visual Studio\VS15Preview\Common7\IDE\VC\redist\1033\vcredist_x64.exeのインストールは必要だったっけ……。
現在のtrunkでは満を持してスーパーハックがマージされているので普通にビルドが通るはず……。
投機実行とOut of Orderはつよいというはなし
fluentdな人達と話していると定期的にRubyのオブジェクト生成が遅いとdisられます。
本質的にしょうがない部分もあるんですが、それにしても遅い部分も結構あるので、おもむろにperf statとperf recordを取ってみましょう。
% sudo perf stat -d ./miniruby -e'GC.disable;i=1000000;while (i-=1)>0;Hash.new;end'
Performance counter stats for './miniruby -eGC.disable;i=1000000;while (i-=1)>0;Hash.new;end':
467.629812 task-clock (msec) # 0.993 CPUs utilized
19 context-switches # 0.041 K/sec
2 cpu-migrations # 0.004 K/sec
65547 page-faults # 0.140 M/sec
1356052041 cycles # 2.900 GHz [49.17%]
683406025 stalled-cycles-frontend # 50.40% frontend cycles idle [49.73%]
<not supported> stalled-cycles-backend
1656503729 instructions # 1.22 insns per cycle
# 0.41 stalled cycles per insn [63.34%]
330462548 branches # 706.676 M/sec [63.60%]
447683 branch-misses # 0.14% of all branches [63.93%]
<not supported> L1-dcache-loads:HG
9560448 L1-dcache-load-misses:HG # 0.00% of all L1-dcache hits [63.35%]
0 LLC-loads:HG # 0.000 K/sec [62.52%]
0 LLC-load-misses:HG # 0.00% of all LL-cache hits [49.22%]
0.470869900 seconds time elapsed
% sudo perf record ./miniruby -e'GC.disable;i=1000000;while (i-=1)>0;Hash.new;end'
Lowering default frequency rate to 1750.
Please consider tweaking /proc/sys/kernel/perf_event_max_sample_rate.
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.036 MB perf.data (~1585 samples) ]
% sudo perf report --stdio
# ========
# captured on: Wed Apr 20 15:09:24 2016
# hostname : tk2-243-31075
# os release : 3.13.0-77-generic
# perf version : 3.13.11-ckt32
# arch : x86_64
# nrcpus online : 3
# nrcpus avail : 3
# cpudesc : Intel(R) Xeon(R) CPU E5-2650 v2 @ 2.60GHz
# cpuid : GenuineIntel,6,62,4
# total memory : 2049828 kB
# cmdline : /usr/lib/linux-tools-3.13.0-77/perf record ./miniruby -eGC.disable;i=1000000;while (i-=1
)>0;Hash.new;end
# event : name = cycles, type = 0, config = 0x0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_ke
rn = 0, excl_host = 0, excl_guest = 1, precise_ip = 0, attr_mmap2 = 0, attr_mmap = 1, attr_mmap_dat
a = 0
# HEADER_CPU_TOPOLOGY info available, use -I to display
# HEADER_NUMA_TOPOLOGY info available, use -I to display
# pmu mappings: cpu = 4, software = 1, tracepoint = 2, breakpoint = 5
# ========
#
# Samples: 1K of event 'cycles'
# Event count (approx.): 1582794433
#
# Overhead Command Shared Object Symbol
# ........ ........ .................. ..........................................
#
13.72% miniruby [kernel.kallsyms] [k] clear_page_c_e
9.49% miniruby miniruby [.] vm_exec_core
7.36% miniruby libc-2.19.so [.] _int_malloc
6.15% miniruby miniruby [.] objspace_malloc_increase.isra.67
5.06% miniruby libc-2.19.so [.] malloc
4.10% miniruby libpthread-2.19.so [.] pthread_getspecific
3.97% miniruby libc-2.19.so [.] __libc_calloc
3.78% miniruby [kernel.kallsyms] [k] get_page_from_freelist
3.21% miniruby miniruby [.] rb_wb_protected_newobj_of
3.12% miniruby miniruby [.] rb_obj_call_init
2.98% miniruby miniruby [.] ruby_xcalloc
2.74% miniruby [kernel.kallsyms] [k] async_page_fault
2.28% miniruby miniruby [.] vm_call0_body.constprop.120
1.75% miniruby miniruby [.] vm_call_cfunc
1.44% miniruby miniruby [.] st_init_table_with_size
1.41% miniruby miniruby [.] rb_callable_method_entry
1.10% miniruby miniruby [.] rb_call0
1.08% miniruby [kernel.kallsyms] [k] handle_mm_fault
1.02% miniruby miniruby [.] vm_search_method.isra.77
0.95% miniruby [kernel.kallsyms] [k] __alloc_pages_nodemask
0.94% miniruby [kernel.kallsyms] [k] __mem_cgroup_commit_charge
0.86% miniruby [kernel.kallsyms] [k] __rmqueue
[…]
上位にカーネルやlibc、RubyVM実行エンジンの中心部であるvm_exec_coreが並んでいて、「あ、これは戦う敵を間違えたかな」って雰囲気が若干漂っていますが、強引に目に入ったruby_xcallocに食らいついていきます。いや、こいつただのcallocのラッパのくせに3%近く食ってて生意気じゃないですか。
とりあえずobjdumpで中身を眺めてみましょう。
% ruby -e'/\A0*(\h+)[ .a-z]*\t0*(\h+)/i=~`objdump -t miniruby|grep #{ARGV[0]||abort}`and exec"objdump -d --start-address=0x#{$1} --stop-address=#{"%#x"%[$1.hex+$2.hex]} miniruby|less"' ruby_xcalloc
miniruby: file format elf64-x86-64
Disassembly of section .text:
0000000000496280 <ruby_xcalloc>:
496280: 48 8d 05 51 7a 44 00 lea 0x447a51(%rip),%rax # 8ddcd8 <ruby_current_vm>
496287: 41 54 push %r12
496289: 31 d2 xor %edx,%edx
49628b: 55 push %rbp
49628c: 53 push %rbx
49628d: 48 8b 00 mov (%rax),%rax
496290: 4c 8b a0 30 06 00 00 mov 0x630(%rax),%r12
496297: 48 c7 c0 ff ff ff ff mov $0xffffffffffffffff,%rax
49629e: 48 f7 f6 div %rsi
4962a1: 48 39 c7 cmp %rax,%rdi
4962a4: 0f 87 43 01 00 00 ja 4963ed <ruby_xcalloc+0x16d>
4962aa: 48 89 fb mov %rdi,%rbx
4962ad: 48 0f af de imul %rsi,%rbx
4962b1: 48 85 db test %rbx,%rbx
4962b4: 0f 88 96 00 00 00 js 496350 <ruby_xcalloc+0xd0>
4962ba: b8 01 00 00 00 mov $0x1,%eax
4962bf: 48 0f 44 d8 cmove %rax,%rbx
4962c3: 41 f6 44 24 10 40 testb $0x40,0x10(%r12)
4962c9: 75 45 jne 496310 <ruby_xcalloc+0x90>
4962cb: 48 89 de mov %rbx,%rsi
4962ce: bf 01 00 00 00 mov $0x1,%edi
4962d3: e8 68 11 f8 ff callq 417440 <calloc@plt>
4962d8: 48 89 c5 mov %rax,%rbp
4962db: 48 85 c0 test %rax,%rax
4962de: 0f 84 a4 00 00 00 je 496388 <ruby_xcalloc+0x108>
4962e4: 48 89 ef mov %rbp,%rdi
4962e7: e8 84 10 f8 ff callq 417370 <malloc_usable_size@plt>
4962ec: 4c 89 e7 mov %r12,%rdi
4962ef: b9 01 00 00 00 mov $0x1,%ecx
4962f4: 31 d2 xor %edx,%edx
4962f6: 48 89 c6 mov %rax,%rsi
4962f9: e8 e2 f7 ff ff callq 495ae0 <objspace_malloc_increase.isra.67>
4962fe: 48 89 e8 mov %rbp,%rax
496301: 5b pop %rbx
496302: 5d pop %rbp
496303: 41 5c pop %r12
496305: c3 retq
496306: 66 2e 0f 1f 84 00 00 nopw %cs:0x0(%rax,%rax,1)
49630d: 00 00 00
496310: e8 fb 2f 16 00 callq 5f9310 <ruby_native_thread_p>
496315: 85 c0 test %eax,%eax
496317: 74 b2 je 4962cb <ruby_xcalloc+0x4b>
496319: 49 8b 84 24 b0 01 00 mov 0x1b0(%r12),%rax
496320: 00
496321: 89 c6 mov %eax,%esi
496323: 83 e6 01 and $0x1,%esi
496326: 74 09 je 496331 <ruby_xcalloc+0xb1>
496328: 48 c1 e8 03 shr $0x3,%rax
49632c: 89 c6 mov %eax,%esi
49632e: 83 e6 01 and $0x1,%esi
496331: 41 b8 00 12 00 00 mov $0x1200,%r8d
496337: b9 01 00 00 00 mov $0x1,%ecx
49633c: ba 01 00 00 00 mov $0x1,%edx
496341: 4c 89 e7 mov %r12,%rdi
496344: e8 d7 f6 ff ff callq 495a20 <garbage_collect_with_gvl>
496349: eb 80 jmp 4962cb <ruby_xcalloc+0x4b>
49634b: 0f 1f 44 00 00 nopl 0x0(%rax,%rax,1)
496350: e8 9b a2 15 00 callq 5f05f0 <ruby_thread_has_gvl_p>
496355: 85 c0 test %eax,%eax
496357: 0f 85 a1 00 00 00 jne 4963fe <ruby_xcalloc+0x17e>
49635d: e8 ae 2f 16 00 callq 5f9310 <ruby_native_thread_p>
496362: 85 c0 test %eax,%eax
496364: 0f 84 88 00 00 00 je 4963f2 <ruby_xcalloc+0x172>
49636a: 48 8d 35 af 1a 17 00 lea 0x171aaf(%rip),%rsi # 607e20 <null_device+0x1378>
496371: 48 8d 3d 28 3f ff ff lea -0xc0d8(%rip),%rdi # 48a2a0 <negative_size_allocation_error_with_gvl>
496378: e8 33 e5 15 00 callq 5f48b0 <rb_thread_call_with_gvl>
49637d: e9 41 ff ff ff jmpq 4962c3 <ruby_xcalloc+0x43>
496382: 66 0f 1f 44 00 00 nopw 0x0(%rax,%rax,1)
496388: 41 b8 00 02 00 00 mov $0x200,%r8d
49638e: b9 01 00 00 00 mov $0x1,%ecx
496393: ba 01 00 00 00 mov $0x1,%edx
496398: be 01 00 00 00 mov $0x1,%esi
49639d: 4c 89 e7 mov %r12,%rdi
4963a0: e8 7b f6 ff ff callq 495a20 <garbage_collect_with_gvl>
4963a5: 85 c0 test %eax,%eax
4963a7: 74 1f je 4963c8 <ruby_xcalloc+0x148>
4963a9: 48 89 de mov %rbx,%rsi
4963ac: bf 01 00 00 00 mov $0x1,%edi
4963b1: e8 8a 10 f8 ff callq 417440 <calloc@plt>
4963b6: 48 85 c0 test %rax,%rax
4963b9: 74 0d je 4963c8 <ruby_xcalloc+0x148>
4963bb: 48 89 c5 mov %rax,%rbp
4963be: e9 21 ff ff ff jmpq 4962e4 <ruby_xcalloc+0x64>
4963c3: 0f 1f 44 00 00 nopl 0x0(%rax,%rax,1)
4963c8: e8 23 a2 15 00 callq 5f05f0 <ruby_thread_has_gvl_p>
4963cd: 85 c0 test %eax,%eax
4963cf: 75 51 jne 496422 <ruby_xcalloc+0x1a2>
4963d1: e8 3a 2f 16 00 callq 5f9310 <ruby_native_thread_p>
4963d6: 85 c0 test %eax,%eax
4963d8: 74 43 je 49641d <ruby_xcalloc+0x19d>
4963da: 48 8d 3d 6f d2 ff ff lea -0x2d91(%rip),%rdi # 493650 <ruby_memerror_body>
4963e1: 31 f6 xor %esi,%esi
4963e3: e8 c8 e4 15 00 callq 5f48b0 <rb_thread_call_with_gvl>
4963e8: e9 f7 fe ff ff jmpq 4962e4 <ruby_xcalloc+0x64>
4963ed: e8 0e d5 ff ff callq 493900 <ruby_malloc_size_overflow>
4963f2: 48 8d 3d 27 1a 17 00 lea 0x171a27(%rip),%rdi # 607e20 <null_device+0x1378>
4963f9: e8 63 1b f8 ff callq 417f61 <negative_size_allocation_error.part.52>
4963fe: 48 8d 05 3b b4 44 00 lea 0x44b43b(%rip),%rax # 8e1840 <rb_eNoMemError>
496405: 48 8d 15 14 1a 17 00 lea 0x171a14(%rip),%rdx # 607e20 <null_device+0x1378>
49640c: 48 8d 35 94 b7 18 00 lea 0x18b794(%rip),%rsi # 621ba7 <yytranslate+0x807>
496413: 48 8b 38 mov (%rax),%rdi
496416: 31 c0 xor %eax,%eax
496418: e8 e3 77 fd ff callq 46dc00 <rb_raise>
49641d: e8 6a 1b f8 ff callq 417f8c <garbage_collect_with_gvl.part.65>
496422: e8 89 a2 ff ff callq 4906b0 <rb_memerror>
ん、思ったよりもでかいぞ?
static void * objspace_xcalloc(rb_objspace_t *objspace, size_t count, size_t elsize) { void *mem; size_t size; size = xmalloc2_size(count, elsize); size = objspace_malloc_prepare(objspace, size); TRY_WITH_GC(mem = calloc(1, size)); size = objspace_malloc_size(objspace, mem, size); objspace_malloc_increase(objspace, mem, size, 0, MEMOP_TYPE_MALLOC); return objspace_malloc_fixup(objspace, mem, size); }
ソースを見るに、前半はcallocするサイズの補正、後半はエラー処理系って感じですかね。納得したようなそれでもまだ多すぎるだろうというような気持ちになりつつ改めて逆アセンブルの中身を見ると、冒頭にdivがあります。そういえばこの連載ではdivが遅いのは前提としていましたがちゃんと見た方がいい気がしてきました。
機械語の速度はAgner FogさんのSoftware optimization resourcesにある"Instruction tables"を見るとよいです。以下の表はIvy Bridgeの場合の抜粋ですが、加算がめっちゃ速くて、除算がとても遅いことがわかりますね。（加算とか1クロックで3命令実行すごい）
| Instruction | Operands | Latency | Throughputの逆数 |
|---|---|---|---|
| ADD SUB | r,r/i | 1 | 0.33 |
| MUL IMUL | r64 | 3 | 1 |
| IMUL | r64,r64,i | 3 | 1 |
| DIV | r64 | 29-94 | 22-76 |
さて、このdivはruby_xmalloc2_sizeの中にあります。何をしているかというとオーバーフローチェックですね。正確にはC言語では符号無し整数はオーバーフローしないのでラップアラウンドチェックになります。
static inline size_t ruby_xmalloc2_size(const size_t count, const size_t elsize) { if (count > SIZE_MAX / elsize) { ruby_malloc_size_overflow(count, elsize); } return count * elsize; }
ところで、この種のチェックには二種類あります。チェックせずに実行すると例外が飛ぶゼロ除算エラーみたいなものと、今回のように単に意図と違う値が返ってくるものです。言い換えると、後者はとりあえず実行してからチェックしてもよいと言うことですね。チェックして違った場合、インテル® 64 アーキテクチャー および IA-32 アーキテクチャー 最適化リファレンス・マニュアルによると「分岐予測ミスには、約 20 サイクルのペナルティーが課せられる」のに加えて乗算のコストも無駄になるのですが、今回の場合どうせruby_malloc_size_overflow()なので気にしません。そのようにしてみたパッチと結果が以下の通りです。
diff --git a/include/ruby/ruby.h b/include/ruby/ruby.h index c41465a..4c50dd2 100644 --- a/include/ruby/ruby.h +++ b/include/ruby/ruby.h @@ -1608,13 +1608,15 @@ rb_num2char_inline(VALUE x) void *rb_alloc_tmp_buffer(volatile VALUE *store, long len) RUBY_ATTR_ALLOC_SIZE((2)); void rb_free_tmp_buffer(volatile VALUE *store); NORETURN(void ruby_malloc_size_overflow(size_t, size_t)); +#define UNLIKELY(x) (__builtin_expect(!!(x), 0)) static inline size_t ruby_xmalloc2_size(const size_t count, const size_t elsize) { - if (count > SIZE_MAX / elsize) { + size_t v = count * elsize; + if (UNLIKELY(count > SIZE_MAX / elsize)) { ruby_malloc_size_overflow(count, elsize); } - return count * elsize; + return v; } /* allocates _n_ bytes temporary buffer and stores VALUE including it * in _v_. _n_ may be evaluated twice. */
00000000004961b0 <ruby_xcalloc>: 4961b0: 48 8d 05 21 7b 44 00 lea 0x447b21(%rip),%rax # 8ddcd8 <ruby_current_vm> 4961b7: 41 54 push %r12 4961b9: 31 d2 xor %edx,%edx 4961bb: 55 push %rbp 4961bc: 53 push %rbx 4961bd: 48 89 fb mov %rdi,%rbx 4961c0: 48 0f af de imul %rsi,%rbx 4961c4: 48 8b 00 mov (%rax),%rax 4961c7: 4c 8b a0 30 06 00 00 mov 0x630(%rax),%r12 4961ce: 48 c7 c0 ff ff ff ff mov $0xffffffffffffffff,%rax 4961d5: 48 f7 f6 div %rsi 4961d8: 48 39 c7 cmp %rax,%rdi 4961db: 0f 87 d7 00 00 00 ja 4962b8 <ruby_xcalloc+0x108> 4961e1: 48 85 db test %rbx,%rbx 4961e4: 0f 88 96 00 00 00 js 496280 <ruby_xcalloc+0xd0> 4961ea: b8 01 00 00 00 mov $0x1,%eax 4961ef: 48 0f 44 d8 cmove %rax,%rbx 4961f3: 41 f6 44 24 10 40 testb $0x40,0x10(%r12) 4961f9: 75 45 jne 496240 <ruby_xcalloc+0x90> 4961fb: 48 89 de mov %rbx,%rsi 4961fe: bf 01 00 00 00 mov $0x1,%edi 496203: e8 38 12 f8 ff callq 417440 <calloc@plt> [...]
% sudo perf stat -d ./miniruby -e'GC.disable;i=1000000;while (i-=1)>0;Hash.new;end'
Performance counter stats for './miniruby -eGC.disable;i=1000000;while (i-=1)>0;Hash.new;end':
402.269177 task-clock (msec) # 0.992 CPUs utilized
23 context-switches # 0.057 K/sec
2 cpu-migrations # 0.005 K/sec
65554 page-faults # 0.163 M/sec
1164270325 cycles # 2.894 GHz [48.83%]
539587746 stalled-cycles-frontend # 46.35% frontend cycles idle [49.62%]
<not supported> stalled-cycles-backend
1660044950 instructions # 1.43 insns per cycle
# 0.33 stalled cycles per insn [63.91%]
330545296 branches # 821.702 M/sec [63.92%]
467450 branch-misses # 0.14% of all branches [64.22%]
<not supported> L1-dcache-loads:HG
9303493 L1-dcache-load-misses:HG # 0.00% of all L1-dcache hits [63.35%]
0 LLC-loads:HG # 0.000 K/sec [62.30%]
0 LLC-load-misses:HG # 0.00% of all LL-cache hits [48.70%]
0.405514667 seconds time elapsed
% sudo perf report --stdio
#
# Samples: 1K of event 'cycles'
# Event count (approx.): 1292902007
#
# Overhead Command Shared Object Symbol
# ........ ........ .................. ........................................
#
15.05% miniruby [kernel.kallsyms] [k] clear_page_c_e
8.95% miniruby miniruby [.] objspace_malloc_increase.isra.67
7.57% miniruby libc-2.19.so [.] _int_malloc
7.15% miniruby miniruby [.] vm_exec_core
4.26% miniruby libc-2.19.so [.] malloc
3.93% miniruby libc-2.19.so [.] __libc_calloc
3.44% miniruby [kernel.kallsyms] [k] async_page_fault
3.43% miniruby [kernel.kallsyms] [k] get_page_from_freelist
2.64% miniruby miniruby [.] vm_call0_body.constprop.120
2.37% miniruby miniruby [.] ruby_xcalloc
2.17% miniruby miniruby [.] vm_call_cfunc
1.87% miniruby miniruby [.] rb_call0
1.50% miniruby miniruby [.] rb_callable_method_entry
0.46 → 0.40 なので結構変わりましたね。アセンブラ上ではimul → mov mov mov → div となっていますが、imulとmov mov movが同時に走って、divしながら投機的実行でZFを使うtestb直前まで走っちゃってるんじゃないでしょうか、たぶん。UNLIKELYなしだとそこまで性能向上無かったので、多分他の場所でもっと効いてるんだと思います。
最初はもうちょっと違う話を書くつもりだったんですが長くなったので今日はここまで
GZIPをZlibデータとして読めるのか?
結論
ムリ。
何がしたいの
例えばMySQLにGZIPのデータが入ってるとき、誰しもこのデータを文字列関数とUNCOMPRESS関数だけで解凍できないのだろうかと思うのでは無いでしょうか。
GZIP
+---+---+---+---+---+---+---+---+---+---+=======================+---+---+---+---+---+---+ |ID1|ID2|CM |FLG| MTIME |XFL|OS |...compressed blocks...| CRC32 | ISIZE | +---+---+---+---+---+---+---+---+---+---+=======================+---+---+---+---+---+---+
GZIPは"\x1F\x8B"ではじまり、少々のヘッダの後圧縮データが続き、CRC32、元データのサイズで終わる。
Zlib
+---+---+=====================+---+---+---+---+ |CMF|FLG|...compressed data...| ADLER32 | +---+---+=====================+---+---+---+---+
CMFとFLGの詳細はRFC1950を見ればいいけど、適当なヘッダをでっち上げるという観点だと"\x78\x9C"でよい。のだが、問題は末尾がADLER32だということである。
MySQLのUNCOMPRESS関数
+---+---+---+---+---+---+=====================+---+---+---+---+ | ISIZE |CMF|FLG|...compressed data...| ADLER32 | +---+---+---+---+---+---+=====================+---+---+---+---+
UNCOMPRESSが解凍できるのは、最初に元データの長さをつけたZlibです。
末尾のADLER32が不正な場合解凍に失敗してNULLにされてしまうので、CRC32しかないGZIPデータからは作ることが出来ません……。
なお、先頭に元データのサイズが必要ならZlibのデータも無理じゃないのか？と思うかもしれませんが、こちらはでたらめでも大丈夫です。たぶんUNCOMPRESSED_LENGTH用？。
まとめ
あきらめてクライアントで解凍しよう。
割り切れてるかの確認を高速化しようとして、コンパイラに負けた話
今日見ていきたいのはtime.cのquo(VALUE x, VALUE y)です。akrさんのRuby における 2038年問題の解決で述べられているとおり、RubyのTimeは内部表現にRationalを使えるようになっているので、その辺を司る部品ですね。
static VALUE quo(VALUE x, VALUE y) { VALUE ret; if (FIXNUM_P(x) && FIXNUM_P(y)) { long a, b, c; a = FIX2LONG(x); b = FIX2LONG(y); if (b == 0) rb_num_zerodiv(); c = a / b; if (c * b == a) { return LONG2NUM(c); } } ret = rb_funcall(x, id_quo, 1, y); if (RB_TYPE_P(ret, T_RATIONAL) && RRATIONAL(ret)->den == INT2FIX(1)) { ret = RRATIONAL(ret)->num; } return ret; }
x64アセンブラも見てみましょう。今日はOS Xで開発しているのでotool -tvV miniruby|lessで見ています。また、quo()は全てインライン化されていたので、ここではtime_subsecの逆アセンブル結果を見ていきます。
static VALUE time_subsec(VALUE time) { struct time_object *tobj; GetTimeval(time, tobj); return quo(w2v(wmod(tobj->timew, WINT2FIXWV(TIME_SCALE))), INT2FIX(TIME_SCALE)); }
_time_subsec: # original 0000000100147f10 pushq %rbp 0000000100147f11 movq %rsp, %rbp 0000000100147f14 pushq %r14 0000000100147f16 pushq %rbx 0000000100147f17 subq $0x10, %rsp 0000000100147f1b movq %rdi, %rbx 0000000100147f1e leaq _time_data_type(%rip), %rsi 0000000100147f25 callq _rb_check_typeddata 0000000100147f2a movb 0x30(%rax), %cl 0000000100147f2d andb $0x7, %cl 0000000100147f30 movzbl %cl, %ecx 0000000100147f33 cmpl $0x3, %ecx 0000000100147f36 je 0x100147ff7 0000000100147f3c movq (%rax), %rdi 0000000100147f3f leaq -0x18(%rbp), %rdx 0000000100147f43 leaq -0x20(%rbp), %rcx 0000000100147f47 movl $0x77359401, %esi ## imm = 0x77359401 0000000100147f4c callq _wdivmod 0000000100147f51 movq -0x20(%rbp), %rdi 0000000100147f55 testb $0x1, %dil 0000000100147f59 je 0x100147fa1 0000000100147f5b movq %rdi, %rcx 0000000100147f5e sarq %rcx0000000100147f61 movabsq $0x112e0be826d694b3, %rdx ## imm = 0x112E0BE826D694B3 0000000100147f6b movq %rcx, %rax 0000000100147f6e imulq %rdx 0000000100147f71 movq %rdx, %rax 0000000100147f74 shrq $0x3f, %rax 0000000100147f78 sarq $0x1a, %rdx 0000000100147f7c addq %rax, %rdx 0000000100147f7f imulq $0x3b9aca00, %rdx, %rax ## imm = 0x3B9ACA00 0000000100147f86 cmpq %rcx, %rax 0000000100147f89 jne 0x100147fa1 0000000100147f8b movabsq $0x4000000000000000, %rax ## imm = 0x4000000000000000 0000000100147f95 addq %rdx, %rax 0000000100147f98 js 0x100147fe7 0000000100147f9a leaq 0x1(%rdx,%rdx), %rax 0000000100147f9f jmp 0x100147fde 0000000100147fa1 movq _id_quo(%rip), %rsi 0000000100147fa8 movl $0x1, %edx 0000000100147fad movl $0x77359401, %ecx ## imm = 0x77359401 0000000100147fb2 xorl %eax, %eax 0000000100147fb4 callq _rb_funcall 0000000100147fb9 testb $0x7, %al 0000000100147fbb jne 0x100147fde 0000000100147fbd movq %rax, %rcx 0000000100147fc0 andq $-0x9, %rcx 0000000100147fc4 je 0x100147fde 0000000100147fc6 movq (%rax), %rcx 0000000100147fc9 andq $0x1f, %rcx 0000000100147fcd cmpq $0xf, %rcx 0000000100147fd1 jne 0x100147fde 0000000100147fd3 cmpq $0x3, 0x18(%rax) 0000000100147fd8 jne 0x100147fde 0000000100147fda movq 0x10(%rax), %rax 0000000100147fde addq $0x10, %rsp 0000000100147fe2 popq %rbx 0000000100147fe3 popq %r14 0000000100147fe5 popq %rbp 0000000100147fe6 retq 0000000100147fe7 movq %rdx, %rdi 0000000100147fea addq $0x10, %rsp 0000000100147fee popq %rbx 0000000100147fef popq %r14 0000000100147ff1 popq %rbp 0000000100147ff2 jmp _rb_int2big 0000000100147ff7 leaq _rb_eTypeError(%rip), %rax 0000000100147ffe movq (%rax), %r14 0000000100148001 movq %rbx, %rdi 0000000100148004 callq _rb_obj_class 0000000100148009 movq %rax, %rcx 000000010014800c leaq 0x8228e(%rip), %rsi ## literal pool for: "uninitialized %li\013" 0000000100148013 xorl %eax, %eax 0000000100148015 movq %r14, %rdi 0000000100148018 movq %rcx, %rdx 000000010014801b callq _rb_raise
とりあえず、その前にこのLONG2NUMですが、このquoって基本割る数yが定数で使われるので、LONG2FIXを使うようにしましょうか。
a = FIX2LONG(x);
b = FIX2LONG(y);
if (b == 0) rb_num_zerodiv();
+ if (b == -1) LONG2NUM(-a);
c = a / b;
if (c * b == a) {
- return LONG2NUM(c);
+ return LONG2FIX(c);
}
}
ret = rb_funcall(x, id_quo, 1, y);
とすると、以下の通り_rb_int2bigが消えます。
_time_subsec: # use Fixnum 0000000100146f30 pushq %rbp 0000000100146f31 movq %rsp, %rbp 0000000100146f34 pushq %r14 0000000100146f36 pushq %rbx 0000000100146f37 subq $0x10, %rsp 0000000100146f3b movq %rdi, %rbx 0000000100146f3e leaq _time_data_type(%rip), %rsi 0000000100146f45 callq _rb_check_typeddata 0000000100146f4a movb 0x30(%rax), %cl 0000000100146f4d andb $0x7, %cl 0000000100146f50 movzbl %cl, %ecx 0000000100146f53 cmpl $0x3, %ecx 0000000100146f56 je 0x100146ff8 0000000100146f5c movq (%rax), %rdi 0000000100146f5f leaq -0x18(%rbp), %rdx 0000000100146f63 leaq -0x20(%rbp), %rcx 0000000100146f67 movl $0x77359401, %esi ## imm = 0x77359401 0000000100146f6c callq _wdivmod 0000000100146f71 movq -0x20(%rbp), %rdi 0000000100146f75 testb $0x1, %dil 0000000100146f79 je 0x100146fb2 0000000100146f7b movq %rdi, %rcx 0000000100146f7e sarq %rcx 0000000100146f81 movabsq $0x112e0be826d694b3, %rdx ## imm = 0x112E0BE826D694B3 0000000100146f8b movq %rcx, %rax 0000000100146f8e imulq %rdx 0000000100146f91 movq %rdx, %rax 0000000100146f94 shrq $0x3f, %rax 0000000100146f98 sarq $0x1a, %rdx 0000000100146f9c addq %rax, %rdx 0000000100146f9f imulq $0x3b9aca00, %rdx, %rax ## imm = 0x3B9ACA00 0000000100146fa6 cmpq %rcx, %rax 0000000100146fa9 jne 0x100146fb2 0000000100146fab leaq 0x1(%rdx,%rdx), %rax 0000000100146fb0 jmp 0x100146fef 0000000100146fb2 movq _id_quo(%rip), %rsi 0000000100146fb9 movl $0x1, %edx 0000000100146fbe movl $0x77359401, %ecx ## imm = 0x77359401 0000000100146fc3 xorl %eax, %eax 0000000100146fc5 callq _rb_funcall 0000000100146fca testb $0x7, %al 0000000100146fcc jne 0x100146fef 0000000100146fce movq %rax, %rcx 0000000100146fd1 andq $-0x9, %rcx 0000000100146fd5 je 0x100146fef 0000000100146fd7 movq (%rax), %rcx 0000000100146fda andq $0x1f, %rcx 0000000100146fde cmpq $0xf, %rcx 0000000100146fe2 jne 0x100146fef 0000000100146fe4 cmpq $0x3, 0x18(%rax) 0000000100146fe9 jne 0x100146fef 0000000100146feb movq 0x10(%rax), %rax 0000000100146fef addq $0x10, %rsp 0000000100146ff3 popq %rbx 0000000100146ff4 popq %r14 0000000100146ff6 popq %rbp 0000000100146ff7 retq 0000000100146ff8 leaq _rb_eTypeError(%rip), %rax 0000000100146fff movq (%rax), %r14 0000000100147002 movq %rbx, %rdi 0000000100147005 callq _rb_obj_class 000000010014700a movq %rax, %rcx 000000010014700d leaq 0x8228d(%rip), %rsi ## literal pool for: "uninitialized %li\013" 0000000100147014 xorl %eax, %eax 0000000100147016 movq %r14, %rdi 0000000100147019 movq %rcx, %rdx 000000010014701c callq _rb_raise 0000000100147021 nopw %cs:(%rax,%rax)
さて、今回のコードを見てまず注目したいのはc * b == aです。これは直前のa / bが割り切れたかを確認しているのですね。しかし、前回の記事を読んだ方ならピーンとくるのではないでしょうか。そう、/と%はコンパイラが一つにまとめてくれます。コンパイラにこのコードの意図を教えてあげましょう。
a = FIX2LONG(x);
b = FIX2LONG(y);
if (b == 0) rb_num_zerodiv();
+ if (b == -1) LONG2NUM(-a);
c = a / b;
- if (c * b == a) {
- return LONG2NUM(c);
+ if (a % b == 0) {
+ return LONG2FIX(c);
}
}
ret = rb_funcall(x, id_quo, 1, y);
0000000100147ecc callq _wdivmod 0000000100147ed1 movq -0x20(%rbp), %rdi 0000000100147ed5 testb $0x1, %dil 0000000100147ed9 je 0x100147f0b 0000000100147edb movq %rdi, %rcx 0000000100147ede sarq %rcx 0000000100147ee1 movabsq $0x112e0be826d694b3, %rsi ## imm = 0x112E0BE826D694B3 0000000100147eeb movq %rcx, %rax 0000000100147eee imulq %rsi 0000000100147ef1 movq %rdx, %rax 0000000100147ef4 shrq $0x3f, %rax 0000000100147ef8 sarq $0x1a, %rdx 0000000100147efc addq %rax, %rdx 0000000100147eff imulq $0x3b9aca00, %rdx, %rax ## imm = 0x3B9ACA00 0000000100147f06 cmpq %rax, %rcx 0000000100147f09 je 0x100147f4a 0000000100147f0b movq _id_quo(%rip), %rsi 0000000100147f12 movl $0x1, %edx 0000000100147f17 movl $0x77359401, %ecx ## imm = 0x77359401 0000000100147f1c xorl %eax, %eax 0000000100147f1e callq _rb_funcall 0000000100147f23 testb $0x7, %al 0000000100147f25 jne 0x100147f63 0000000100147f27 movq %rax, %rcx 0000000100147f2a andq $-0x9, %rcx 0000000100147f2e je 0x100147f63 0000000100147f30 movq (%rax), %rcx 0000000100147f33 andq $0x1f, %rcx 0000000100147f37 cmpq $0xf, %rcx 0000000100147f3b jne 0x100147f63 0000000100147f3d cmpq $0x3, 0x18(%rax) 0000000100147f42 jne 0x100147f63 0000000100147f44 movq 0x10(%rax), %rax 0000000100147f48 jmp 0x100147f63 0000000100147f4a movq %rcx, %rax 0000000100147f4d imulq %rsi 0000000100147f50 movq %rdx, %rax 0000000100147f53 shrq $0x3f, %rax 0000000100147f57 sarq $0x1a, %rdx 0000000100147f5b addq %rax, %rdx 0000000100147f5e leaq 0x1(%rdx,%rdx), %rax 0000000100147f63 addq $0x10, %rsp 0000000100147f67 popq %rbx 0000000100147f68 popq %r14 0000000100147f6a popq %rbp 0000000100147f6b retq
……わかりづらいと思いますが、命令数が増えています。ていうか、そもそもアセンブラに前回登場したidivがいません、ふしぎ。
これは、定数の除算がコンパイル時点で乗算とシフトに置き換えられているからです。整数の割り算を掛け算に変換のシリーズが詳しいので解説は譲り、ここでは動きだけ確認しましょう。
- callq _wdivmod # wmodから戻ってくる
- movq -0x20(%rbp), %rdi # 戻り値を%rdiに入れる
- testb $0x1, %dil # 戻り値がFixnumか、１と論理積を取って判定。Fixnumの場合、VALUEは最下位ビットが1です。なお、これはquo(x, y)のxで、yは1000000000で定数なので消えています。
- je 0x100147f0b # ZFが0の時にジャンプ。つまり、Fixnumならジャンプしません
- movq %rdi, %rcx # %rdiの内容を%rcxにコピー
- sarq %rcx # rcx >> = 1 # つまり、xの数値です
- movabsq $0x112e0be826d694b3, %rsiに謎の値を入れる
- movq %rcx, %rax # %rcxの内容を%raxにコピー
- imulq %rsi # %rsi * %rax を計算し、下位64bitを%raxに、上位64bitを%rdxに入れます
- movq %rdx, %rax # %rdxを%raxにコピー
- shrq $0x3f, %rax # rax >>= 0x3f # 符号維持63bit右シフト
- sarq $0x1a, %rdx # rdx >>= 0x1a # 20bit右シフト
- addq %rax, %rdx %rdxに%raxを足す
- imulq $0x3b9aca00, %rdx, %rax # %rdx * 0x3b9aca00 を %raxにいれる (0x3b9aca00 == 1000000000)
- cmpq %rax, %rcx一致したか確認
微妙な誤差の調整を除いてまとめると、だいたい(123456789000000000*0x112e0be826d694b3)>>(64+0x1a) == 123456789ってとこですね。
同じ割り算を連続して行うようなアプリケーションならば、このような最適化をその都度行ってJIT的に処理すると言うことも考えられますが、Rubyだとちょっとやりづらいですかねぇ。
さて、今回は既にコンパイラが十分に最適化していたため、目立った成果はありませんでした。次回こそ頑張りましょう。
Bignumの10進文字列化を速くしよう
んー、花粉症がひどいし、ここはぱーっとRubyでも高速化して景気づけしたいですね。
先日の日記 でRubyとCしか読めないこの日記の読者の皆さんも、アセンブラに親しみが持てるようになったのではないかと思います。せっかくなので、引き続きこの方向で頑張ってみましょう。
さて、3年前、akrさんが一度はマージしながらも断念した、Use 128 bit integer type in Bignumという案件があります。今日はここから始めます。同時期に公開された資料に「プログラミング言語 Ruby に GMP を組み込む」というものがあります。読むとakrさんの思想の一端が垣間見え、それはしばしばRubyの仕様に影響を与えたりしなくもないのですが、それはまた別の話。どうも1000bitあたりの基数変換(2進→10進 文字列化) が遅かったみたいですね。
しかし、冷静になって考えてみましょう。32bitでの計算を64bitで計算して遅くなるはずがありません。どこかに遅くしている犯人がいるに違いない。また、天下のIntel様の誇る21世紀のCPUや、人類の叡智の結晶GCCが悪いはずもないでしょう。つまり、CRubyが悪いに決まっています。容疑者が絞れたので、早速今日もperfを使ってみましょう。
./miniruby -ve'n=Random.new.random_number(2**1000);n.to_s while 1'
などと雑なマイクロベンチマークを回しつつ、sudo perf topで見てみましょう。
64.53% miniruby [.] big2str_2bdigits 21.09% miniruby [.] bigdivrem1 5.10% miniruby [.] big2str_karatsuba 1.98% miniruby [.] bary_addc.constprop.35 0.82% miniruby [.] bigdivrem_restoring 0.69% miniruby [.] power_cache_get_power 0.60% libc-2.19.so [.] _int_free
big2str_2bdigitsが1番のボトルネックみたいですね。詳細を見ます。
0.04 │ 3c: movslq 0x10(%rbx),%rdi ▒
0.00 │ lea ruby_digitmap,%r9 ▒
│ movslq 0x4(%rbx),%rcx ▒
0.03 │ nop ▒
0.10 │ 50:┌─ mov %rsi,%rax ▒
1.42 │ │ xor %edx,%edx ▒
0.10 │ │ sub $0x1,%rdi ▒
0.04 │ │ div %rcx ▒
58.45 │ │ movzbl (%r9,%rdx,1),%eax ▒
6.47 │ │ xor %edx,%edx ▒
│ │ mov %al,(%r8,%rdi,1) ▒
1.69 │ │ movslq 0x4(%rbx),%rcx ▒
0.11 │ │ mov %rsi,%rax ▒
│ │ div %rcx ▒
27.79 │ │ mov %rax,%rsi ▒
0.03 │ │ test %rdi,%rdi ▒
│ └──jne 50 ▒
│ movslq 0x10(%rbx),%rbp ▒
0.09 │ 7d: add %rbp,0x20(%rbx) ▒
│ 81: mov 0x48(%rsp),%rax ▒
│ xor %fs:0x28,%rax
さて、ここで気付くのは最内ループにdivが2個あることです。Cソースを見ると、
p = b2s->ptr;
j = b2s->hbase2_numdigits;
do {
p[--j] = ruby_digitmap[num % b2s->base];
num /= b2s->base;
} while (j);
len = b2s->hbase2_numdigits;
となっており、%と/の2回ですね。しかたないね…じゃなくて、待って欲しい。割り算の商と余りは一度に両方出せる。人間でも知ってますね。GCC様が知らないはずがありません。書き方を工夫してみましょう。
p = b2s->ptr;
j = b2s->hbase2_numdigits;
do {
long idx = num % b2s->base;
num /= b2s->base;
p[--j] = ruby_digitmap[idx];
} while (j);
len = b2s->hbase2_numdigits;
これならGCCも理解できたようで、無事divが1つになりました。
4291b0: 48 63 73 04 movslq 0x4(%rbx),%rsi 4291b4: 31 d2 xor %edx,%edx 4291b6: 48 83 e9 01 sub $0x1,%rcx 4291ba: 48 f7 f6 div %rsi 4291bd: 41 0f b6 14 10 movzbl (%r8,%rdx,1),%edx 4291c2: 88 14 0f mov %dl,(%rdi,%rcx,1) 4291c5: 48 85 c9 test %rcx,%rcx 4291c8: 75 e6 jne 4291b0 <big2str_2bdigits+0x50> 4291ca: 48 63 6b 10 movslq 0x10(%rbx),%rbp 4291ce: 48 01 6b 20 add %rbp,0x20(%rbx) 4291d2: 48 8b 44 24 48 mov 0x48(%rsp),%rax 4291d7: 64 48 33 04 25 28 00 xor %fs:0x28,%rax
BEFORE:
% perf stat ./miniruby -ve'1000000.times{1394009519767279294246510141478471797669978954897613915557413368048327134214313607298484892788729181350733701973860680235136215859195604566916047459319639591913564242295277658139309044846000010192944937354743647901341274278586535726609303298455111458383678266601931358370666199705386621791721556094289.to_s}'
ruby 2.4.0dev (2016-03-14 trunk 54096) [x86_64-linux]
Performance counter stats for './miniruby -ve1000000.times{1394009519767279294246510141478471797669978954897613915557413368048327134214313607298484892788729181350733701973860680235136215859195604566916047459319639591913564242295277658139309044846000010192944937354743647901341274278586535726609303298455111458383678266601931358370666199705386621791721556094289.to_s}':
8686.042902 task-clock (msec) # 0.999 CPUs utilized
136 context-switches # 0.016 K/sec
2 cpu-migrations # 0.000 K/sec
1288 page-faults # 0.148 K/sec
25492506980 cycles # 2.935 GHz
13225449435 stalled-cycles-frontend # 51.88% frontend cycles idle
<not supported> stalled-cycles-backend
22023197929 instructions # 0.86 insns per cycle
# 0.60 stalled cycles per insn
3213414500 branches # 369.951 M/sec
4716993 branch-misses # 0.15% of all branches
8.695071305 seconds time elapsed
AFTER (r54102):
% perf stat ./miniruby -ve'1000000.times{1394009519767279294246510141478471797669978954897613915557413368048327134214313607298484892788729181350733701973860680235136215859195604566916047459319639591913564242295277658139309044846000010192944937354743647901341274278586535726609303298455111458383678266601931358370666199705386621791721556094289.to_s}'
ruby 2.4.0dev (2016-03-14 trunk 54096) [x86_64-linux]
Performance counter stats for './miniruby -ve1000000.times{1394009519767279294246510141478471797669978954897613915557413368048327134214313607298484892788729181350733701973860680235136215859195604566916047459319639591913564242295277658139309044846000010192944937354743647901341274278586535726609303298455111458383678266601931358370666199705386621791721556094289.to_s}':
6391.824784 task-clock (msec) # 0.999 CPUs utilized
134 context-switches # 0.021 K/sec
3 cpu-migrations # 0.000 K/sec
1287 page-faults # 0.201 K/sec
18756613064 cycles # 2.934 GHz
9833932236 stalled-cycles-frontend # 52.43% frontend cycles idle
<not supported> stalled-cycles-backend
20548725389 instructions # 1.10 insns per cycle
# 0.48 stalled cycles per insn
3212938017 branches # 502.664 M/sec
4574367 branch-misses # 0.14% of all branches
6.400175165 seconds time elapsed
はい、簡単でしたね。
当初の予定からはちょっとずれた気もしますが、一パッチできたので今日はこの辺で。
