Profiling Vim

Lately, I’ve noticed that opening Markdown files in Vim is slow. I don’t know exactly how slow, but slow enough that I notice a pause after opening the file before I can edit it. I’m not sure why or when it started, but it’s painful enough that I want to track down and alleviate it.

Fortunately, Vim has profiling tools that can help (learn more with :help profile). In this post I’ll iterate the steps I went through to track down the slowness using those tools.

In my case, the slow part is opening a Markdown file. Once opened, navigating and editing feels fine. To profile the opening of a file, I launch Vim and run the following commands:

:profile start vim-markdown.log
:profile file *
:profile func *
:e foo.md
:q

• :profile start vim-markdown.log tells Vim to begin profiling and save the output to a file called vim-markdown.log
• :profile file * tells Vim to profile Vimscript files (plugins, mostly) that match the given pattern, in this case * matches all of them
• :profile func * tells Vim to profile all functions
• :e foo.md opens a Markdown file, which I’ve classified as the slow part
• :q quits because our experiment has been conducted

I now have a bunch of profiling information in a vim-markdown.log file. It’s broken down by script (file), then by individual function calls. The “Total time” is how long it took to execute each file/function including its children, while the “Self time” is the time minus the children.

This is the first entry in my file:

SCRIPT  /Users/thorn/.vim/ftplugin/markdown.vim
Sourced 2 times
Total time:   0.000101
 Self time:   0.000101

That’s a file I have in my dotfiles to makes the settings and mappings I want for Markdown files. The total time it took is less than a millisecond, so probably not contributing to my slowdown. I don’t know why it was sourced twice. 🤷

I’m going to scan through the rest of this file, looking at the section summaries for times that stand out. In Vim, I’m using the /^SCRIPT search term.

This entry catches my eye:

SCRIPT  /Users/thorn/.vim/plugged/vim-markdown/syntax/markdown.vim
Sourced 2 times
Total time:   0.421129
 Self time:   0.012444

421ms is certainly long enough to notice! This has to be the problem file. The much lower Self time is interesting. It seems the slowness is coming from other scripts as a result of something here. Since I enabled function profiling, I can go line by line looking for outliers.

Here’s the first one that stands out:

count  total (s)   self (s)

    2   0.109486   0.001499 runtime! syntax/html.vim

109ms to load… the HTML syntax file? I’m confused by this at first, but Markdown is a superset of HTML, so it makes sense to support HTML syntax highlighting.

Moving on, I come to this line:

count  total (s)   self (s)

   16   0.307634   0.006936   exe 'syn include @markdownHighlight'.substitute(s:type,'\.','','g').' syntax/'.matchstr(s:type,'[^.]*').'.vim'

307ms! I’m not totally sure what’s happening here, other than it’s executing something related to syntax highlighting. I’ll take a look at the lines around this one to try to get some context:

count  total (s)   self (s)

   22              0.000303 for s:type in map(copy(g:markdown_fenced_languages),'matchstr(v:val,"[^=]*$")')
   20              0.000278   if has_key(s:done_include, matchstr(s:type,'[^.]*'))
    4              0.000045     continue
   16              0.000012   endif
   16              0.000054   if s:type =~ '\.'
                                let b:{matchstr(s:type,'[^.]*')}_subtype = matchstr(s:type,'\.\zs.*')
   16              0.000012   endif
   16   0.307634   0.006936   exe 'syn include @markdownHighlight'.substitute(s:type,'\.','','g').' syntax/'.matchstr(s:type,'[^.]*').'.vim'
   16              0.000033   unlet! b:current_syntax
   16              0.000201   let s:done_include[matchstr(s:type,'[^.]*')] = 1
   18              0.000044 endfor

I can see that this line is executed within a for loop that’s iterating over a variable called g:markdown_fenced_languages. Okay, it seems in order to support syntax highlighting in code blocks, vim-markdown loads the syntax files (which in turn loads related plugins) for all the languages that are specified in the g:markdown_fenced_languages variable. I vaguely recall setting that value in my dotfiles, but I can’t remember the details. I take a look there and I see:

let g:markdown_fenced_languages = ['coffee', 'css', 'erb=eruby', 'javascript', 'js=javascript', 'json=javascript', 'ruby', 'sass', 'xml', 'html']

There are quite a few! The reasons for the slowness are now apparent - every time I open a Markdown file, I’m paying the cost for Coffeescript, CSS, ERB, JavaScript, Ruby, Sass, XML, and HTML. Yikes.

I don’t actually use fenced code blocks that much, so syntax highlighting them is a low priority for me. I decide to disable that feature by removing the config value entirely. Rerunning the experiment, I can tell it’s much faster. Taking a look at the new log file, I see:

SCRIPT  /Users/thorn/.vim/plugged/vim-markdown/syntax/markdown.vim
Sourced 2 times
Total time:   0.098814
 Self time:   0.002827

That’s 98ms, down from 421ms - quite a reduction! 📉