wassup?

プログラミング、ボドゲ、ボカロ

Rubyのtrace命令の話を確かめる

過去のblogから移動しました 元公開日時 2017-12-31 06:10:19

こんばんは。
この記事はKMCアドベントカレンダー23日目の記事です。大遅刻です。

前日の記事はprimeさんの
ビット演算マニアのためのAVX512入門 【KMCアドベントカレンダー 22日目】 - prime's diaryです

明日の記事はtetsutalowさんの
3つの事件で振り返る「何をやったらウイルス罪で捕まるか2017」 - Tetsu=TaLowの雑記(はてブロ版)です

本題

Ruby 2.5 の改善を自慢したい

インターンの講義でお世話になった笹田さんの上の記事を読みました。
その記述を確かめながら小ネタにしようと思います。

次の素朴なコードのベンチマークを見てください。

require 'benchmark'
Benchmark.bmbm 10 do |r|
  r.report "Normal" do
    1000000.times {
      a = 0
      b = 1
      100.times {
        c = a + b
        a = b
        b = c
      }
    }
  end
  r.report "Boost" do
  boost %q(
    1000000.times {
      a = 0
      b = 1
      100.times {
        c = a + b
        a = b
        b = c
      }
    }
  )
  end
  //省略
end
                 user     system      total        real
Normal       9.510000   0.130000   9.640000 ( 10.713862)
Boost        8.590000   0.090000   8.680000 (  9.021931)

Boostのほうが速いようです。
boost %q()で囲むだけでちょっと速くなっているようにみえます。

ねたばらし

boostの実装は以下のとおりです。

def boost src
  eval src.gsub("\n", ";")
end

引数の文字列の改行全てをセミコロンに置き換えて実行するだけです。

すなわち次のコードより

a = 1 + 2
b = 3 + a

このコードの方がちょっと速くなるということです

a = 1 + 2;b = 3 + a

なんでだろう?

結論としては, trace命令が減ったからです。

RubyVM

YARV

VMコードを見るには

  puts RubyVM::InstructionSequence.compile("1+1").disasm

のようにすれば"1+1"のVM命令が読めます。

== disasm: #<ISeq:<compiled>@<compiled>>================================
0000 trace            1                                               (   1)
0002 putobject_OP_INT2FIX_O_1_C_
0003 putobject_OP_INT2FIX_O_1_C_
0004 opt_plus         <callinfo!mid:+, argc:1, ARGS_SIMPLE>, <callcache>
0007 leave

細かいところは説明しません。行番号と命令が1行ずつかかれています。
雰囲気で1と1をスタックに積んで足し合わせている様子を感じ取ってください。

rubyのコードは実行するときに, このようにVM命令を一度挟んでいます。

命令の説明は
insns.def
にあるので興味があれば読んでください。

trace命令

笹田さんの記事によると, trace命令はRubyコードの各行に挟まれるようです。

実際, ベンチマークで使ったコードのVM命令を見るとtrace命令はたくさんあります。

1000000.times {
  a = 0
  b = 1
  100.times {
    c = a + b
    a = b
    b = c
  }
}
== disasm: #<ISeq:<compiled>@<compiled>>================================
== catch table
| catch type: break  st: 0002 ed: 0008 sp: 0000 cont: 0008
|------------------------------------------------------------------------
0000 trace            1                                               (   1)
0002 putobject        1000000
0004 send             <callinfo!mid:times, argc:0>, <callcache>, block in <compiled>
0008 leave
== disasm: #<ISeq:block in <compiled>@<compiled>>=======================
== catch table
| catch type: break  st: 0014 ed: 0020 sp: 0000 cont: 0020
| catch type: redo   st: 0002 ed: 0020 sp: 0000 cont: 0002
| catch type: next   st: 0002 ed: 0020 sp: 0000 cont: 0020
|------------------------------------------------------------------------
local table (size: 2, argc: 0 [opts: 0, rest: -1, post: 0, block: -1, kw: -1@-1, kwrest: -1])
[ 2] a          [ 1] b
0000 trace            256                                             (   1)
0002 trace            1                                               (   2)
0004 putobject_OP_INT2FIX_O_0_C_
0005 setlocal_OP__WC__0 4
0007 trace            1                                               (   3)
0009 putobject_OP_INT2FIX_O_1_C_
0010 setlocal_OP__WC__0 3
0012 trace            1                                               (   4)
0014 putobject        100
0016 send             <callinfo!mid:times, argc:0>, <callcache>, block (2 levels) in <compiled>
0020 trace            512                                             (   9)
0022 leave                                                            (   4)
== disasm: #<ISeq:block (2 levels) in <compiled>@<compiled>>============
== catch table
| catch type: redo   st: 0002 ed: 0026 sp: 0000 cont: 0002
| catch type: next   st: 0002 ed: 0026 sp: 0000 cont: 0026
|------------------------------------------------------------------------
local table (size: 1, argc: 0 [opts: 0, rest: -1, post: 0, block: -1, kw: -1@-1, kwrest: -1])
[ 1] c
0000 trace            256                                             (   4)
0002 trace            1                                               (   5)
0004 getlocal_OP__WC__1 4
0006 getlocal_OP__WC__1 3
0008 opt_plus         <callinfo!mid:+, argc:1, ARGS_SIMPLE>, <callcache>
0011 setlocal_OP__WC__0 3
0013 trace            1                                               (   6)
0015 getlocal_OP__WC__1 3
0017 setlocal_OP__WC__1 4
0019 trace            1                                               (   7)
0021 getlocal_OP__WC__0 3
0023 dup
0024 setlocal_OP__WC__1 3
0026 trace            512                                             (   8)
0028 leave

