How to profile slow vim startup

Profiling slow nvim startup.md

Introduction

Neovim was taking a long time to start up but only on my laptop. Like 2 seconds long. This didn't happen on a shared aws dev box, which led me to thinking this was maybe hardware or OS filesystem caching issue. Here's what I did to debug and get to the bottom of the mystery.

Profiling vim

The first step was to sanity check how slow this was.

time nvim -c quit
        2.30 real         1.21 user         0.79 sys

The user time is 1.2 seconds. Wow, that's pretty slow startup time.

Let's profile neovim itself to see if this is caused by a slow plugin. This can be done with the --startuptime argument, which outputs profiling timings:

vim --startuptime output.log
cat output.log

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

000.011  000.011: --- NVIM STARTING ---
001.012  001.000: locale set
001.795  000.783: inits 1
001.816  000.021: window checked
002.033  000.217: parsing arguments
002.418  000.385: expanding arguments
002.569  000.151: inits 2
003.064  000.495: init highlight
005.683  001.906  001.906: sourcing /Users/jngu/.config/nvim/autoload/plug.vim
020.847  003.326  003.326: sourcing /Users/jngu/.vim/bundle/vim-polyglot/ftdetect/polyglot.vim
021.343  000.041  000.041: sourcing /Users/jngu/.vim/bundle/vim-polyglot/after/ftdetect/rspec.vim
021.436  010.796  007.430: sourcing /usr/local/Cellar/neovim/0.3.1/share/nvim/runtime/filetype.vim
...
<truncated>
...
2042.010  000.131  000.131: sourcing /Users/jngu/.vim/bundle/vim-airline/autoload/airline/init.vim
2042.872  001.226  001.096: sourcing /Users/jngu/.vim/bundle/vim-airline/autoload/airline/section.vim
2043.112  2039.617  2019.833: sourcing /Users/jngu/.config/nvim/init.vim
2043.148  000.467: sourcing vimrc file(s)
...
<truncated>
...
2199.493  000.381  000.381: sourcing /Users/jngu/.vim/bundle/vim-gitgutter/autoload/gitgutter/hunk.vim
2200.435  019.790: first screen update
2200.437  000.002: --- NVIM STARTED ---

The first column shows the elasped time (from start) and the second column shows the incremental time. Sourcing my init.vim takes 2.04 seconds, out of the total running time of 2.20 seconds.

Debugging vimrc

The next step is narrow down what in my init.vim is causing the slowness. It's possible I have too much crap in my vimrc and it's taking forever to load on a cold cache.

Vim has some profiling functions for plugin authors to use:

:profile start debug_vimrc.log
:profile! file */<plugin>/*

This can be used to dive deeper into a specific plugin's behaviour to a great granularity.

But in my case, I found the issue by binary-search-and-comment-out my vimrc. And narrowed it down to these lines:

   if has('nvim') && has('ttyin') && has('ttyout')
       if exists("$VIRTUAL_ENV")
           " Skip the activated virtualenv, which probably doesn't have neovim package
           let g:python3_host_prog = system("type -ap python3 | head -n2 | tail -n1")[:-2]
           let g:python_host_prog = system("type -ap python2 | head -n2 | tail -n1")[:-2]
       else
           let g:python3_host_prog = system("command -v python3")[:-2]
           let g:python_host_prog = system("command -v python2")[:-2]
       endif
   endif

This snippet is used for selecting the python virtualenv that has neovim package installed. It uses system(), which runs a command in a new subshell.

Hmm... that can't be the problem, right? Let's test it.

time fish -c exit
        1.03 real         0.52 user         0.36 sys

Huh, that's 0.5 seconds to spawn a new shell and we're calling it twice here.

Debugging Fish startup

fish has the debug flag -d, which prints debugging trace to stderr. There several levels of debug verbosity so I iterated through it incrementally, to avoid reading through noisy logs.

fish -d 3 -c exit 2>&1 | ts -i '%.S' | sort -n -k 1

This will spawn a fish shell and immediately exit, print debug information to stdout (instead of stderr). The output goes to ts from moreutils, which appends a timestamp to every line. Then we sort it by the duration.

<truncated>
...
00.000225 <3> fish: Created job 3 from command 'status --is-interactive' with pgrp -2
00.000397 <2> fish: determine_config_directory_paths() results:
00.990492 <3> fish: Created job 5 from command 'set PATH (brew --prefix coreutils)/libexec/gnubin $PATH' with pgrp -2

The Fix

So it seems the command set PATH (brew --prefix coreutils)/libexec/gnubin $PATH is the culprit. More precisely, the call to brew --prefix coreutils via command substitution.

time brew --prefix coreutils
        1.42 real         0.55 user         0.41 sys

The entire cost of creating a new subshell was on this brew call. Since the brew installation path doesn't change often, the workaround is to statically hardcoded the path. This is much prefered to paying the cost of subshell startup.

set PATH /usr/local/opt/coreutils/libexec/gnubin $PATH

And with that small change, we've fix shell and nvim start up times.

time nvim -c quit
        0.30 real         0.18 user         0.06 sys