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

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

はい、簡単でしたね。

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

CRubyとLink Time Optimizationについて

ruby

 最近、夜寝る前にRubyベンチマークを眺めたり、仕事の障害時のログを眺めるっていう悪趣味極まりない習慣がついてしまった。まぁ、草木も眠る丑三つ時にこの世の真理を求めて何かを読みふけるって言うのは、この業界にいる人間なら誰しもがやることなんじゃ無いかと思う。それと同じで現場百遍とも言うとおり、何度もprofileやログを眺めれば何か気付くこともあるんじゃないかと思って読んでいる……というわけではなくて、ふと見たくなる衝動に従っているだけだけど。

 さて、Rubyのprofileを取るときに便利なのがRubyKaigi 2015でこさきさんも紹介していたperf。あまりに便利なせいで、プライベートでLinuxを触る時間が何千倍にも増えたくらい。あの発表はもっぱらperf-topの紹介だったけど、perfの使い方とかを見ると他にも色々な機能があることがわかる。例えば、昨日話題になったひたすらblockを実行するコードを見たくなったら、

% perf record ./miniruby --disable-gem -e'100_000_000.times{}'
% perf report

とすると、

Samples: 8K of event 'cycles', Event count (approx.): 13538619277
 27.11%  miniruby  miniruby            [.] vm_exec_core
 24.59%  miniruby  miniruby            [.] invoke_block_from_c_0
 12.85%  miniruby  miniruby            [.] vm_push_frame.isra.69
 12.76%  miniruby  miniruby            [.] vm_exec
 10.25%  miniruby  miniruby            [.] rb_yield_1
  9.72%  miniruby  miniruby            [.] vm_callee_setup_block_arg
  2.39%  miniruby  miniruby            [.] int_dotimes
  0.22%  miniruby  [kernel.kallsyms]   [k] 0xffffffff8104f45a
  0.01%  miniruby  miniruby            [.] rb_ivar_get
  0.01%  miniruby  miniruby            [.] rb_frozen_class_p
  0.01%  miniruby  miniruby            [.] st_clear
  0.01%  miniruby  miniruby            [.] mix_id_table_insert
  0.01%  miniruby  miniruby            [.] mix_id_table_lookup
  0.01%  miniruby  miniruby            [.] rb_add_method_cfunc
  0.01%  miniruby  miniruby            [.] coderange_scan
  0.01%  miniruby  libc-2.19.so        [.] __libc_calloc
  0.01%  miniruby  miniruby            [.] hash_id_table_insert_key.part.19
  0.01%  miniruby  miniruby            [.] ruby_sip_hash24
  0.01%  miniruby  miniruby            [.] mix_id_table_foreach
  0.01%  miniruby  miniruby            [.] rb_enc_symname_type
  0.00%  miniruby  libc-2.19.so        [.] _int_malloc
  0.00%  miniruby  miniruby            [.] rb_define_method
  0.00%  miniruby  miniruby            [.] fstr_update_callback
  0.00%  miniruby  libc-2.19.so        [.] _IO_file_fopen@@GLIBC_2.2.5
  0.00%  miniruby  miniruby            [.] ruby_init_stack
  0.00%  miniruby  libpthread-2.19.so  [.] pthread_setname_np

Press '?' for help on key bindings

という画面になる。こっからさらにカーソル[→]で各関数についての詳細を見れる。

Annotate vm_exec_core
Zoom into miniruby(26888) thread
Zoom into miniruby DSO
Browse map details
Run scripts for samples of thread [miniruby]
Run scripts for samples of symbol [vm_exec_core]
Run scripts for all samples
Switch to another data file in PWD
Exit

けど、Rubyのprofileを見るって観点だとあまり使えない項目ばかりなので、"Annotate vm_exec_core"を選んで逆アセンブル結果を表示します。

