Profiling vim start up time

After updating my vim plugins and adding a few new ones, I found my start up time became unreasonably slow. I blamed my tag generating plugin because of how the slowdown only occurred when opening vim with a file. That was a red herring, removing it didn't speed things up. Checking that projects issues I found that it was already switched to be asynchronous.

While investigating, I found a reference to the --startuptime option in vim. This option creates a log file containing entries for each startup action: sourcing files, executing plugins etc with timing information showing start and end times for each action, measuring relatively from the start and from the previous command. It's a lot of useful information for investigating which plugins are slowing startup time, reported in a useful format. Thumbs up to vim1

% vim --startuptime /tmp/startup-time.log
% vim --startuptime /tmp/startup-time-vimrc.log ~/.vimrc

Wow, loading all these new plugins was taking a while. 800ms in the first case but 3200ms when loading a file! More files are sourced in the latter case as the FileType files need to be sourced and applied.

Timing

starting time without a file load

471.134  121.649: VimEnter autocommands
471.137  000.003: before starting main loop
477.200  004.424  004.424: sourcing /home/andrew/.vim/bundle/vim-fugitive/autoload/fugitive.vim
481.049  002.378  002.378: sourcing /home/andrew/.vim/bundle/tagbar/autoload/tagbar.vim
481.569  000.173  000.173: sourcing /home/andrew/.vim/bundle/tagbar/autoload/tagbar/debug.vim
851.768  000.774  000.774: sourcing /home/andrew/.vim/bundle/tagbar/autoload/tagbar/types/uctags.vim
852.226  000.177  000.177: sourcing /home/andrew/.vim/bundle/tagbar/autoload/tagbar/prototypes/typeinfo.vim
861.475  382.412: first screen update
861.476  000.001: --- VIM STARTED ---

Starting time loading .vimrc

585.708  181.604: VimEnter autocommands
585.715  000.007: before starting main loop
595.217  000.623  000.623: sourcing /home/andrew/.vim/bundle/vim-airline/autoload/airline/async.vim
606.194  006.914  006.914: sourcing /home/andrew/.vim/bundle/tagbar/autoload/tagbar.vim
606.877  000.122  000.122: sourcing /home/andrew/.vim/bundle/tagbar/autoload/tagbar/debug.vim
3057.382  001.216  001.216: sourcing /home/andrew/.vim/bundle/tagbar/autoload/tagbar/types/uctags.vim
3057.895  000.191  000.191: sourcing /home/andrew/.vim/bundle/tagbar/autoload/tagbar/prototypes/typeinfo.vim
3065.474  000.258  000.258: sourcing /home/andrew/.vim/bundle/tagbar/autoload/tagbar/prototypes/fileinfo.vim
3242.091  000.213  000.213: sourcing /home/andrew/.vim/bundle/tagbar/autoload/tagbar/state.vim
3249.747  2655.495: first screen update
3249.750  000.003: --- VIM STARTED ---

The big difference: missing time between loading tagbar/debug and tagbar/types/uctags.vim, 370ms vs 2400ms. The files are getting sourced quickly, but something is causing an external delay.

So maybe it is the tags generating plugin locking the tags file? But a tags file neither exists nor is generated in the directory containing .vimrc. Very curious indeed.

The debug file (tagbar/debug) file defines several function! functions, and has one minor branch on if has('realtime'). Nothing suspicious at all.
Similarly, the uctags file (tagbar/types/uctags.vim) creates a single function function! tagbar#types#uctags#init(supported_types) abort which doesn't seem to be affected by the currently loaded file.

480.725  101.452: VimEnter autocommands
480.732  000.007: before starting main loop
490.939  000.468  000.468: sourcing /home/andrew/.vim/bundle/vim-airline/autoload/airline/async.vim
498.378  003.465  003.465: sourcing /home/andrew/.vim/bundle/tagbar/autoload/tagbar.vim
499.003  000.131  000.131: sourcing /home/andrew/.vim/bundle/tagbar/autoload/tagbar/debug.vim
2947.025  000.461  000.461: sourcing /home/andrew/.vim/bundle/tagbar/autoload/tagbar/types/uctags.vim
2947.325  000.041  000.041: sourcing /home/andrew/.vim/bundle/tagbar/autoload/tagbar/prototypes/typeinfo.vim
2954.640  000.096  000.096: sourcing /home/andrew/.vim/bundle/tagbar/autoload/tagbar/prototypes/fileinfo.vim
3179.663  000.203  000.203: sourcing /home/andrew/.vim/bundle/tagbar/autoload/tagbar/state.vim
3188.567  2703.970: first screen update
3188.572  000.005: --- VIM STARTED ---

330.198  006.165: BufEnter autocommands
330.201  000.003: editing files in windows
330.967  000.694  000.694: sourcing /home/andrew/.vim/bundle/YouCompleteMe/autoload/youcompleteme.vim
442.792  111.897: VimEnter autocommands
442.797  000.005: before starting main loop
449.255  000.333  000.333: sourcing /home/andrew/.vim/bundle/vim-airline/autoload/airline/async.vim
462.352  019.222: first screen update
462.358  000.006: --- VIM STARTED ---

Summary

Disabling the tagbar plugin gets me back my missing 2.5 seconds.

Tagbar has Issue #477 open for this delay during startup, it is running ctags synchronously under the hood on startup.

Further debugging

The syntastic and YouCompleteMe plugins each add ~200ms to startup time. Removing all three lowers my start time to 180ms which feels fast, as there is no noticable lag after the first paint of the screen.

I really enjoy the benefits of live linting with syntastic. Moving to Ale, an asynchoronus linter speeds up startup considerably with a ~30ms load time. I'll switch for a while and see how it compares.