Use timers to identify slow[est] parts of vim-easytags

See also https://github.com/xolox/vim-easytags/pull/80 where I suggested
to add accurate timing to the vim-easytags plug-in. Here it is :-). This
is still quite rudimentary but it's already an improvement over what was
there before!

3 files changed, 85 insertions, 21 deletions

diff --git a/README.md b/README.md
index 5b4640a..978b56a 100644
--- a/README.md
+++ b/README.md
@@ -265,6 +265,23 @@ This option defines the pathname of the script that contains the Python implemen
 
 ## Troubleshooting
 
+## vim-easytags is slow!
+
+Yes, I know. I'm trying to make it faster but that's far from trivial. In the process of trying to speed up vim-easytags I've added reporting of elapsed time in several ways. If Vim seems very slow and you suspect this plug-in might be the one to blame, increase Vim's verbosity level:
+
+    :set vbs=1
+
+Every time the plug-in executes it will time how long the execution takes and add the results to Vim's message history, which you can view by executing the [:messages] [messages] command. If you want a more fine grained impression of the time spent by vim-easytags on various operations you can call the `xolox#easytags#why_so_slow()` function:
+
+    :call xolox#easytags#why_so_slow()
+    easytags.vim 3.6.4: Timings since you started Vim:
+     - 0.094937 seconds updating tags
+     - 1.850201 seconds highlighting tags
+     - 0.035167 seconds highlighting tags using ':syntax match')
+     - 0.493910 seconds highlighting tags using ':syntax keyword')
+     - 0.413160 seconds filtering tags for highlighting (stage 1)
+     - 0.141747 seconds filtering tags for highlighting (stage 2)
+
 ### `:HighlightTags` only works for the tags file created by `:UpdateTags`
 
 If you want to create tags files and have their tags highlighted by the `easytags.vim` plug-in then you'll have to create the tags file with certain arguments to Exuberant Ctags:
@@ -299,12 +316,6 @@ Once or twice now in several years I've experienced Exuberant Ctags getting into
 
     $ pkill -KILL ctags
 
-If Vim seems very slow and you suspect this plug-in might be the one to blame, increase Vim's verbosity level:
-
-    :set vbs=1
-
-Every time the plug-in executes it will time how long the execution takes and add the results to Vim's message history, which you can view by executing the [:messages] [messages] command.
-
 ### Failed to highlight tags because pattern is too big!
 
 If the `easytags.vim` plug-in fails to highlight your tags and the error message mentions that the pattern is too big, your tags file has grown too large for Vim to be able to highlight all tagged identifiers! I've had this happen to me with 50 KB patterns because I added most of the headers in `/usr/include/` to my tags file. Internally Vim raises the error [E339: Pattern too long] [e339] and unfortunately the only way to avoid this problem once it occurs is to reduce the number of tagged identifiers...
diff --git a/autoload/xolox/easytags.vim b/autoload/xolox/easytags.vim
index b98fb2b..f450785 100644
--- a/autoload/xolox/easytags.vim
+++ b/autoload/xolox/easytags.vim
@@ -1,12 +1,22 @@
 " Vim script
 " Author: Peter Odding <peter@peterodding.com>
-" Last Change: July 9, 2014
+" Last Change: July 19, 2014
 " URL: http://peterodding.com/code/vim/easytags/
 
-let g:xolox#easytags#version = '3.6.3'
+let g:xolox#easytags#version = '3.6.4'
 let g:xolox#easytags#default_pattern_prefix = '\C\<'
 let g:xolox#easytags#default_pattern_suffix = '\>'
 
+if !exists('s:timers_initialized')
+  let g:xolox#easytags#update_timer = xolox#misc#timer#resumable()
+  let g:xolox#easytags#highlight_timer = xolox#misc#timer#resumable()
+  let g:xolox#easytags#syntax_match_timer = xolox#misc#timer#resumable()
+  let g:xolox#easytags#syntax_keyword_timer = xolox#misc#timer#resumable()
+  let g:xolox#easytags#syntax_filter_stage_1_timer = xolox#misc#timer#resumable()
+  let g:xolox#easytags#syntax_filter_stage_2_timer = xolox#misc#timer#resumable()
+  let s:timers_initialized = 1
+endif
+
 " Plug-in initialization. {{{1
 
 function! xolox#easytags#initialize(min_version) " {{{2
@@ -155,6 +165,7 @@ endfunction
 
 function! xolox#easytags#update(silent, filter_tags, filenames) " {{{2
   let async = xolox#misc#option#get('easytags_async', 0)
+  call g:xolox#easytags#update_timer.start()
   try
     let have_args = !empty(a:filenames)
     let starttime = xolox#misc#timer#start()
