Profiling Vim to Find Out Which Plugin Makes Vim Slow

Vim is pretty fast and powerful. However, the core of Vim is (yet) single-threaded (some discussions and tries on porting Vim to be multi-threading, but not yet there). This means some functions that are slow will block Vim there and you have to wait for it. While Vim is fast, some plugins are not. When Vim turns to be slow, it is very likely caused by one or more plugins.

However, Vim users tend to have a bunch of plugins installed and managed by pathogen, Vindle (my preference, my Vim configs) or manually. Guessing and trying out which plugins are slow from 10s of plugins is no fun. For these situations, the profiling mechanism in Vim will help you out.

Find out which plugin makes Vim slow to start

You can profile the startup process of Vim by adding the --startuptime option during starting Vim as follows.

vim --startuptime profile.log

One example profile.log is as follows for you reference.

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

000.018  000.018: --- VIM STARTING ---
000.113  000.095: Allocated generic buffers
000.188  000.075: locale set
000.193  000.005: window checked
000.593  000.400: inits 1
000.636  000.043: parsing arguments
000.637  000.001: expanding arguments
000.648  000.011: shell init
000.858  000.210: Termcap init
000.877  000.019: inits 2
000.981  000.104: init highlight
001.417  000.142  000.142: sourcing /usr/share/vim/vim74/syntax/syncolor.vim
001.505  000.266  000.124: sourcing /usr/share/vim/vim74/syntax/synload.vim
018.452  000.044  000.044: sourcing /usr/share/vim/vimfiles/ftdetect/stp.vim
018.565  017.026  016.982: sourcing /usr/share/vim/vim74/filetype.vim
018.595  017.396  000.104: sourcing /usr/share/vim/vim74/syntax/syntax.vim
018.633  000.007  000.007: sourcing /usr/share/vim/vim74/filetype.vim
018.689  000.028  000.028: sourcing /usr/share/vim/vim74/ftplugin.vim
018.716  017.704  000.273: sourcing /etc/vimrc
019.066  000.264  000.264: sourcing /usr/share/vim/vim74/ftoff.vim
019.459  000.179  000.179: sourcing /home/zma/.vim/bundle/Vundle.vim/autoload/vundle.vim
019.660  000.137  000.137: sourcing /home/zma/.vim/bundle/Vundle.vim/autoload/vundle/config.vim
038.883  000.076  000.076: sourcing /home/zma/.vim/bundle/omlet.vim/ftdetect/omlet.vim
038.999  000.052  000.052: sourcing /usr/share/vim/vimfiles/ftdetect/stp.vim
039.267  017.721  017.593: sourcing /usr/share/vim/vim74/filetype.vim
...
...
084.542  065.800  046.465: sourcing $HOME/.vimrc
084.557  000.072: sourcing vimrc file(s)
085.672  000.971  000.971: sourcing /home/zma/.vim/bundle/YouCompleteMe/plugin/youcompleteme.vim
100.023  014.292  014.292: sourcing /home/zma/.vim/bundle/AutoTag/plugin/autotag.vim
100.321  000.016  000.016: sourcing /home/zma/.vim/bundle/Syntastic/plugin/syntastic/autoloclist.vim
...
...
114.569  014.046  012.347: sourcing /home/zma/.vim/bundle/Syntastic/plugin/syntastic.vim
115.107  000.470  000.470: sourcing /home/zma/.vim/bundle/taglist.vim/plugin/taglist.vim
117.816  002.652  002.652: sourcing /home/zma/.vim/bundle/The-NERD-tree/plugin/NERD_tree.vim
118.277  000.392  000.392: sourcing /home/zma/.vim/bundle/snipMate/plugin/snipMate.vim
119.694  001.353  001.353: sourcing /home/zma/.vim/bundle/TinyBufferExplorer/plugin/tbe.vim
149.035  029.274  029.274: sourcing /home/zma/.vim/bundle/LustyJuggler/plugin/lusty-juggler.vim
149.397  000.274  000.274: sourcing /home/zma/.vim/bundle/vim-slime/plugin/slime.vim
149.628  000.069  000.069: sourcing /usr/share/vim/vim74/plugin/getscriptPlugin.vim
...
...
152.029  000.491  000.491: sourcing /home/zma/.vim/bundle/snipMate/after/plugin/snipMate.vim
152.097  001.635: loading plugins
152.106  000.009: inits 3
152.510  000.404: reading viminfo
152.519  000.009: setting raw mode
152.538  000.019: start termcap
152.576  000.038: clearing screen
220.202  000.173  000.173: sourcing /usr/share/vim/vim74/ftplugin/c.vim
265.430  000.066  000.066: sourcing /usr/share/vim/vim74/indent/c.vim
310.045  001.924  001.924: sourcing /usr/share/vim/vim74/syntax/c.vim
349.111  000.230  000.230: sourcing /usr/share/vim/vim74/indoff.vim
349.373  194.404: opening buffers
350.037  000.141  000.141: sourcing /usr/share/vim/vim74/ftplugin/c.vim
352.132  001.410  001.410: sourcing /usr/share/vim/vim74/syntax/c.vim
352.761  000.181  000.181: sourcing /home/zma/.vim/bundle/Syntastic/autoload/syntastic/log.vim
353.582  002.477: BufEnter autocommands
353.584  000.002: editing files in windows
354.535  000.865  000.865: sourcing /home/zma/.vim/bundle/YouCompleteMe/autoload/youcompleteme.vim
505.914  000.134  000.134: sourcing /home/zma/.vim/bundle/The-NERD-tree/nerdtree_plugin/exec_menuitem.vim
506.267  000.312  000.312: sourcing /home/zma/.vim/bundle/The-NERD-tree/nerdtree_plugin/fs_menu.vim
506.772  151.877: VimEnter autocommands
506.773  000.001: before starting main loop
511.890  003.069  003.069: sourcing /home/zma/project/vim-config/.vim/bundle/taglist.vim/plugin/taglist.vim
512.093  002.251: first screen update
512.095  000.002: --- VIM STARTED ---