trace 1 というのがコードの行ごとに挟まるVM命令です。
この命令が7回も現れているのがわかります。

これに対して, コードの改行を削除して以下のように(広義の)ワンライナーにした場合, VM命令はこうなります。

1000000.times {;  a = 0;  b = 1;  100.times {;    c = a + b;    a = b;   b = c;  };};
== disasm: #<ISeq:<compiled>@<compiled>>================================
== catch table
| catch type: break  st: 0002 ed: 0008 sp: 0000 cont: 0008
|------------------------------------------------------------------------
0000 trace            1                                               (   1)
0002 putobject        1000000
0004 send             <callinfo!mid:times, argc:0>, <callcache>, block in <compiled>
0008 leave
== disasm: #<ISeq:block in <compiled>@<compiled>>=======================
== catch table
| catch type: break  st: 0010 ed: 0016 sp: 0000 cont: 0016
| catch type: redo   st: 0002 ed: 0016 sp: 0000 cont: 0002
| catch type: next   st: 0002 ed: 0016 sp: 0000 cont: 0016
|------------------------------------------------------------------------
local table (size: 2, argc: 0 [opts: 0, rest: -1, post: 0, block: -1, kw: -1@-1, kwrest: -1])
[ 2] a          [ 1] b
0000 trace            256                                             (   1)
0002 trace            1
0004 putobject_OP_INT2FIX_O_0_C_
0005 setlocal_OP__WC__0 4
0007 putobject_OP_INT2FIX_O_1_C_
0008 setlocal_OP__WC__0 3
0010 putobject        100
0012 send             <callinfo!mid:times, argc:0>, <callcache>, block (2 levels) in <compiled>
0016 trace            512
0018 leave
== disasm: #<ISeq:block (2 levels) in <compiled>@<compiled>>============
== catch table
| catch type: redo   st: 0002 ed: 0022 sp: 0000 cont: 0002
| catch type: next   st: 0002 ed: 0022 sp: 0000 cont: 0022
|------------------------------------------------------------------------
local table (size: 1, argc: 0 [opts: 0, rest: -1, post: 0, block: -1, kw: -1@-1, kwrest: -1])
[ 1] c
0000 trace            256                                             (   1)
0002 trace            1
0004 getlocal_OP__WC__1 4
0006 getlocal_OP__WC__1 3
0008 opt_plus         <callinfo!mid:+, argc:1, ARGS_SIMPLE>, <callcache>
0011 setlocal_OP__WC__0 3
0013 getlocal_OP__WC__1 3
0015 setlocal_OP__WC__1 4
0017 getlocal_OP__WC__0 3
0019 dup
0020 setlocal_OP__WC__1 3
0022 trace            512
0024 leave

わかりにくいと思いますが, 行trace命令は7つから2つになり, 5つも減っています。
このため, 実行がすこし速くなったわけです。

trace命令の定義

trace命令の定義はinsns.defにあります。

nopほど単純ではない処理が行われているのがわかります。
記事に説明されていたとおり, TracePointという機能で使われているようです。

もうちょっと検証

最初のベンチマークの時にもう少し検証をしています。
boostの定義とほとんど同じですが,
セミコロンではなく元の改行のままにするnonboostを定義しました。

def nonboost src
  eval src.gsub("\n", "\n")
end

boostnonboostの違いは";""\n"だけです。
このベンチマークは以下のようになりました。

