Interpreting the output when using --startuptime

Question

When I use the --startuptime <file> option, vim generates an output file. I've included an example at the bottom of this post.

How can I interpret the output? I can't find documentation to verify my assumptions (I checked :help startuptime).

The preamble suggests that lines are of one of two forms:

1. clock self+sourced self: sourced script
2. clock elapsed: other lines

Interpreting form 1 lines seems straightforward, with times corresponding to the described event. However, I'm not sure what exactly is meant by other lines (assuming I've interpreted the preamble correctly).

For the form 2 lines, what are the definitions of self+sourced and self? I have assumed the former corresponds to loading time including time for recursively :source'd files, and the latter corresponds to loading time excluding time for recursively :source'd files.

What does the sourcing vimrc file(s) line's time represent? There is a separate line for $HOME/.vimrc, with a time greater than given for sourcing vimrc file(s).

Similarly, what does the loading plugins line's time represent? The preceding lines also correspond to plugins, and the sum of the times does not match the loading plugins time.

Example:

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

000.011  000.011: --- VIM STARTING ---
000.149  000.138: Allocated generic buffers
000.757  000.608: locale set
000.761  000.004: clipboard setup
000.770  000.009: window checked
001.565  000.795: inits 1
001.577  000.012: parsing arguments
001.578  000.001: expanding arguments
012.666  011.088: shell init
013.157  000.491: Termcap init
013.174  000.017: inits 2
013.360  000.186: init highlight
015.671  001.128  001.128: sourcing /usr/local/share/vim/vim82/syntax/syncolor.vim
015.851  001.490  000.362: sourcing /usr/local/share/vim/vim82/syntax/synload.vim
023.584  007.559  007.559: sourcing /usr/local/share/vim/vim82/filetype.vim
023.644  009.518  000.469: sourcing /usr/local/share/vim/vim82/syntax/syntax.vim
023.810  000.024  000.024: sourcing /usr/local/share/vim/vim82/filetype.vim
023.968  000.021  000.021: sourcing /usr/local/share/vim/vim82/filetype.vim
024.170  000.056  000.056: sourcing /usr/local/share/vim/vim82/ftplugin.vim
024.326  000.021  000.021: sourcing /usr/local/share/vim/vim82/filetype.vim
024.524  000.056  000.056: sourcing /usr/local/share/vim/vim82/indent.vim
025.633  011.850  002.154: sourcing $HOME/.vimrc
025.641  000.431: sourcing vimrc file(s)
026.743  000.087  000.087: sourcing /usr/local/share/vim/vim82/plugin/getscriptPlugin.vim
027.089  000.265  000.265: sourcing /usr/local/share/vim/vim82/plugin/gzip.vim
027.499  000.326  000.326: sourcing /usr/local/share/vim/vim82/plugin/logiPat.vim
027.651  000.050  000.050: sourcing /usr/local/share/vim/vim82/plugin/manpager.vim
027.965  000.234  000.234: sourcing /usr/local/share/vim/vim82/plugin/matchparen.vim
028.739  000.692  000.692: sourcing /usr/local/share/vim/vim82/plugin/netrwPlugin.vim
028.956  000.038  000.038: sourcing /usr/local/share/vim/vim82/plugin/rrhelper.vim
029.179  000.093  000.093: sourcing /usr/local/share/vim/vim82/plugin/spellfile.vim
029.526  000.228  000.228: sourcing /usr/local/share/vim/vim82/plugin/tarPlugin.vim
029.757  000.135  000.135: sourcing /usr/local/share/vim/vim82/plugin/tohtml.vim
030.055  000.211  000.211: sourcing /usr/local/share/vim/vim82/plugin/vimballPlugin.vim
030.379  000.219  000.219: sourcing /usr/local/share/vim/vim82/plugin/zipPlugin.vim
031.020  000.382  000.382: sourcing /usr/local/share/vim/vim82/pack/dist/opt/matchit/plugin/matchit.vim
032.073  000.812  000.812: sourcing /usr/local/share/vim/vim82/pack/dist/opt/termdebug/plugin/termdebug.vim
032.081  002.668: loading plugins
032.198  000.117: loading packages
032.245  000.047: loading after plugins
032.251  000.006: inits 3
041.476  009.225: reading viminfo
041.548  000.072: setting raw mode
041.556  000.008: start termcap
041.574  000.018: clearing screen
041.684  000.110: opening buffers
041.745  000.061: BufEnter autocommands
041.751  000.006: editing files in windows
042.152  000.401: VimEnter autocommands
042.154  000.002: before starting main loop
043.052  000.898: first screen update
043.054  000.002: --- VIM STARTED ---