vm_exec_core  /home/naruse/ruby/miniruby
       │          SET_GLOBAL((VALUE)entry, val);
       │        vzerou
       │        callq  rb_gvar_set
       │        jmpq   ffffffffffa33d50
       │        nop
       │      {
       │        VALUE val;
       │
       │
       │        DEBUG_ENTER_INSN("putnil");
       │        ADD_PC(1+0);
       │        lea    0x8(%r14),%rax
       │        mov    %r14,%rcx
  1.66 │        mov    %rax,(%r15)
  0.09 │        mov    %rax,%r14
       │      #line 267 "insns.def"
       │          val = Qnil;
       │
       │      #line 382 "vm.inc"
       │        CHECK_VM_STACK_OVERFLOW_FOR_INSN(REG_CFP, 1);
       │        PUSH(val);
  0.30 │        mov    0x8(%r15),%rax
  0.13 │        movq   $0x8,(%rax)
  8.82 │        add    $0x8,%rax
  0.04 │        mov    %rax,0x8(%r15)
       │        jmpq   ffffffffffa33d50
       │        nop
       │      {
       │        VALUE val;
       │
       │
       │        DEBUG_ENTER_INSN("putself");
       │        ADD_PC(1+0);
       │        lea    0x8(%r14),%rdx
       │        mov    %r14,%rcx
       │      putself
       │      ()
       │      ()
       │      (VALUE val)
       │      {
       │          val = GET_SELF();
       │        mov    0x20(%r15),%rsi
       │        mov    %rdx,(%r15)
       │        mov    %rdx,%r14
       │      #line 281 "insns.def"
       │          val = GET_SELF();
       │
Press 'h' for help on key bindings

この日記の読者は、Cは読めてもアセンブラは読めない人が多いと思うけど、大丈夫、わたしも読めない。いつもぐぐって出てきたページとかを見ながら眺めてます。

さて、この8.82(vm_exec_core中の8%がここ)って出てるところでちょっと時間を食ってるみたいなんだけど、加算命令であるaddでそんなに時間がかかるはずはなくて、たぶん前後のメモリ書き込み命令movを待ってるんじゃ無いかと思う。つまり、わたしごときでは何か出来ることはない。

気を取り直して[←]を押し、他の関数……rb_yield_1を見てみよう。

rb_yield_1  /home/naruse/ruby/miniruby
  5.86 │      sub    $0x18,%rsp
       │      mov    %rdi,0x8(%rsp)
 14.30 │      mov    ruby_current_thread,%rdi
  2.70 │      mov    0x30(%rdi),%rax
  1.69 │      mov    0x28(%rax),%rax
  2.48 │      mov    (%rax),%rsi
 10.70 │      test   $0x2,%sil
       │      jne    35
       │      nop
       │28:   and    $0xfffffffffffffffc,%rsi
       │      mov    (%rsi),%rsi
       │      test   $0x2,%sil
       │      je     28
  3.38 │35:   and    $0xfffffffffffffffc,%rsi
       │      je     59
  3.15 │      mov    (%rsi),%rdx
 28.83 │      pushq  $0x1
       │      xor    %r9d,%r9d
       │      mov    $0x1,%ecx
       │      pushq  $0x0
  4.62 │      lea    0x18(%rsp),%r8
       │      callq  invoke_block_from_c_0
 22.18 │      add    $0x28,%rsp
  0.11 │      retq
       │59:   lea    pathname_too_long.9784+0x500,%rdi
       │      xor    %edx,%edx
       │      mov    $0x8,%esi
       │      callq  rb_vm_localjump_error

短いですね。[s]を押すとCのソースが消えてアセンブラだけになり、30行無いことがわかります。

二桁の数値がいくつも踊っているけど、単に短いからなのでそこは気にするところではなくて、気にするのはこの長さならinlineしてよくね?ってとこですね。inlineされていない理由は簡単は、単にrb_yield_1()はvm_eval.cにあって、それを呼んでるint_dotimes() ——この関数が何者かわかりますね?—— はnumeric.cにいるからですね。

じゃあinline化したら速くなるのかな?というのは気になるところで、int_dotimesをvm_eval.cに持ってきてもいいんだけど(よくないけど)、最近のコンパイラにはリンク時にオブジェクトファイルをまたいでinline化とかをしてくれる超技術Link Time Optimizationってのがついているので使って見ましょう。optflags='-O3 -fno-fast-math -march=native -flto'などと追加してビルドし、profileを取ってみます。

BEFORE:
 Performance counter stats for './miniruby --disable-gem -e100_000_000.times{}':

       5153.515293 task-clock (msec)         #    0.997 CPUs utilized
               123 context-switches          #    0.024 K/sec
                 1 cpu-migrations            #    0.000 K/sec
               873 page-faults               #    0.169 K/sec
       14894914453 cycles                    #    2.890 GHz
        5256063515 stalled-cycles-frontend   #   35.29% frontend cycles idle
   <not supported> stalled-cycles-backend
       37123557344 instructions              #    2.49  insns per cycle
                                             #    0.14  stalled cycles per insn
        5304912019 branches                  # 1029.377 M/sec
            202652 branch-misses             #    0.00% of all branches

       5.170935973 seconds time elapsed

AFTER:
 Performance counter stats for './miniruby --disable-gem -e100_000_000.times{}':

       4456.424594 task-clock (msec)         #    0.997 CPUs utilized
               269 context-switches          #    0.060 K/sec
                 2 cpu-migrations            #    0.000 K/sec
               823 page-faults               #    0.185 K/sec
       13179265879 cycles                    #    2.957 GHz
        3793118960 stalled-cycles-frontend   #   28.78% frontend cycles idle
   <not supported> stalled-cycles-backend
       36422695065 instructions              #    2.76  insns per cycle
                                             #    0.10  stalled cycles per insn
        5004776248 branches                  # 1123.047 M/sec
            147323 branch-misses             #    0.00% of all branches

       4.471030258 seconds time elapsed

2割ほど速くなったようです。 ついでにint_dotimesを見てみると、さっきはrb_yield_1()の中にいた、rb_yieldやinvoke_block_from_c_0()を呼ぶコードがinline化されていることがわかりますね。

int_dotimes  /home/naruse/ruby/miniruby
       │       mov    %rbp,%rbx                                                                    ▒
       │       sar    %rbx                                                                         ▒
       │       test   %rbx,%rbx                                                                    ▒
       │       jle    a9                                                                           ▒
       │       lea    0x8(%rsp),%r12                                                               ▒
       │       xor    %r13d,%r13d                                                                  ▒
       │       nop                                                                                 ▒
  5.38 │ 40:   mov    ruby_current_thread,%rdi                                                     ▒
       │       lea    0x1(%r13,%r13,1),%rax                                                        ▒
       │       mov    %rax,0x8(%rsp)                                                               ▒
 16.46 │       mov    0x30(%rdi),%rax                                                              ▒
       │       mov    0x28(%rax),%rax                                                              ▒
  0.67 │       mov    (%rax),%rsi                                                                  ▒
 14.33 │       test   $0x2,%sil                                                                    ▒
  7.39 │       jne    7d                                                                           ▒
       │       data32 data32 data32 data32 nopw %cs:0x0(%rax,%rax,1)                               ▒
       │ 70:   and    $0xfffffffffffffffc,%rsi                                                     ▒
       │       mov    (%rsi),%rsi                                                                  ▒
       │       test   $0x2,%sil                                                                    ◆
       │       je     70                                                                           ▒
  6.61 │ 7d:   and    $0xfffffffffffffffc,%rsi                                                     ▒
       │       je     13a                                                                          ▒
  0.11 │       mov    (%rsi),%rdx                                                                  ▒
 23.07 │       pushq  $0x1                                                                         ▒
       │       xor    %r9d,%r9d                                                                    ▒
       │       mov    %r12,%r8                                                                     ▒
       │       pushq  $0x0                                                                         ▒
  6.49 │       mov    $0x1,%ecx                                                                    ▒
       │       add    $0x1,%r13                                                                    ▒
       │       callq  invoke_block_from_c_0.lto_priv.567                                           ▒
 18.81 │       pop    %rax                                                                         ▒
  0.11 │       pop    %rdx                                                                         ▒
  0.56 │       cmp    %r13,%rbx                                                                    ▒
       │       jne    40                                                                           ▒
       │ a9:   add    $0x18,%rsp                                                                   ▒
       │       mov    %rbp,%rax                                                                    ▒
       │       pop    %rbx                                                                         ▒
       │       pop    %rbp                                                                         ▒
       │       pop    %r12                                                                         ▒
       │       pop    %r13                                                                         ▒
       │       retq                                                                                ▒
       │       nop                                                                                 ▒
       │ c0:   mov    %rbx,%rdi                                                                    ▒
       │       callq  rb_yield                                                                     ▒
       │       mov    %rbx,%rdi                                                                    ▒
       │       mov    $0x3,%ecx                                                                    ▒
       │       xor    %eax,%eax                                                                    ▒
Press 'h' for help on key bindings

ちなみに、スピード狂の方々はご存じでしょうが、Rubyでループを最速に回せるのはwhileで、その場合の結果は以下のような感じでした。

 Performance counter stats for './miniruby --disable-gem -ei=0;while i<100_000_000;i+=1;end':

       2071.648179 task-clock (msec)         #    0.998 CPUs utilized
                35 context-switches          #    0.017 K/sec
                 2 cpu-migrations            #    0.001 K/sec
               878 page-faults               #    0.424 K/sec
        6041423503 cycles                    #    2.916 GHz
        2493938546 stalled-cycles-frontend   #   41.28% frontend cycles idle
   <not supported> stalled-cycles-backend
       14520079387 instructions              #    2.40  insns per cycle
                                             #    0.17  stalled cycles per insn
        1504280501 branches                  #  726.127 M/sec
            116788 branch-misses             #    0.01% of all branches

       2.076396582 seconds time elapsed

Samples: 3K of event 'cycles', Event count (approx.): 6014184501
 99.69%  miniruby  miniruby           [.] vm_exec_core
  0.25%  miniruby  [kernel.kallsyms]  [k] 0xffffffff8104f45a
  0.02%  miniruby  miniruby           [.] rb_class_foreach_subclass
  0.01%  miniruby  miniruby           [.] st_lookup
  0.01%  miniruby  miniruby           [.] ruby_sip_hash24
  0.01%  miniruby  miniruby           [.] rb_wb_protected_newobj_of
  0.01%  miniruby  miniruby           [.] rb_freeze_singleton_class
  0.01%  miniruby  miniruby           [.] fc_i
  0.00%  miniruby  miniruby           [.] thread_timer

バイトコードコンパイルする際にエスケープ解析とかすればJITを導入しなくてもまだ倍速くする余地があるってことですかね……。これをやるのは読者の宿題に残しておくのでぜひ頑張って欲しい。