CRubyとLink Time Optimizationについて
最近、夜寝る前に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を導入しなくてもまだ倍速くする余地があるってことですかね……。これをやるのは読者の宿題に残しておくのでぜひ頑張って欲しい。