Rubyのtrace命令の話を確かめる
過去のblogから移動しました 元公開日時 2017-12-31 06:10:19
こんばんは。
この記事はKMCアドベントカレンダー23日目の記事です。大遅刻です。
前日の記事はprimeさんの
ビット演算マニアのためのAVX512入門 【KMCアドベントカレンダー 22日目】 - prime's diaryです
明日の記事はtetsutalowさんの
3つの事件で振り返る「何をやったらウイルス罪で捕まるか2017」 - Tetsu=TaLowの雑記（はてブロ版）です
本題
インターンの講義でお世話になった笹田さんの上の記事を読みました。
その記述を確かめながら小ネタにしようと思います。
次の素朴なコードのベンチマークを見てください。
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命令が減ったからです。
RubyのVM
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
boostとnonboostの違いは";"と"\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}
を使うべきです。