Overall, Vim took around half a second to start. Among the plugins, lustyjuggler and syntastic took the most time to initialize themselves, while both are still fine as they took only 10s of microseconds. If Vim turned to be slow because of some plugins, the suspicious ones will show up in the list with lots time used shown in the profile log.

Find out which plugin makes Vim run slowly for certain actions

Vim also supports profiling of operations during using Vim to help us find out why one operation in Vim is slow.

First, enable the profiling before doing the slow operation by:

:profile start profile.log
:profile func *
:profile file *

Then you can do the slow action in Vim as usual.

After doing the slow actions, you can stop the profiling by:

:profile pause
:wq

In the profile.log, you can check the profiling of the functions called.

If there are plugins that are very slow, the profiling results will show you the suspicious ones. You may try to disable these plugins and see whether Vim can turn to be faster or profile again.

The profile.log is usually quite large depending on the number of functions called. One example profile.log I got during saving a Scala source file can be found here.

You can directly go to the summary at the end of the profile.log and check the results. The summary from the above example is as follows.

FUNCTIONS SORTED ON TOTAL TIME
count  total (s)   self (s)  function
    1 127.616234   0.000035  <SNR>27_BufWritePostHook()
    1 127.616184   0.000131  <SNR>27_UpdateErrors()
    1 127.615884   0.000138  <SNR>27_CacheErrors()
    1 127.586013   0.000019  16()
    1 127.585994   0.000104  15()
    1 127.585890   0.000054  SyntaxCheckers_scala_fsc_GetLocList()
    1 127.585429   0.000217  SyntasticMake()
    1   0.029151   0.000056  78()
    1   0.029048   0.028209  85()
    2   0.003059   0.000067  <SNR>50_OnCursorHold()
    2   0.002786   0.002718  <SNR>50_OnFileReadyToParse()
    1   0.001322             <SNR>37_Highlight_Matching_Pair()
    6   0.000725   0.000672  Tlist_Get_Tagname_By_Line()
    1   0.000719   0.000494  AutoTag()
    3   0.000377   0.000068  77()
    1   0.000352   0.000041  18()
    1   0.000339   0.000030  <SNR>27_ClearCache()
    5   0.000262   0.000115  24()
    1   0.000242   0.000164  74()
    1   0.000225   0.000116  <SNR>29_Tlist_Update_Current_File()

FUNCTIONS SORTED ON SELF TIME
count  total (s)   self (s)  function
    1   0.029048   0.028209  85()
    2   0.002786   0.002718  <SNR>50_OnFileReadyToParse()
    1              0.001322  <SNR>37_Highlight_Matching_Pair()
    6   0.000725   0.000672  Tlist_Get_Tagname_By_Line()
    1   0.000719   0.000494  AutoTag()
    1 127.585429   0.000217  SyntasticMake()
    3              0.000202  10()
    1   0.000242   0.000164  74()
    2              0.000152  <SNR>50_AllowedToCompleteInCurrentFile()
    1 127.615884   0.000138  <SNR>27_CacheErrors()
    1 127.616184   0.000131  <SNR>27_UpdateErrors()
   15              0.000118  syntastic#util#argsescape()
    1   0.000225   0.000116  <SNR>29_Tlist_Update_Current_File()
    5   0.000262   0.000115  24()
    1 127.585994   0.000104  15()
    2   0.000124   0.000089  <SNR>27__skip_file()
    3   0.000083   0.000075  83()
    3   0.000377   0.000068  77()
    2   0.003059   0.000067  <SNR>50_OnCursorHold()
    7              0.000058  <SNR>29_Tlist_Get_File_Index()

In this example, SyntaxCheckers_scala_fsc_GetLocList() and SyntasticMake() (called by SyntaxCheckers_scala_fsc_GetLocList() if you look at the top parts of the profile.log for the function) cost more than 127 seconds. And Vim was also blocked for that long time. Actually, I had to press “Ctrl-C” to stop the operation.

From the profiling results, it seems that “syntastic” plugin was trying to compile the Scala source file and find whether there were errors. Compiling Scala source file takes lots time and sbt is a better tool to do this. Hence, I disabled automatic syntactic check for Scala from syntastic by adding the line let g:syntastic_scala_checkers=[''] to my ~/.vimrc file. After this, Vim is fast again for saving Scala source files.

Eric Zhiqiang Ma

Eric is interested in building high-performance and scalable distributed systems and related technologies. The views or opinions expressed here are solely Eric's own and do not necessarily represent those of any third parties.

2 comments:

Leave a Reply

Your email address will not be published. Required fields are marked *