@@ -162,7 +173,7 @@ function! xolox#easytags#update(silent, filter_tags, filenames) " {{{2
     let tagsfile = xolox#easytags#get_tagsfile()
     let command_line = s:prep_cmdline(cfile, tagsfile, a:filenames)
     if empty(command_line)
-      return
+      return 0
     endif
     " Pack all of the information required to update the tags in
     " a Vim dictionary which is easy to serialize to a string.
@@ -191,6 +202,8 @@ function! xolox#easytags#update(silent, filter_tags, filenames) " {{{2
     return 1
   catch
     call xolox#misc#msg#warn("easytags.vim %s: %s (at %s)", g:xolox#easytags#version, v:exception, v:throwpoint)
+  finally
+    call g:xolox#easytags#update_timer.stop()
   endtry
 endfunction
 
@@ -279,6 +292,7 @@ endfunction
 function! xolox#easytags#highlight() " {{{2
   " TODO This is a mess; Re-implement Python version in Vim script, benchmark, remove Python version.
   try
+    call g:xolox#easytags#highlight_timer.start()
     " Treat C++ and Objective-C as plain C.
     let filetype = xolox#easytags#filetypes#canonicalize(&filetype)
     let tagkinds = get(s:tagkinds, filetype, [])
@@ -304,7 +318,9 @@ function! xolox#easytags#highlight() " {{{2
             " Get the list of tags when we need it and remember the results.
             let ctags_filetypes = xolox#easytags#filetypes#find_ctags_aliases(filetype)
             let filetypes_pattern = printf('^\(%s\)$', join(map(ctags_filetypes, 'xolox#misc#escape#pattern(v:val)'), '\|'))
+            call g:xolox#easytags#syntax_filter_stage_1_timer.start()
             let taglist = filter(taglist('.'), "get(v:val, 'language', '') =~? filetypes_pattern")
+            call g:xolox#easytags#syntax_filter_stage_1_timer.stop()
           endif
           " Filter a copy of the list of tags to the relevant kinds.
           if has_key(tagkind, 'tagkinds')
@@ -312,7 +328,9 @@ function! xolox#easytags#highlight() " {{{2
           else
             let filter = tagkind.vim_filter
           endif
+          call g:xolox#easytags#syntax_filter_stage_2_timer.start()
           let matches = filter(copy(taglist), filter)
+          call g:xolox#easytags#syntax_filter_stage_2_timer.stop()
           if matches != []
             " Convert matched tags to :syntax commands and execute them.
             let use_keywords_when = xolox#misc#option#get('easytags_syntax_keyword', 'auto')
@@ -326,6 +344,7 @@ function! xolox#easytags#highlight() " {{{2
               " keyword command when 1) we can do so without sacrificing
               " accuracy or 2) the user explicitly chose to sacrifice
               " accuracy in order to make the highlighting faster.
+              call g:xolox#easytags#syntax_keyword_timer.start()
               let keywords = {}
               for tag in matches
                 if s:is_keyword_compatible(tag)
@@ -341,8 +360,10 @@ function! xolox#easytags#highlight() " {{{2
                 " tags that still need to be highlighted.
                 call filter(matches, "!s:is_keyword_compatible(v:val)")
               endif
+              call g:xolox#easytags#syntax_keyword_timer.stop()
             endif
             if !empty(matches)
+              call g:xolox#easytags#syntax_match_timer.start()
               let matches = xolox#misc#list#unique(map(matches, 'xolox#misc#escape#pattern(get(v:val, "name"))'))
               let pattern = tagkind.pattern_prefix . '\%(' . join(matches, '\|') . '\)' . tagkind.pattern_suffix
               let template = 'syntax match %s /%s/ containedin=ALLBUT,%s'
@@ -354,6 +375,7 @@ function! xolox#easytags#highlight() " {{{2
                 let msg = "easytags.vim %s: Failed to highlight %i %s tags because pattern is too big! (%i KB)"
                 call xolox#misc#msg#warn(msg, g:xolox#easytags#version, len(matches), tagkind.hlgroup, len(pattern) / 1024)
               endtry
+              call g:xolox#easytags#syntax_match_timer.stop()
             endif
           endif
         endif
@@ -373,6 +395,8 @@ function! xolox#easytags#highlight() " {{{2
     endif
   catch
     call xolox#misc#msg#warn("easytags.vim %s: %s (at %s)", g:xolox#easytags#version, v:exception, v:throwpoint)
+  finally
+    call g:xolox#easytags#highlight_timer.stop()
   endtry
 endfunction
 
@@ -490,6 +514,17 @@ function! xolox#easytags#restore_automatic_updates() " {{{2
   endif
 endfunction
 
