読者です 読者をやめる 読者になる 読者になる

ムーアの法則の終わり、そして最近の分岐予測について

ムーアの法則の終わり、そして最近の分岐予測について

僕ら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

なんか前にやろうとしてできなかった気がしたんだけど、今改めて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)

*1:ムーアの法則の初出は1965年だが、IntelがTick-Tockモデルを採用したのは2006年のCoreマイクロアーキテクチャからである。

*2:2002年の頃を思い出して欲しいのだが、21世紀になってまもなくフリーランチの時代は終わっていたのではなかったか?

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.incYARV命令との紐付けはソースコードを上から順に正規表現マッチして見ていくだけですから、あとは命令アドレスとソースコードを紐付けるだけです。

この一見絶望的に困難に思われる仕事ですが、実際はそれほどでもありません。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はつよいというはなし

C Ruby

fluentdな人達と話していると定期的にRubyのオブジェクト生成が遅いとdisられます。

本質的にしょうがない部分もあるんですが、それにしても遅い部分も結構あるので、おもむろにperf statperf 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データとして読めるのか?

結論

ムリ。

何がしたいの

例えばMySQLGZIPのデータが入ってるとき、誰しもこのデータを文字列関数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用?。

まとめ

あきらめてクライアントで解凍しよう。

割り切れてるかの確認を高速化しようとして、コンパイラに負けた話

Ruby

今日見ていきたいのはtime.cquo(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か、1と論理積を取って判定。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でも高速化して景気づけしたいですね。

先日の日記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

はい、簡単でしたね。

当初の予定からはちょっとずれた気もしますが、一パッチできたので今日はこの辺で。