Profiling Vim to Find Out Which Plugin Makes Vim Slow
Posted on In Linux, Programming, Software, TutorialVim 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.
Great post. Thanks for sharing.
Thanks. It’s great to know you like it.
Any idea what the lines with SNR refer to and how to find the packages they’re pulling from? I’m gathering they might be builitin functions. For example, what is this?
27_BufWritePostHook()
Possibly from syntastic.vim:
https://github.com/vim-syntastic/syntastic/blob/master/plugin/syntastic.vim#L309