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.

debugging nagios remote nrpe commands

Nagios NRPE debugging steps:

1. run the command manually on the target host
   
2. enable debugging in nrpe.cfg and watch syslog
   
3. dig in deeper with debug jobs.
   

Debugging nagios remote nrpe commands can feel very opaque. Normally I find my issue in step 1 of the debug escalation. Today I had to hit all three steps while debugging a test that wrapped around s3cmd. I eventually found that HOME is not set in the environment used to run nrpe commands.

check_nrpe -H 10.7.202.92 -c check_ui_s3_backup                                 
NRPE: Unable to read output

I run my check remotely and receive the dreaded general error "unable to read output." This means the script failed to run and didn't produce any output to STDOUT. STDERR seems to be ignored, even with logging enabled.

Step 1a: go to the server and verify the command being run by nrpe.

[andrew@ip-10-7-202-92]% grep check_ui_s3_backup /etc/nagios/nrpe.d/herbie.cfg
command[check_ui_s3_backup]=HOME=~postgres /usr/lib/nagios/plugins/herbie/check_ui_s3_backup

Step 1b: run the command manually. Here I find that the script fails if I don't have the config file:

[andrew@ip-10-7-202-92]% /usr/lib/nagios/plugins/herbie/check_ui_s3_backup
ERROR: /home/andrew/.s3cfg: No such file or directory
ERROR: Configuration file not available.
ERROR: Consider using --configure parameter to create one.

That should be a simple fix. Find the user running the nrpe command and give them a .s3cfg. Easy-Peasy.

cp .s3cfg ~nagios/
sudo -u nagios -H /usr/lib/nagios/plugins/herbie/check_ui_s3_backup
OK - Last backup 0 days ago.

Ok, it works locally. Recheck it remotely. It fails?!!?! This is where we start the gnashing of teeth and pulling of hair

[andrew@ip-10-7-203-10]% check_nrpe -H 10.7.202.92 -c check_ui_s3_backup
NRPE: Unable to read output

Step 2: Enable logging in nrpe.cfg, run the remote check and inspect the logs. Surprise, nothing useful.

May  7 19:08:29 ip-10-7-202-92 nrpe[17159]: Connection from 10.7.203.10 port 15286
May  7 19:08:29 ip-10-7-202-92 nrpe[17159]: Host address is in allowed_hosts
May  7 19:08:29 ip-10-7-202-92 nrpe[17159]: Handling the connection...
May  7 19:08:29 ip-10-7-202-92 nrpe[17159]: Host is asking for command 'check_ui_s3_backup' to be run...
May  7 19:08:29 ip-10-7-202-92 nrpe[17159]: Running command: /usr/lib/nagios/plugins/herbie/check_ui_s3_backup
May  7 19:08:29 ip-10-7-202-92 nrpe[17159]: Command completed with return code 3 and output: 
May  7 19:08:29 ip-10-7-202-92 nrpe[17159]: Return Code: 3, Output: NRPE: Unable to read output
May  7 19:08:29 ip-10-7-202-92 nrpe[17159]: Connection from 10.7.203.10 closed.

Step 3: debug jobs (aka printf aka "hail marry" debugging). I create two new nrpe entries and restart nagios-nrpe-server. The first will show me the user running the command and the second will show the environment, using whoami and env respectively.

command[check_ui_test]=whoami
command[check_ui_test2]=env

[andrew@ip-10-7-203-10]% check_nrpe -H 10.7.202.92 -c check_ui_test
nagios
[andrew@ip-10-7-203-10]% check_nrpe -H 10.7.202.92 -c check_ui_test2
NRPE_PROGRAMVERSION=2.12
TERM=screen-256color-bce
PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin
LANG=en_US.UTF-8
NRPE_MULTILINESUPPORT=1
PWD=/

Yep, the tests are running as the expected user, nagios.

Holy Schmoly! Look at that environment! HOME is not set. Simple enough to fix for my check, but wow was I not expecting that. Also useful to note the minimal PATH and that the working directory is /.

Update check to explicitly set HOME in the environment and restart nrpe:

command[check_ui_s3_backup]=HOME=~nagios /usr/lib/nagios/plugins/herbie/check_ui_s3_backup

Restart nrpe:

[andrew@ip-10-7-202-92]% sudo service nagios-nrpe-server restart
 * Stopping nagios-nrpe nagios-nrpe
   ...done.
 * Starting nagios-nrpe nagios-nrpe
   ...done.

Check:

[andrew@ip-10-7-203-10]% check_nrpe -H 10.7.202.92 -c check_ui_s3_backup
OK - Last backup 0 days ago.