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

この一見絶望的に困難に思われる仕事ですが、実際はそれほどでもありません。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での時間が多いのはちょっと気になりますね。絶対数が多いだけかな。まぁ今までわかりづらかったことが数値で見えるようになりました。

めでたしめでたし