Lua高速化プロジェクト開発状況など(3)

ひどい話でObjectStackのリサイズをまだ実装していない。スタックそのものをreallocしたあとには当然スタック割り当てを指してるオブジェクト達のポインタを修正してやらにゃならんのだけど、どっかで漏れてるようでうまくいかない。気分転換にプロファイリングなど。
使う道具はOProfileで。あとOProfileでテストするときのために適当に書いたスクリプトoptest.rbを使います。
先の日記 Lua高速化プロジェクト開発状況など(1) - hogeなlog に書きましたがなんだか結構な高速化に成功しました。ただ「速くなってる! よくわかんないけど!」では「なんで? 正しい結果じゃないんじゃないの?」と言われたときに困ります。「こうこうこんな理由で速くなってるのです! 謝罪しろ!」と言い返すためにちゃんと理由を調べましょう。
OProfileについては以前ちょっとだけ解説を試みた記事があるので、読むと何かわかったような気分になれるかもしれません。

時間のプロファイル

まずは単純に「元の実装はどこで時間くってるのか」調べるために、1クロックごとに発生する(らしい)CPU_CLK_UNHALTEDをサンプリング。

% sudo opcontrol --event=CPU_CLK_UNHALTED:10000
% optest ./lua-original ao.lua --report=optest-original
# /usr/bin/sudo /usr/bin/opcontrol --image=./lua-original
# /usr/bin/sudo /usr/bin/opcontrol --shutdown
Stopping profiling.
Killing daemon.
# /usr/bin/sudo /usr/bin/opcontrol --reset
# /usr/bin/sudo /usr/bin/opcontrol --start
Using 2.6+ OProfile kernel interface.
Using log file /var/lib/oprofile/samples/oprofiled.log
Daemon started.
Profiler running.
# ./lua-original ao.lua
--- aobench ---
init scene
render start
save ppm
time to render end      214
total time      214
--- done ---
# /usr/bin/sudo /usr/bin/opcontrol --dump
# /usr/bin/sudo /usr/bin/opcontrol --stop
Stopping profiling.
# /usr/bin/opreport ./lua-original
# /usr/bin/opreport -l ./lua-original
# /usr/bin/opannotate -as ./lua-original
# /usr/bin/opannotate -a ./lua-original
# /usr/bin/opannotate -s ./lua-original
% cat optest-original.report.l
CPU: AMD64 processors, speed 2410.97 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 10000
samples  %        symbol name
5192807  38.9721  luaV_execute
1943239  14.5841  luaV_gettable
1555359  11.6730  luaH_get
833782    6.2576  luaD_precall
550677    4.1328  setnodevector
535552    4.0193  propagatemark
344504    2.5855  luaM_realloc_
326751    2.4523  luaD_poscall
267898    2.0106  luaV_settable
267091    2.0045  newkey
256199    1.9228  luaH_free
229004    1.7187  luaC_link
150810    1.1318  l_alloc
139415    1.0463  luaH_set
112902    0.8473  mainposition
80198     0.6019  luaH_getnum
76348     0.5730  luaH_new
61315     0.4602  sweeplist
49088     0.3684  setarrayvector
36823     0.2764  math_random
32033     0.2404  math_sqrt
30470     0.2287  luaV_lessthan
27994     0.2101  luaO_fb2int
27718     0.2080  lua_pushnumber
25408     0.1907  luaL_checknumber
21021     0.1578  singlestep
20194     0.1516  hashnum
18066     0.1356  math_sin
17196     0.1291  math_cos
15462     0.1160  index2adr
14060     0.1055  math_abs
13663     0.1025  luaO_log2
12803     0.0961  reallymarkobject
12411     0.0931  lua_tonumber
...
# ./lua-stackalloc-dev ao.lua
--- aobench ---
init scene
render start
save ppm
time to render end      152
total time      152
--- done ---
...
% cat optest-stackalloc-dev.report.l
CPU: AMD64 processors, speed 2410.97 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mas
k) count 10000
samples  %        image name               symbol name
5661788  46.8418  lua-stackalloc-dev       luaV_execute
2155330  17.8317  lua-stackalloc-dev       luaV_gettable
1587087  13.1305  lua-stackalloc-dev       luaH_get
910107    7.5296  lua-stackalloc-dev       luaD_precall
340603    2.8179  lua-stackalloc-dev       luaD_poscall
279875    2.3155  lua-stackalloc-dev       luaV_settable
265766    2.1988  lua-stackalloc-dev       newkey
213770    1.7686  lua-stackalloc-dev       luaH_ostack_new
149016    1.2329  lua-stackalloc-dev       luaH_set
114820    0.9499  lua-stackalloc-dev       mainposition
91977     0.7610  lua-stackalloc-dev       luaH_getnum
29226     0.2418  lua-stackalloc-dev       ostack_alloc_
28518     0.2359  lua-stackalloc-dev       luaO_fb2int
27360     0.2264  lua-stackalloc-dev       math_sqrt
27211     0.2251  lua-stackalloc-dev       luaV_lessthan
27113     0.2243  lua-stackalloc-dev       hashnum
25205     0.2085  lua-stackalloc-dev       luaL_checknumber
24763     0.2049  lua-stackalloc-dev       math_random
24707     0.2044  lua-stackalloc-dev       lua_pushnumber
19452     0.1609  lua-stackalloc-dev       luaO_log2
18235     0.1509  lua-stackalloc-dev       math_sin
17151     0.1419  lua-stackalloc-dev       math_cos
14647     0.1212  lua-stackalloc-dev       index2adr
12645     0.1046  lua-stackalloc-dev       lua_tonumber
10246     0.0848  lua-stackalloc-dev       math_abs
...

