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ですね。まずLuaのGCはIncremental MarkSweep GC。MarkSweepの「Markフェーズでヒープ領域全部触るからキャッシュミスしまくる」という弱点がモロに。GCでキャッシュを荒されたおかげで、他の部分でもキャッシュミス発生しまくり。それらをほとんど解消しているようで、これは喜ばしいことです。
キャッシュヒット率が非常に上がったのであれですね。「省電力です!」と強弁することすら可能で、これは喜ばしいことです。エコ! エコ!