Rehearsal ----------------------------------------------
Normal      10.420000   0.210000  10.630000 ( 13.289735)
Boost       10.280000   0.190000  10.470000 ( 12.934161)
NonBoost    10.750000   0.200000  10.950000 ( 13.520492)
------------------------------------ total: 32.050000sec

                 user     system      total        real
Normal      10.260000   0.160000  10.420000 ( 11.629897)
Boost        8.970000   0.120000   9.090000 (  9.784410)
NonBoost     9.820000   0.140000   9.960000 ( 11.012133)

何度か実行してみると, Boost <<< NonBoost < Normal の順に遅い感じがしました。
明らかにNonBoostは余計な処理を行っているのにも関わらず, 遅くならないのは不思議です。

ruby2.5の場合

このベンチマークは以下のruby2.4で実行しましたが,

ruby 2.4.3p205 (2017-12-14 revision 61247) [x86_64-darwin16]

次のruby2.5では続く結果のように, どれもほとんど差がありません。

ruby 2.5.0p0 (2017-12-25 revision 61468) [x86_64-darwin16]
Rehearsal ----------------------------------------------
Normal      12.007801   0.255304  12.263105 ( 15.818664)
Boost       12.588323   0.237480  12.825803 ( 15.782480)
NonBoost    12.292849   0.235013  12.527862 ( 14.568634)
------------------------------------ total: 37.616770sec

                 user     system      total        real
Normal      11.921363   0.238929  12.160292 ( 13.990406)
Boost       11.551764   0.235187  11.786951 ( 13.314673)
NonBoost    11.725629   0.180515  11.906144 ( 13.135241)

これは最初の記事で紹介されている通り, trace命令が抑制される最適化が施されたためです。

実際の命令を見てみると, 1つもtrace命令が存在しません。

== disasm: #<ISeq:<compiled>@<compiled>:1 (1,0)-(9,5)>==================
== catch table
| catch type: break  st: 0000 ed: 0006 sp: 0000 cont: 0006
== disasm: #<ISeq:block in <compiled>@<compiled>:1 (1,14)-(9,5)>========
== catch table
| catch type: break  st: 0007 ed: 0013 sp: 0000 cont: 0013
== disasm: #<ISeq:block (2 levels) in <compiled>@<compiled>:4 (4,16)-(8,7)>
== catch table
| catch type: redo   st: 0001 ed: 0019 sp: 0000 cont: 0001
| catch type: next   st: 0001 ed: 0019 sp: 0000 cont: 0019
|------------------------------------------------------------------------
local table (size: 1, argc: 0 [opts: 0, rest: -1, post: 0, block: -1, kw: -1@-1, kwrest: -1])
[ 1] c
0000 nop                                                              (   4)[Bc]
0001 getlocal_OP__WC__1 a                                             (   5)[Li]
0003 getlocal_OP__WC__1 b
0005 opt_plus         <callinfo!mid:+, argc:1, ARGS_SIMPLE>, <callcache>
0008 setlocal_OP__WC__0 c
0010 getlocal_OP__WC__1 b                                             (   6)[Li]
0012 setlocal_OP__WC__1 a
0014 getlocal_OP__WC__0 c                                             (   7)[Li]
0016 dup
0017 setlocal_OP__WC__1 b
0019 leave                                                            (   8)[Br]
| catch type: redo   st: 0001 ed: 0013 sp: 0000 cont: 0001
| catch type: next   st: 0001 ed: 0013 sp: 0000 cont: 0013
|------------------------------------------------------------------------
local table (size: 2, argc: 0 [opts: 0, rest: -1, post: 0, block: -1, kw: -1@-1, kwrest: -1])
[ 2] a          [ 1] b
0000 nop                                                              (   1)[Bc]
0001 putobject_OP_INT2FIX_O_0_C_                                      (   2)[Li]
0002 setlocal_OP__WC__0 a
0004 putobject_OP_INT2FIX_O_1_C_                                      (   3)[Li]
0005 setlocal_OP__WC__0 b
0007 putobject        100                                             (   4)[Li]
0009 send             <callinfo!mid:times, argc:0>, <callcache>, block (2 levels) in <compiled>
0013 leave                                                            (   9)[Br]
|------------------------------------------------------------------------
0000 putobject        1000000                                         (   1)[Li]
0002 send             <callinfo!mid:times, argc:0>, <callcache>, block in <compiled>
0006 leave

これによってほぼ任意のRubyのコードが数%速くなったのだと思います。すごい。

注意

記事にあるように, Ruby2.5以前でこの最適化を施したければ,

RubyVM::InstructionSequence.compile_option = {trace_instruction: false}

を使うべきです。