luaV_execute, luaH_gettableに時間かかってるのはどちらも同じだけど、元実装だとGCとreallocに時間がかかっていることが読み取れますね、と。stackalloc-devではこの二つはではスタック割り当てにより、ほとんど呼ばれていない。そりゃ速くなります。
次はキャッシュミスを。L2キャッシュまでにヒットしてりゃあ十分速い処理になってんだろということで、L2_CACHE_MISSでもサンプリングしてみる。

% sudo opcontrol --event=L2_CACHE_MISS:500
% optest ./lua-original ao.lua --report=optest-original
# /usr/bin/sudo /usr/bin/opcontrol --image=./lua-original
# /usr/bin/sudo /usr/bin/opcontrol --shutdown
Stopping profiling.
Killing daemon.
# /usr/bin/sudo /usr/bin/opcontrol --reset
# /usr/bin/sudo /usr/bin/opcontrol --start
Using 2.6+ OProfile kernel interface.
Using log file /var/lib/oprofile/samples/oprofiled.log
Daemon started.
Profiler running.
# ./lua-original ao.lua
--- aobench ---
init scene
render start
save ppm
time to render end      187
total time      187
--- done ---
...
% optest ./lua-stackalloc-dev ao.lua --report=optest-stackalloc-dev
# /usr/bin/sudo /usr/bin/opcontrol --image=./lua-stackalloc-dev
# /usr/bin/sudo /usr/bin/opcontrol --shutdown
Stopping profiling.
Killing daemon.
# /usr/bin/sudo /usr/bin/opcontrol --reset
# /usr/bin/sudo /usr/bin/opcontrol --start
Using 2.6+ OProfile kernel interface.
Using log file /var/lib/oprofile/samples/oprofiled.log
Daemon started.
Profiler running.
# ./lua-stackalloc-dev ao.lua
--- aobench ---
init scene
render start
save ppm
time to render end      136
total time      136
--- done ---
...
% cat optest-original.report.l
CPU: AMD64 processors, speed 2410.97 MHz (estimated)
Counted L2_CACHE_MISS events (L2 Cache Misses) with a unit mask of 0x07 (multiple flags) count 500
samples  %        symbol name
197869   38.6208  propagatemark
111403   21.7440  setnodevector
65256    12.7369  luaM_realloc_
42544     8.3039  luaH_free
32065     6.2586  luaV_execute
23609     4.6081  luaC_link
12976     2.5327  l_alloc
11490     2.2427  luaH_new
3153      0.6154  reallymarkobject
3044      0.5941  sweeplist
2211      0.4316  singlestep
1525      0.2977  luaV_gettable
1048      0.2046  luaH_set
1045      0.2040  luaC_step
938       0.1831  luaH_get
682       0.1331  luaD_precall
145       0.0283  lua_gettop
134       0.0262  setarrayvector
133       0.0260  luaC_separateudata
123       0.0240  markroot
...
% cat optest-stackalloc-dev.report.l
CPU: AMD64 processors, speed 2410.97 MHz (estimated)
Counted L2_CACHE_MISS events (L2 Cache Misses) with a unit mask of 0x07 (multiple flags) count 500
samples  %        symbol name
212      22.3629  setarrayvector
197      20.7806  resize
152      16.0338  luaM_realloc_
129      13.6076  luaD_precall
102      10.7595  setnodevector
101      10.6540  luaC_link
14        1.4768  newkey
10        1.0549  luaH_free
8         0.8439  luaV_settable
6         0.6329  luaH_new
5         0.5274  luaS_newlstr
5         0.5274  luaV_execute
2         0.2110  luaH_set
1         0.1055  addk
1         0.1055  luaS_resize
1         0.1055  luaV_gettable
1         0.1055  luaX_init
1         0.1055  math_random

こちらの値は驚くほどの違いが。元の実装のキャッシュミスの数がすさまじい理由の根源はGCですね。まずLuaGCはIncremental MarkSweep GC。MarkSweepの「Markフェーズでヒープ領域全部触るからキャッシュミスしまくる」という弱点がモロに。GCでキャッシュを荒されたおかげで、他の部分でもキャッシュミス発生しまくり。それらをほとんど解消しているようで、これは喜ばしいことです。
キャッシュヒット率が非常に上がったのであれですね。「省電力です!」と強弁することすら可能で、これは喜ばしいことです。エコ! エコ!

test