Vimのstartuptime出力結果の読み方

Vimには処理時間を計測する機能があり、以下のようにvimの引数に --startuptime を付けることで指定した{logfilename}に処理時間を計測した結果をファイルとして出力できる。

vim --startuptime {logfilename}

その出力結果は以下の形式で出力される。

times in msec
 clock   self+sourced   self:  sourced script
 clock   elapsed:              other lines

000.000  000.000: --- VIM STARTING ---
000.000  000.000: Allocated generic buffers
002.000  002.000: locale set
002.000  000.000: clipboard setup
002.000  000.000: window checked
003.000  001.000: inits 1
009.000  006.000: parsing arguments
009.000  000.000: expanding arguments
025.000  016.000: shell init
026.000  001.000: Termcap init
026.000  000.000: inits 2
026.000  000.000: init highlight
658.000  312.000  312.000: sourcing C:\Users\naru1/.vimrc.c
658.000  514.000  202.000: sourcing C:\Users\naru1/.vimrc.b
658.000  632.000  118.000: sourcing C:\Users\naru1/.vimrc.a
658.000  632.000  000.000: sourcing $HOME\_vimrc
658.000  000.000: sourcing vimrc file(s)
660.000  000.000  000.000: sourcing C:\Users\naru1\vim-on-windows\runtime\plugin\getscriptPlugin.vim
661.000  001.000  001.000: sourcing C:\Users\naru1\vim-on-windows\runtime\plugin\gzip.vim
661.000  000.000  000.000: sourcing C:\Users\naru1\vim-on-windows\runtime\plugin\logiPat.vim
662.000  000.000  000.000: sourcing C:\Users\naru1\vim-on-windows\runtime\plugin\manpager.vim
662.000  000.000  000.000: sourcing C:\Users\naru1\vim-on-windows\runtime\plugin\matchparen.vim
663.000  000.000  000.000: sourcing C:\Users\naru1\vim-on-windows\runtime\plugin\netrwPlugin.vim
664.000  001.000  001.000: sourcing C:\Users\naru1\vim-on-windows\runtime\plugin\rrhelper.vim
664.000  000.000  000.000: sourcing C:\Users\naru1\vim-on-windows\runtime\plugin\spellfile.vim
664.000  000.000  000.000: sourcing C:\Users\naru1\vim-on-windows\runtime\plugin\tarPlugin.vim
665.000  000.000  000.000: sourcing C:\Users\naru1\vim-on-windows\runtime\plugin\tohtml.vim
665.000  000.000  000.000: sourcing C:\Users\naru1\vim-on-windows\runtime\plugin\vimballPlugin.vim
666.000  000.000  000.000: sourcing C:\Users\naru1\vim-on-windows\runtime\plugin\zipPlugin.vim
666.000  006.000: loading plugins
666.000  000.000: loading packages
666.000  000.000: loading after plugins
666.000  000.000: inits 3
667.000  001.000: reading viminfo
667.000  000.000: setting raw mode
701.000  034.000: start termcap
701.000  000.000: clearing screen
702.000  001.000: opening buffers
702.000  000.000: BufEnter autocommands
702.000  000.000: editing files in windows
703.000  001.000: VimEnter autocommands
703.000  000.000: before starting main loop
710.000  007.000: first screen update
710.000  000.000: --- VIM STARTED ---

この出力は大きく以下の2つの形式で出力されていることがわかる。

000.000 000.000: xxx
000.000 000.000 000.000: xxx

まず、測定時間らしきもの 000.000 の単位はミリ秒である。たとえば 008.012 の場合、8.012ミリ秒掛ったことを意味する。

`000.000 000.000: xxx` の読み方

1つ目の000.000は--- VIM STARTING ---からの現時点までに掛った測定時間を意味している。

2つ目の000.000はその行の処理時間のみを意味している。

`000.000 000.000 000.000: xxx` の読み方

この形式はVim scriptファイルを読み込んでいるときの処理時間を出力することに使用される。

1つ目の000.000は--- VIM STARTING ---からの現時点までに掛った測定時間を意味している。

2つ目の000.000はそのVim scriptファイルの処理時間を意味する。そのファイルが別のVim scriptファイルを読み込んでいる場合、その読み込んだVim scriptファイルの処理時間はこの値に含まれる。

3つ目の000.000はそのVim scriptファイルの処理時間を意味する。そのファイルが別のVim scriptファイルを読み込んでいる場合、その読み込んだVim scriptファイルの処理時間はこの値に含まれない。

たとえば、上記の

658.000  312.000  312.000: sourcing C:\Users\naru1/.vimrc.c
658.000  514.000  202.000: sourcing C:\Users\naru1/.vimrc.b
658.000  632.000  118.000: sourcing C:\Users\naru1/.vimrc.a

はそれぞれ以下のVim scriptファイルである。

.vimrc.a

sleep 100m
source .vimrc.b

.vimrc.b

sleep 200m
source .vimrc.c

.vimrc.c

sleep 300m

そして、.vimrcから.vimrc.aを読み込んでいる。これからわかるように3行目の632.000は.vimrc.aが読み込んでいる.vimrc.b、.vimrc.bが読み込んでいる.vimrc.cの処理時間を含んでいることがわかる。

000.000 000.000: xxx の読み方

000.000 000.000 000.000: xxx の読み方

`000.000 000.000: xxx` の読み方

`000.000 000.000 000.000: xxx` の読み方