Answer 1

How can I interpret the output? I can't find documentation to verify my assumptions (I checked :help startuptime).

See just below :h :profd:

You must always start with a ":profile start fname" command. The resulting file is written when Vim exits. Here is an example of the output, with line numbers prepended for the explanation:

  1 FUNCTION  Test2() ~
  2 Called 1 time ~
  3 Total time:   0.155251 ~
  4  Self time:   0.002006 ~
  5  ~
  6 count  total (s)   self (s) ~
  7   9          0.000096   for i in range(8) ~
  8   8   0.153655   0.000410     call Test3() ~
  9   8          0.000070   endfor ~
 10                 " Ask a question ~
 11   1          0.001341   echo input("give me an answer: ") ~

The header (lines 1-4) gives the time for the whole function. The "Total" time is the time passed while the function was executing. The "Self" time is the "Total" time reduced by time spent in:

• other user defined functions
• sourced scripts
• executed autocommands
• external (shell) commands

Lines 7-11 show the time spent in each executed line. Lines that are not executed do not count. Thus a comment line is never counted.

The Count column shows how many times a line was executed. Note that the "for" command in line 7 is executed one more time as the following lines. That is because the line is also executed to detect the end of the loop.

The time Vim spends waiting for user input isn't counted at all. Thus how long you take to respond to the input() prompt is irrelevant.

Profiling should give a good indication of where time is spent, but keep in mind there are various things that may clobber the results:

• The accuracy of the time measured depends on the gettimeofday() system function. It may only be as accurate as 1/100 second, even though the times are displayed in micro seconds.

• Real elapsed time is measured, if other processes are busy they may cause delays at unpredictable moments. You may want to run the profiling several times and use the lowest results.

• If you have several commands in one line you only get one time. Split the line to see the time for the individual commands.

• The time of the lines added up is mostly less than the time of the whole function. There is some overhead in between.

• Functions that are deleted before Vim exits will not produce profiling information. You can check the |v:profiling| variable if needed: > :if !v:profiling : delfunc MyFunc :endif <

• Profiling may give weird results on multi-processor systems, when sleep mode kicks in or the processor frequency is reduced to save power.

• The "self" time is wrong when a function is used recursively.

---

The preamble suggests that lines are of one of two forms:

clock   self+sourced   self:  sourced script
clock   elapsed:              other lines

Interpreting form 1 lines seems straightforward, with times corresponding to the described event. However, I'm not sure what exactly is meant by other lines (assuming I've interpreted the preamble correctly).

There are 2 types of lines in the output; those with 4 fields:

015.671  001.128       001.128:  sourcing /usr/local/share/vim/vim82/syntax/syncolor.vim
^^^^^^^  ^^^^^^^       ^^^^^^^^  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
field 1  field 2       field 3   field 4
clock    self+sourced  self:     sourced script

And those with 3 fields:

000.149  000.138:  Allocated generic buffers
^^^^^^^  ^^^^^^^^  ^^^^^^^^^^^^^^^^^^^^^^^^^
field 1  field 2   field 3
clock    elapsed   other lines

"other lines" refers to the third field in lines with only 3 fields.

---

For the form 2 lines, what are the definitions of self+sourced and self? I have assumed the former corresponds to loading time including time for recursively :source'd files, and the latter corresponds to loading time excluding time for recursively :source'd files.

If self has the same meaning as in the output of :prof start, it's documented like this:

The "Self" time is the "Total" time reduced by time spent in:

• other user defined functions
• sourced scripts
• executed autocommands
• external (shell) commands

---

What does the sourcing vimrc file(s) line's time represent? There is a separate line for $HOME/.vimrc, with a time greater than given for sourcing vimrc file(s).

Just a guess, but it may be the time taken by Vim to find the vimrc file on your system... If you want to look at the source code, the relevant line is here.

---

Similarly, what does the loading plugins line's time represent? The preceding lines also correspond to plugins, and the sum of the times does not match the loading plugins time.

Again, just a guess, but it may be the time taken by Vim to find all your plugin files on your system (i.e. all the files in your runtime path matching the glob plugin/**/*.vim)... If you want to look at the source code, the relevant line is here.