+function! xolox#easytags#why_so_slow() " {{{2
+  let message = [printf("easytags.vim %s: Timings since you started Vim:",  g:xolox#easytags#version)]
+  call add(message, printf(" - %s seconds updating tags", g:xolox#easytags#update_timer.format()))
+  call add(message, printf(" - %s seconds highlighting tags", g:xolox#easytags#highlight_timer.format()))
+  call add(message, printf(" - %s seconds highlighting tags using ':syntax match')", g:xolox#easytags#syntax_match_timer.format()))
+  call add(message, printf(" - %s seconds highlighting tags using ':syntax keyword')", g:xolox#easytags#syntax_keyword_timer.format()))
+  call add(message, printf(" - %s seconds filtering tags for highlighting (stage 1)", g:xolox#easytags#syntax_filter_stage_1_timer.format()))
+  call add(message, printf(" - %s seconds filtering tags for highlighting (stage 2)", g:xolox#easytags#syntax_filter_stage_2_timer.format()))
+  echo join(message, "\n")
+endfunction
+
 " Public API for definition of file type specific dynamic syntax highlighting. {{{1
 
 function! xolox#easytags#define_tagkind(object) " {{{2
diff --git a/doc/easytags.txt b/doc/easytags.txt
index f1f9820..99ae24c 100644
--- a/doc/easytags.txt
+++ b/doc/easytags.txt
@@ -35,14 +35,15 @@ Contents ~
   1. The |g:easytags_python_enabled| option
   2. The |g:easytags_python_script| option
  7. Troubleshooting                                  |easytags-troubleshooting|
+ 8. vim-easytags is slow!                                |vim-easytags-is-slow|
   1. |:HighlightTags| only works for the tags file created by |:UpdateTags| |easytags-highlighttags-only-works-for-tags-file-created-by-updatetags|
   2. The plug-in complains that Exuberant Ctags isn't installed |easytags-plug-in-complains-that-exuberant-ctags-isnt-installed|
   3. Vim locks up while the plug-in is running |easytags-vim-locks-up-while-plug-in-is-running|
   4. Failed to highlight tags because pattern is too big! |easytags-failed-to-highlight-tags-because-pattern-is-too-big|
   5. The plug-in doesn't seem to work in Cygwin |easytags-plug-in-doesnt-seem-to-work-in-cygwin|
- 8. Contact                                                  |easytags-contact|
- 9. License                                                  |easytags-license|
- 10. References                                           |easytags-references|
+ 9. Contact                                                  |easytags-contact|
+ 10. License                                                 |easytags-license|
+ 11. References                                           |easytags-references|
 
 ===============================================================================
                                                         *easytags-introduction*
@@ -556,6 +557,32 @@ implementation of dynamic syntax highlighting.
                                                      *easytags-troubleshooting*
 Troubleshooting ~
 
+===============================================================================
+                                                         *vim-easytags-is-slow*
+vim-easytags is slow! ~
+
+Yes, I know. I'm trying to make it faster but that's far from trivial. In the
+process of trying to speed up vim-easytags I've added reporting of elapsed time
+in several ways. If Vim seems very slow and you suspect this plug-in might be
+the one to blame, increase Vim's verbosity level:
+>
+  :set vbs=1
+<
+Every time the plug-in executes it will time how long the execution takes and
+add the results to Vim's message history, which you can view by executing the
+|:messages| command. If you want a more fine grained impression of the time
+spent by vim-easytags on various operations you can call the
+'xolox#easytags#why_so_slow()' function:
+>
+  :call xolox#easytags#why_so_slow()
+  easytags.vim 3.6.4: Timings since you started Vim:
+   - 0.094937 seconds updating tags
+   - 1.850201 seconds highlighting tags
+   - 0.035167 seconds highlighting tags using ':syntax match')
+   - 0.493910 seconds highlighting tags using ':syntax keyword')
+   - 0.413160 seconds filtering tags for highlighting (stage 1)
+   - 0.141747 seconds filtering tags for highlighting (stage 2)
+<
 -------------------------------------------------------------------------------
         *easytags-highlighttags-only-works-for-tags-file-created-by-updatetags*
 :HighlightTags only works for the tags file created by :UpdateTags ~
@@ -618,15 +645,6 @@ command (available on most UNIX systems):
 >
   $ pkill -KILL ctags
 <
-If Vim seems very slow and you suspect this plug-in might be the one to blame,
-increase Vim's verbosity level:
->
-  :set vbs=1
-<
-Every time the plug-in executes it will time how long the execution takes and
-add the results to Vim's message history, which you can view by executing the
-|:messages| command.
-
 -------------------------------------------------------------------------------
                  *easytags-failed-to-highlight-tags-because-pattern-is-too-big*
 Failed to highlight tags because pattern is too big! ~