割り切れてるかの確認を高速化しようとして、コンパイラに負けた話
今日見ていきたいのはtime.cのquo(VALUE x, VALUE y)です。akrさんのRuby における 2038年問題の解決で述べられているとおり、RubyのTimeは内部表現にRationalを使えるようになっているので、その辺を司る部品ですね。
static VALUE quo(VALUE x, VALUE y) { VALUE ret; if (FIXNUM_P(x) && FIXNUM_P(y)) { long a, b, c; a = FIX2LONG(x); b = FIX2LONG(y); if (b == 0) rb_num_zerodiv(); c = a / b; if (c * b == a) { return LONG2NUM(c); } } ret = rb_funcall(x, id_quo, 1, y); if (RB_TYPE_P(ret, T_RATIONAL) && RRATIONAL(ret)->den == INT2FIX(1)) { ret = RRATIONAL(ret)->num; } return ret; }
x64アセンブラも見てみましょう。今日はOS Xで開発しているのでotool -tvV miniruby|lessで見ています。また、quo()は全てインライン化されていたので、ここではtime_subsecの逆アセンブル結果を見ていきます。
static VALUE time_subsec(VALUE time) { struct time_object *tobj; GetTimeval(time, tobj); return quo(w2v(wmod(tobj->timew, WINT2FIXWV(TIME_SCALE))), INT2FIX(TIME_SCALE)); }
_time_subsec: # original 0000000100147f10 pushq %rbp 0000000100147f11 movq %rsp, %rbp 0000000100147f14 pushq %r14 0000000100147f16 pushq %rbx 0000000100147f17 subq $0x10, %rsp 0000000100147f1b movq %rdi, %rbx 0000000100147f1e leaq _time_data_type(%rip), %rsi 0000000100147f25 callq _rb_check_typeddata 0000000100147f2a movb 0x30(%rax), %cl 0000000100147f2d andb $0x7, %cl 0000000100147f30 movzbl %cl, %ecx 0000000100147f33 cmpl $0x3, %ecx 0000000100147f36 je 0x100147ff7 0000000100147f3c movq (%rax), %rdi 0000000100147f3f leaq -0x18(%rbp), %rdx 0000000100147f43 leaq -0x20(%rbp), %rcx 0000000100147f47 movl $0x77359401, %esi ## imm = 0x77359401 0000000100147f4c callq _wdivmod 0000000100147f51 movq -0x20(%rbp), %rdi 0000000100147f55 testb $0x1, %dil 0000000100147f59 je 0x100147fa1 0000000100147f5b movq %rdi, %rcx 0000000100147f5e sarq %rcx0000000100147f61 movabsq $0x112e0be826d694b3, %rdx ## imm = 0x112E0BE826D694B3 0000000100147f6b movq %rcx, %rax 0000000100147f6e imulq %rdx 0000000100147f71 movq %rdx, %rax 0000000100147f74 shrq $0x3f, %rax 0000000100147f78 sarq $0x1a, %rdx 0000000100147f7c addq %rax, %rdx 0000000100147f7f imulq $0x3b9aca00, %rdx, %rax ## imm = 0x3B9ACA00 0000000100147f86 cmpq %rcx, %rax 0000000100147f89 jne 0x100147fa1 0000000100147f8b movabsq $0x4000000000000000, %rax ## imm = 0x4000000000000000 0000000100147f95 addq %rdx, %rax 0000000100147f98 js 0x100147fe7 0000000100147f9a leaq 0x1(%rdx,%rdx), %rax 0000000100147f9f jmp 0x100147fde 0000000100147fa1 movq _id_quo(%rip), %rsi 0000000100147fa8 movl $0x1, %edx 0000000100147fad movl $0x77359401, %ecx ## imm = 0x77359401 0000000100147fb2 xorl %eax, %eax 0000000100147fb4 callq _rb_funcall 0000000100147fb9 testb $0x7, %al 0000000100147fbb jne 0x100147fde 0000000100147fbd movq %rax, %rcx 0000000100147fc0 andq $-0x9, %rcx 0000000100147fc4 je 0x100147fde 0000000100147fc6 movq (%rax), %rcx 0000000100147fc9 andq $0x1f, %rcx 0000000100147fcd cmpq $0xf, %rcx 0000000100147fd1 jne 0x100147fde 0000000100147fd3 cmpq $0x3, 0x18(%rax) 0000000100147fd8 jne 0x100147fde 0000000100147fda movq 0x10(%rax), %rax 0000000100147fde addq $0x10, %rsp 0000000100147fe2 popq %rbx 0000000100147fe3 popq %r14 0000000100147fe5 popq %rbp 0000000100147fe6 retq 0000000100147fe7 movq %rdx, %rdi 0000000100147fea addq $0x10, %rsp 0000000100147fee popq %rbx 0000000100147fef popq %r14 0000000100147ff1 popq %rbp 0000000100147ff2 jmp _rb_int2big 0000000100147ff7 leaq _rb_eTypeError(%rip), %rax 0000000100147ffe movq (%rax), %r14 0000000100148001 movq %rbx, %rdi 0000000100148004 callq _rb_obj_class 0000000100148009 movq %rax, %rcx 000000010014800c leaq 0x8228e(%rip), %rsi ## literal pool for: "uninitialized %li\013" 0000000100148013 xorl %eax, %eax 0000000100148015 movq %r14, %rdi 0000000100148018 movq %rcx, %rdx 000000010014801b callq _rb_raise
とりあえず、その前にこのLONG2NUMですが、このquoって基本割る数yが定数で使われるので、LONG2FIXを使うようにしましょうか。
a = FIX2LONG(x);
b = FIX2LONG(y);
if (b == 0) rb_num_zerodiv();
+ if (b == -1) LONG2NUM(-a);
c = a / b;
if (c * b == a) {
- return LONG2NUM(c);
+ return LONG2FIX(c);
}
}
ret = rb_funcall(x, id_quo, 1, y);
とすると、以下の通り_rb_int2bigが消えます。
_time_subsec: # use Fixnum 0000000100146f30 pushq %rbp 0000000100146f31 movq %rsp, %rbp 0000000100146f34 pushq %r14 0000000100146f36 pushq %rbx 0000000100146f37 subq $0x10, %rsp 0000000100146f3b movq %rdi, %rbx 0000000100146f3e leaq _time_data_type(%rip), %rsi 0000000100146f45 callq _rb_check_typeddata 0000000100146f4a movb 0x30(%rax), %cl 0000000100146f4d andb $0x7, %cl 0000000100146f50 movzbl %cl, %ecx 0000000100146f53 cmpl $0x3, %ecx 0000000100146f56 je 0x100146ff8 0000000100146f5c movq (%rax), %rdi 0000000100146f5f leaq -0x18(%rbp), %rdx 0000000100146f63 leaq -0x20(%rbp), %rcx 0000000100146f67 movl $0x77359401, %esi ## imm = 0x77359401 0000000100146f6c callq _wdivmod 0000000100146f71 movq -0x20(%rbp), %rdi 0000000100146f75 testb $0x1, %dil 0000000100146f79 je 0x100146fb2 0000000100146f7b movq %rdi, %rcx 0000000100146f7e sarq %rcx 0000000100146f81 movabsq $0x112e0be826d694b3, %rdx ## imm = 0x112E0BE826D694B3 0000000100146f8b movq %rcx, %rax 0000000100146f8e imulq %rdx 0000000100146f91 movq %rdx, %rax 0000000100146f94 shrq $0x3f, %rax 0000000100146f98 sarq $0x1a, %rdx 0000000100146f9c addq %rax, %rdx 0000000100146f9f imulq $0x3b9aca00, %rdx, %rax ## imm = 0x3B9ACA00 0000000100146fa6 cmpq %rcx, %rax 0000000100146fa9 jne 0x100146fb2 0000000100146fab leaq 0x1(%rdx,%rdx), %rax 0000000100146fb0 jmp 0x100146fef 0000000100146fb2 movq _id_quo(%rip), %rsi 0000000100146fb9 movl $0x1, %edx 0000000100146fbe movl $0x77359401, %ecx ## imm = 0x77359401 0000000100146fc3 xorl %eax, %eax 0000000100146fc5 callq _rb_funcall 0000000100146fca testb $0x7, %al 0000000100146fcc jne 0x100146fef 0000000100146fce movq %rax, %rcx 0000000100146fd1 andq $-0x9, %rcx 0000000100146fd5 je 0x100146fef 0000000100146fd7 movq (%rax), %rcx 0000000100146fda andq $0x1f, %rcx 0000000100146fde cmpq $0xf, %rcx 0000000100146fe2 jne 0x100146fef 0000000100146fe4 cmpq $0x3, 0x18(%rax) 0000000100146fe9 jne 0x100146fef 0000000100146feb movq 0x10(%rax), %rax 0000000100146fef addq $0x10, %rsp 0000000100146ff3 popq %rbx 0000000100146ff4 popq %r14 0000000100146ff6 popq %rbp 0000000100146ff7 retq 0000000100146ff8 leaq _rb_eTypeError(%rip), %rax 0000000100146fff movq (%rax), %r14 0000000100147002 movq %rbx, %rdi 0000000100147005 callq _rb_obj_class 000000010014700a movq %rax, %rcx 000000010014700d leaq 0x8228d(%rip), %rsi ## literal pool for: "uninitialized %li\013" 0000000100147014 xorl %eax, %eax 0000000100147016 movq %r14, %rdi 0000000100147019 movq %rcx, %rdx 000000010014701c callq _rb_raise 0000000100147021 nopw %cs:(%rax,%rax)
さて、今回のコードを見てまず注目したいのはc * b == aです。これは直前のa / bが割り切れたかを確認しているのですね。しかし、前回の記事を読んだ方ならピーンとくるのではないでしょうか。そう、/と%はコンパイラが一つにまとめてくれます。コンパイラにこのコードの意図を教えてあげましょう。
a = FIX2LONG(x);
b = FIX2LONG(y);
if (b == 0) rb_num_zerodiv();
+ if (b == -1) LONG2NUM(-a);
c = a / b;
- if (c * b == a) {
- return LONG2NUM(c);
+ if (a % b == 0) {
+ return LONG2FIX(c);
}
}
ret = rb_funcall(x, id_quo, 1, y);
0000000100147ecc callq _wdivmod 0000000100147ed1 movq -0x20(%rbp), %rdi 0000000100147ed5 testb $0x1, %dil 0000000100147ed9 je 0x100147f0b 0000000100147edb movq %rdi, %rcx 0000000100147ede sarq %rcx 0000000100147ee1 movabsq $0x112e0be826d694b3, %rsi ## imm = 0x112E0BE826D694B3 0000000100147eeb movq %rcx, %rax 0000000100147eee imulq %rsi 0000000100147ef1 movq %rdx, %rax 0000000100147ef4 shrq $0x3f, %rax 0000000100147ef8 sarq $0x1a, %rdx 0000000100147efc addq %rax, %rdx 0000000100147eff imulq $0x3b9aca00, %rdx, %rax ## imm = 0x3B9ACA00 0000000100147f06 cmpq %rax, %rcx 0000000100147f09 je 0x100147f4a 0000000100147f0b movq _id_quo(%rip), %rsi 0000000100147f12 movl $0x1, %edx 0000000100147f17 movl $0x77359401, %ecx ## imm = 0x77359401 0000000100147f1c xorl %eax, %eax 0000000100147f1e callq _rb_funcall 0000000100147f23 testb $0x7, %al 0000000100147f25 jne 0x100147f63 0000000100147f27 movq %rax, %rcx 0000000100147f2a andq $-0x9, %rcx 0000000100147f2e je 0x100147f63 0000000100147f30 movq (%rax), %rcx 0000000100147f33 andq $0x1f, %rcx 0000000100147f37 cmpq $0xf, %rcx 0000000100147f3b jne 0x100147f63 0000000100147f3d cmpq $0x3, 0x18(%rax) 0000000100147f42 jne 0x100147f63 0000000100147f44 movq 0x10(%rax), %rax 0000000100147f48 jmp 0x100147f63 0000000100147f4a movq %rcx, %rax 0000000100147f4d imulq %rsi 0000000100147f50 movq %rdx, %rax 0000000100147f53 shrq $0x3f, %rax 0000000100147f57 sarq $0x1a, %rdx 0000000100147f5b addq %rax, %rdx 0000000100147f5e leaq 0x1(%rdx,%rdx), %rax 0000000100147f63 addq $0x10, %rsp 0000000100147f67 popq %rbx 0000000100147f68 popq %r14 0000000100147f6a popq %rbp 0000000100147f6b retq
……わかりづらいと思いますが、命令数が増えています。ていうか、そもそもアセンブラに前回登場したidivがいません、ふしぎ。
これは、定数の除算がコンパイル時点で乗算とシフトに置き換えられているからです。整数の割り算を掛け算に変換のシリーズが詳しいので解説は譲り、ここでは動きだけ確認しましょう。
- callq _wdivmod # wmodから戻ってくる
- movq -0x20(%rbp), %rdi # 戻り値を%rdiに入れる
- testb $0x1, %dil # 戻り値がFixnumか、１と論理積を取って判定。Fixnumの場合、VALUEは最下位ビットが1です。なお、これはquo(x, y)のxで、yは1000000000で定数なので消えています。
- je 0x100147f0b # ZFが0の時にジャンプ。つまり、Fixnumならジャンプしません
- movq %rdi, %rcx # %rdiの内容を%rcxにコピー
- sarq %rcx # rcx >> = 1 # つまり、xの数値です
- movabsq $0x112e0be826d694b3, %rsiに謎の値を入れる
- movq %rcx, %rax # %rcxの内容を%raxにコピー
- imulq %rsi # %rsi * %rax を計算し、下位64bitを%raxに、上位64bitを%rdxに入れます
- movq %rdx, %rax # %rdxを%raxにコピー
- shrq $0x3f, %rax # rax >>= 0x3f # 符号維持63bit右シフト
- sarq $0x1a, %rdx # rdx >>= 0x1a # 20bit右シフト
- addq %rax, %rdx %rdxに%raxを足す
- imulq $0x3b9aca00, %rdx, %rax # %rdx * 0x3b9aca00 を %raxにいれる (0x3b9aca00 == 1000000000)
- cmpq %rax, %rcx一致したか確認
微妙な誤差の調整を除いてまとめると、だいたい(123456789000000000*0x112e0be826d694b3)>>(64+0x1a) == 123456789ってとこですね。
同じ割り算を連続して行うようなアプリケーションならば、このような最適化をその都度行ってJIT的に処理すると言うことも考えられますが、Rubyだとちょっとやりづらいですかねぇ。
さて、今回は既にコンパイラが十分に最適化していたため、目立った成果はありませんでした。次回こそ頑張りましょう。
Bignumの10進文字列化を速くしよう
んー、花粉症がひどいし、ここはぱーっとRubyでも高速化して景気づけしたいですね。
先日の日記 でRubyとCしか読めないこの日記の読者の皆さんも、アセンブラに親しみが持てるようになったのではないかと思います。せっかくなので、引き続きこの方向で頑張ってみましょう。
さて、3年前、akrさんが一度はマージしながらも断念した、Use 128 bit integer type in Bignumという案件があります。今日はここから始めます。同時期に公開された資料に「プログラミング言語 Ruby に GMP を組み込む」というものがあります。読むとakrさんの思想の一端が垣間見え、それはしばしばRubyの仕様に影響を与えたりしなくもないのですが、それはまた別の話。どうも1000bitあたりの基数変換(2進→10進 文字列化) が遅かったみたいですね。
しかし、冷静になって考えてみましょう。32bitでの計算を64bitで計算して遅くなるはずがありません。どこかに遅くしている犯人がいるに違いない。また、天下のIntel様の誇る21世紀のCPUや、人類の叡智の結晶GCCが悪いはずもないでしょう。つまり、CRubyが悪いに決まっています。容疑者が絞れたので、早速今日もperfを使ってみましょう。
./miniruby -ve'n=Random.new.random_number(2**1000);n.to_s while 1'
などと雑なマイクロベンチマークを回しつつ、sudo perf topで見てみましょう。
64.53% miniruby [.] big2str_2bdigits 21.09% miniruby [.] bigdivrem1 5.10% miniruby [.] big2str_karatsuba 1.98% miniruby [.] bary_addc.constprop.35 0.82% miniruby [.] bigdivrem_restoring 0.69% miniruby [.] power_cache_get_power 0.60% libc-2.19.so [.] _int_free
big2str_2bdigitsが1番のボトルネックみたいですね。詳細を見ます。
0.04 │ 3c: movslq 0x10(%rbx),%rdi ▒
0.00 │ lea ruby_digitmap,%r9 ▒
│ movslq 0x4(%rbx),%rcx ▒
0.03 │ nop ▒
0.10 │ 50:┌─ mov %rsi,%rax ▒
1.42 │ │ xor %edx,%edx ▒
0.10 │ │ sub $0x1,%rdi ▒
0.04 │ │ div %rcx ▒
58.45 │ │ movzbl (%r9,%rdx,1),%eax ▒
6.47 │ │ xor %edx,%edx ▒
│ │ mov %al,(%r8,%rdi,1) ▒
1.69 │ │ movslq 0x4(%rbx),%rcx ▒
0.11 │ │ mov %rsi,%rax ▒
│ │ div %rcx ▒
27.79 │ │ mov %rax,%rsi ▒
0.03 │ │ test %rdi,%rdi ▒
│ └──jne 50 ▒
│ movslq 0x10(%rbx),%rbp ▒
0.09 │ 7d: add %rbp,0x20(%rbx) ▒
│ 81: mov 0x48(%rsp),%rax ▒
│ xor %fs:0x28,%rax
さて、ここで気付くのは最内ループにdivが2個あることです。Cソースを見ると、
p = b2s->ptr;
j = b2s->hbase2_numdigits;
do {
p[--j] = ruby_digitmap[num % b2s->base];
num /= b2s->base;
} while (j);
len = b2s->hbase2_numdigits;
となっており、%と/の2回ですね。しかたないね…じゃなくて、待って欲しい。割り算の商と余りは一度に両方出せる。人間でも知ってますね。GCC様が知らないはずがありません。書き方を工夫してみましょう。
p = b2s->ptr;
j = b2s->hbase2_numdigits;
do {
long idx = num % b2s->base;
num /= b2s->base;
p[--j] = ruby_digitmap[idx];
} while (j);
len = b2s->hbase2_numdigits;
これならGCCも理解できたようで、無事divが1つになりました。
4291b0: 48 63 73 04 movslq 0x4(%rbx),%rsi 4291b4: 31 d2 xor %edx,%edx 4291b6: 48 83 e9 01 sub $0x1,%rcx 4291ba: 48 f7 f6 div %rsi 4291bd: 41 0f b6 14 10 movzbl (%r8,%rdx,1),%edx 4291c2: 88 14 0f mov %dl,(%rdi,%rcx,1) 4291c5: 48 85 c9 test %rcx,%rcx 4291c8: 75 e6 jne 4291b0 <big2str_2bdigits+0x50> 4291ca: 48 63 6b 10 movslq 0x10(%rbx),%rbp 4291ce: 48 01 6b 20 add %rbp,0x20(%rbx) 4291d2: 48 8b 44 24 48 mov 0x48(%rsp),%rax 4291d7: 64 48 33 04 25 28 00 xor %fs:0x28,%rax
BEFORE:
% perf stat ./miniruby -ve'1000000.times{1394009519767279294246510141478471797669978954897613915557413368048327134214313607298484892788729181350733701973860680235136215859195604566916047459319639591913564242295277658139309044846000010192944937354743647901341274278586535726609303298455111458383678266601931358370666199705386621791721556094289.to_s}'
ruby 2.4.0dev (2016-03-14 trunk 54096) [x86_64-linux]
Performance counter stats for './miniruby -ve1000000.times{1394009519767279294246510141478471797669978954897613915557413368048327134214313607298484892788729181350733701973860680235136215859195604566916047459319639591913564242295277658139309044846000010192944937354743647901341274278586535726609303298455111458383678266601931358370666199705386621791721556094289.to_s}':
8686.042902 task-clock (msec) # 0.999 CPUs utilized
136 context-switches # 0.016 K/sec
2 cpu-migrations # 0.000 K/sec
1288 page-faults # 0.148 K/sec
25492506980 cycles # 2.935 GHz
13225449435 stalled-cycles-frontend # 51.88% frontend cycles idle
<not supported> stalled-cycles-backend
22023197929 instructions # 0.86 insns per cycle
# 0.60 stalled cycles per insn
3213414500 branches # 369.951 M/sec
4716993 branch-misses # 0.15% of all branches
8.695071305 seconds time elapsed
AFTER (r54102):
% perf stat ./miniruby -ve'1000000.times{1394009519767279294246510141478471797669978954897613915557413368048327134214313607298484892788729181350733701973860680235136215859195604566916047459319639591913564242295277658139309044846000010192944937354743647901341274278586535726609303298455111458383678266601931358370666199705386621791721556094289.to_s}'
ruby 2.4.0dev (2016-03-14 trunk 54096) [x86_64-linux]
Performance counter stats for './miniruby -ve1000000.times{1394009519767279294246510141478471797669978954897613915557413368048327134214313607298484892788729181350733701973860680235136215859195604566916047459319639591913564242295277658139309044846000010192944937354743647901341274278586535726609303298455111458383678266601931358370666199705386621791721556094289.to_s}':
6391.824784 task-clock (msec) # 0.999 CPUs utilized
134 context-switches # 0.021 K/sec
3 cpu-migrations # 0.000 K/sec
1287 page-faults # 0.201 K/sec
18756613064 cycles # 2.934 GHz
9833932236 stalled-cycles-frontend # 52.43% frontend cycles idle
<not supported> stalled-cycles-backend
20548725389 instructions # 1.10 insns per cycle
# 0.48 stalled cycles per insn
3212938017 branches # 502.664 M/sec
4574367 branch-misses # 0.14% of all branches
6.400175165 seconds time elapsed
はい、簡単でしたね。
当初の予定からはちょっとずれた気もしますが、一パッチできたので今日はこの辺で。
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を導入しなくてもまだ倍速くする余地があるってことですかね……。これをやるのは読者の宿題に残しておくのでぜひ頑張って欲しい。
What is nil? No matter. What is nil? Never mind.
"What is nil?" is mysterious question in Ruby. You may answer like "nothing", "nothing exists", or "NULL". Brian, the founder of Rubinius, wrote his thoughts around Lonely operator.
CRuby developers sometimes discussed about nil for example [ruby-dev:29374] nil.to_s. The thread is talked about the behavior of nil.to_s.
The use case of &.
Ruby solves real problem. Ruby's complexity is come from the complexity of the real world. When Ruby adds a new feature, it should be designed for real use case. For example Lonely operator (and the ancestor Object#try! of ActionSupport) are designed for below:
<% if current_user && current_user.premium? %> Hi,<%= current_user.name %>, we offer a new campaign! <% end %>
Rails programmers often write a template like this. In this case, current_user is nil when the user is not login yet; it's actually valid status.
Some people try to define NilClass#method_missing like Brian says. "The Hopelessly Egocentric Blog Post" is a good article about the idea. I summarize the article: don't try it. Rails developed Object#try/try! from the experience. Ruby agreed the conclusion and added &..
The use case of dig
The use case of Hash#dig and Array#dig is JSON from REST API. For example following Redmine's REST API (full result),
{ "issue": { "id": 11537, ... "assigned_to": { "id": 13, "name": "Yukihiro Matsumoto" }, "subject": "Introduce \"Safe navigation operator\"", "done_ratio": 100, "created_on": "2015-09-18T09:29:09Z", "updated_on": "2015-12-05T07:58:25Z", "closed_on": "2015-12-05T07:58:25Z" } }
You can get matz by json.dig('issue', 'assigned_to', 'name') without suffering issue doesn't exist or it is not assigned anyone.
Traceable nils
I don't have a use case for this because I don't have an experience suffered to explore where a nil come from. When I hit "NoMethodError: undefined method `...' for nil:NilClass", it usually come from models. It doesn't need to trace. Or if people hit a trouble the issue is how the nil come from, not where the nil is born, I imagine. Anyway such experiment is interesting. I watch the reaction by developers.
therubyracer considered harmful
要約
therubyracerはやめてexecjsからnodeコマンド使え。
解説
Rails 3.1 で Asset Pipeline が導入されて以来、Gemfileにgem 'therubyracer'と書く人も増えたのではないでしょうか。しかし、それがどの程度のリスクを背負っているのか自覚のない人も多いように感じます。
平時はChrome由来のJavaScriptエンジンであるv8を手軽にインストールできてスーパー便利なtherubyracer.gem & libv8.gemですが、その潜在的なリスクには震えるものがあります。最初にこれが世を騒がせたのは3年前のクリスマス前のことだったでしょうか。
v8
この問題の背景には、本質的に「v8のビルドは難しい」という点があります。雑にバージョンを選ぶとビルドが通りません。そもそもがChromeのためのものだからなんでしょうか。リリースする前に個別にパッチ当ててるんですかね。
libv8.gem
上記のような邪悪を封じ込めたのがlibv8.gemです。libv8.gemがインストールされていれば、楽に利用することが出来ます。バイナリのlibv8.gemが既にあれば楽ですが、時々ありません。例えば、2016年1月8日現在、El Capitan用のバイナリgemはありません。
自分でgemを作る場合は自分でv8もビルドするか、–with-system-v8でbrewなどから入れたv8を使うかを選ぶ必要があります。前者は言うまでもなく大変なのですが（2016年1月8日現在、正常にビルドが通りましたが3分かかりました）、後者もv8とlibv8のバージョン依存問題に加え、一度libv8.gemを作ったあとでうっかりbrew updateするとバイナリgemが壊れることがあります。
therubyracer.gem
therubyracerはlibv8への激しいバージョン依存があります。昔はプラットフォームによって正常にビルドできるlibv8のバージョンが違うのにtherubyracerがそれぞれ別のバージョンになっていてGemfileどう書けばいいんだ…とか泣いてた記憶があるんですが、さすがに今はそういうことはないのかな。
まとめ
以上の通り大変なので、この問題につっこんでいくことは特段の必要性が無い限り避けるべきです。（特段の必要性というのは、たとえば細かいJavaScriptコードを何度も繰り返し実行する必要がある、とかです）RailsのAsset Pipeラインの場合、execjsを用いてnodeコマンドを叩くことが出来ます。nodeコマンドならどのプラットフォームかによらず、いつでも簡単に新しいものを入れられるので安心安全です。無駄な仕事を減らして高い生産性を保ちましょう。
RubyとGit for Windows
序
人は誰しも理想郷を求めるものだし求めてしまうものだろう。「最強のUnix環境」、これもまたそうしたユートピアの一つである。
21世紀の正常な判断能力を持った人間ならば、ユートピアを探し求めることは諦めて、OS Xこそが現実的なデスクトップUNIX環境だと認め、林檎の木の下で日々を暮らし、1日17回だったり2週間に1度、現実的なサーバー用UnixであるLinuxサーバーにdeployして生活の糧を得るものだ。
しかし、やはり人はユートピアを求めてしまうものだし、正常な判断能力を失ってしまったプログラマにはよりにもよってWindows上にそれを求めてしまう頭の不自由な人もいる。この記事はそうした人に向けた、2015年末での状況を述べたものです。
さて、アベノミクス以来の円安もあり、2015年に大きく生活環境が変わった人も多いと思いますが、Windows上でのUnix環境にとっても2015年は大きな変化のあった年でした。OpenSSH for Windowsは話題性の割に正直どうでもいいのですが、Git for Windowsは福音と言っていいでしょう。
そもそも昨年くらいからMinGW64の安定、MSYS2の登場とパッケージマネージャpacmanの移植など、Unix on Windows業界は活気づいてはいました。しかし一方で勃興期にありがちな「結局どれとどれを入れてどう設定すれば正解なのかわからん」という問題を抱えていました。
Git for Windows SDK
さて、Git for Windowsの何が福音かって、彼らはgitのビルド環境をきちんと整備してGit for Windows SDKとして別リポジトリで公開しているところなのです。
意気揚々とMSYS2単体を入れた人は誰しもその3秒後gccすら入っていない上に、聞きかじったpacmanでgccを入れようとすると無数に現れる候補に途方に暮れてウィンドウをそっと閉じると思うのですが、Git for Windows SDKならばそんなことはありません！リンク先からexeを拾ってきていつものようにNextを連打すれば、必要なものはだいたいあらかじめインストールしてくれます。とはいえ、Rubyのビルドに必要なものが全て入っているわけでは無いので、pacman -S autoconf bison rubyしましょう。
追記
OpenSSLのライブラリはどこから入れるんだというご質問を頂きました。それは Git for Windows SDK ではなく、LibreSSLのDLLを取ってくるのが現代では一番簡単です。詳しくは RubyをWindows上でVisual C++でビルドする をご覧ください。
ruby
Rubyのビルドは特にトラブル無く通るはずです。MSYSに慣れていない人はインストール先の指定がMSYSでのパスではなく、Windows側のパスであることに注意しましょう。
調子に乗ってtest-allを走らせるとそうそうにこけますが、これは読者の宿題としておきます。Enjoy debugging Ruby and MinGW!!!
Ruby 2.3.0 released
Ruby 2.3.0 Releasedでした。皆さんお疲れ様でした。
リリーススケジュールとしては今回は例年になくぐだぐだで、リリース直前までブランチを切らなかったのも1.9系の仕様が安定した1.9.1以降では異例のことです。もっとも、これはCIが整備されたことで形式的なブランチ作成による隔離無しのリリースエンジニアリングが可能になったのだと肯定的に評価していきたい。
preview1が出てから盛り上がるという人の性の理解が足りていなかったのは反省点で、来年は夏くらいには出したいですね。（今回、夏頃にはまだ目玉機能が入っていなかったという事情もあるのだが）
来年は、mingwのCIや、CIをコミットごとに走らせる仕組みが欲しいです。
