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

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

今日見ていきたいのは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と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世紀の正常な判断能力を持った人間A pragmatic programmerならば、ユートピアを探し求めることは諦めて、OS Xこそが現実的なデスクトップUNIX環境だと認め、林檎の木の下で日々を暮らし、1日17回だったり2週間に1度、現実的なサーバー用UnixであるLinuxサーバーにdeployして生活の糧を得るものだ。

 しかし、やはり人はユートピアを求めてしまうものだし、正常な判断能力を失ってしまったプログラマプログラマにはよりにもよってWindows上にそれを求めてしまう頭の不自由な人interixやcygwinで懲りない人もいる。この記事はそうした人に向けた、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すら入っていない上に、聞きかじったpacmangccを入れようとすると無数に現れる候補に途方に暮れてウィンドウをそっと閉じると思うのですが、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をコミットごとに走らせる仕組みが欲しいです。