この記事はVim Advent Calendar 2012 : ATND 245日目の記事です。
Vim scriptは実行速度が遅いことで有名ですが、どこでどれくらい時間がかかっているのかを調べたい時があります。今回はVim scriptの実行時間を計測する方法をまとめました。
起動時間を調べる
1. --startuptimeオプションを付けて起動する
$gvim --startuptime {ファイル名}Vim起動時に読み込んだスクリプトと、かかった時間をリストアップしたファイルを、ホームディレクトリに生成します。
起動時しか計測できないのと、結果がファイルに出力されるので（工夫をしない限りは）気軽に見られないということと、ファイルの見方がイマイチ分からないのが難点です（後述の:profileコマンドで出力されるのと同じ形式です）。
ファイルに追記していく方式なので、--startuptimeで起動する度にログファイルが大きくなっていきます。
あるスクリプトの実行時間を調べる
2. :profileコマンドを使う
前述の--startuptimeを任意のスクリプトや関数に適用するイメージです。ただし、Vimが"huge"バージョンでないと利用できません。
:echo has('profile')
で利用できるか確認できます。Shougoさんの働きかけで最近、Kaoriyaバージョンでも利用できるようになったらしいです。
ただし、profileが利用できるバージョンは全てのスクリプトの実行速度が遅くなるそうです。
スクリプトファイル全体の実行時間を計測することも、関数を計測することも出来ます。
それより細かい単位の計測は出来ません。
はじめに`:profile start {filename}`をしないと、`profile func {funcpattern}`や`profile file {filepattern}`を実行できません。
また、Vimを終了しないと結果は書き出されません。
関数名「lily#*」に一致する関数のそれぞれの実行時間を計測したいとき
:profile start vimprofile.txt :profile func lily#*
3. benchvimrc-vimを使う
こちらは"huge"バージョンでなくても利用可能ですが、vimrc限定です。vimrcを複写してから各行にreltime()を埋め込んで計測する方式なので、再読込可能なvimrcでないといけません。
モジュールの実行時間を調べる
4. vim-benchmarkを使う
ある書き方と別の書き方、どちらの方が速いかを調べることが出来るオブジェクトを生成します。
オブジェクトに作られた関数の実行速度を比較する形式です。
5. TimerStart、TimerEndコマンドを使う
計測を始めたいところにTimerStart、終えたいところにTimerEndと書けば2点間の処理時間を計測できます。
vimrcに、ほんの2行ほど付け足せばいいだけので導入が簡単です。
command! -bar TimerStart let start_time = reltime() command! -bar TimerEnd echo reltimestr(reltime(start_time)) | unlet start_time
それでいて任意の2点間を調べることも、ベンチマークを取ることも出来るので応用性があります。
実行するとすぐに結果が表示されるので自動で呼び出されるような処理の計測には不向きです。
また、計測対象のスクリプトにこのコマンドを埋め込まなくてはいけません。
6. laptime.vimを使う
laptime.vimはスクリプト2点間とその中間点を計測できます。
(laptime.vimの使い方)
function! s:test() let g:lt = laptime#new() "計測を始める場所でlaptime#new()する let num = 2 let i = 1 call g:lt.lap() " .lap()を呼ぶと、測定開始からの時間を記録 while i < 5 let num = num * i let i += 1 call g:lt.lap('ループ中') "各関数に引数を渡すことが出来る endwhile call g:lt.end() "計測を終える場所で .end()を呼ぶ return num endfunction echo s:test() call g:lt.show() " .show()を呼ぶと、結果を表示する
48
TOTAL LAP
1: 0.000058 0.000058
2: 0.000159 0.000101 > ループ中
3: 0.000262 0.000103 > ループ中
4: 0.000361 0.000099 > ループ中
5: 0.000459 0.000098 > ループ中
6: 0.000578 0.000119この場合実行に合計0.000578秒かかったことになります（計測時のオーバーヘッド含む）。
そしてLAPというのが前の計測点から次の計測点までにかかった時間です。
文字列以外も引数として渡すことが出来ます。変数の変動を見たいときに使えます。複数の引数を渡すことも出来ます。その場合表示は複数行になります。
function! s:test() let g:lt = laptime#new('変数の変化も見る') "タイトルをつけることも出来ます。 let num = 2 let i = 1 call g:lt.lap() while i < 5 let num = num * i let i += 1 call g:lt.lap(i, num) "複数引数を与えることが出来ます。 endwhile call g:lt.end(num) return num endfunction echo s:test() call g:lt.show()
48
変数の変化も見る
TOTAL LAP
1: 0.000058 0.000058
2: 0.000160 0.000102 > 2
2
3: 0.000265 0.000105 > 3
4
4: 0.000362 0.000097 > 4
12
5: 0.000460 0.000097 > 5
48
6: 0.000579 0.000120 > 48さらに、laptime.vimで計測した過去の結果は、g:laptimesに蓄えられています*1。
これをやめさせたければ、g:laptimes.disableに0以外の値を代入してください。
g:laptimes.show()で過去の計測結果を見ることが出来ます。
:call g:laptimes.show()
[1]
TOTAL LAP
1: 0.000058 0.000058
2: 0.000159 0.000101 > ループ中
3: 0.000262 0.000103 > ループ中
4: 0.000361 0.000099 > ループ中
5: 0.000459 0.000098 > ループ中
6: 0.000578 0.000119
[2]
変数の変化も見る
TOTAL LAP
1: 0.000058 0.000058
2: 0.000160 0.000102 > 2
2
3: 0.000265 0.000105 > 3
4
4: 0.000362 0.000097 > 4
12
5: 0.000460 0.000097 > 5
48
6: 0.000579 0.000120 > 48これによって、、同じスクリプトに手を加えて変更前と比較することもできます。また、趣旨から外れますが、プラグイン作成における発見しにくいバグである、意図しない再帰的な自分の呼び出しを見つけることが出来ます（laptime.vimの計測が終わらない*2うちに同じ場所で新しくnew()されると再帰呼び出ししているとみなし、g:laptimes.show()の結果にCONTAIN CONTAINED標記が付きます）。
注意しなければいけないのは、緻密な計測には向いていません。私の環境ですと、.lap()の実行に約0.0001秒のオーバーヘッドがありました。
7. reltime() reltimestr()を直接使う
let s:start = reltime() "{...計測したい処理...} echo reltimestr(reltime(s:start))
