Re: slow output in *compilation* buffer

[Dan Nicolaescu <dann@ics.uci.edu>]

Stefan Monnier <monnier@IRO.UMontreal.CA> writes:

  > >> - It seems that they the calls to the interval code come from
  > >> compilation-error-properties, but that function should only be called
  > >> for regexps that do match, which shouldn't be that many.  Can you look
  > >> at the text to see if there really are that many matches?  BTW, we
  > >> should probably be able to make compile.el a bit lazier (i.e. the
  > >> font-lock-phase part of the code should do a bit less work by moving
  > >> it to the next-error-phase code).
  > > The output is about 4500 lines, they all match.
  > 
  > Ah, I see.  So yes, the likely solution is to make compile.el lazier:
  > use font-lock-syntactic-keywords and jit-lock (so the text past the end
  > of the window doesn't need to be scanned right away), and postpone more
  > of the work to next-error.

elp says that most time is spent in `compilation-error-properties', if
that helps...

  > > BTW, doing the same search with M-x rgrep is MUCH MUCH slower.
  > 
  > That sucks.  What does rgrep do so differently to make it even worse?

My guess would be more highlighting: it also highlights the matched words on
each line.

  >   > > They time spent there seems a bit excessive, so maybe something strange
  > > is going on...
  > 
  > That's also possible.

  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
 33.02      2.46     2.46 50974295     0.00     0.00  lookup_char_property
 21.61      4.07     1.61 50847996     0.00     0.00  previous_interval
 13.83      5.10     1.03 204112526     0.00     0.00  Fcdr
  7.25      5.64     0.54 50946735     0.00     0.00  Fassq
  6.17      6.10     0.46     4509     0.00     0.00  Fprevious_single_property_change

elp says there are 9018 calls to `compilation-error-properties'
The file has 4509 lines, and it's fontified twice (M-x compilation-mode + M-x font-lock-fontify-buffer)

That means 50974295/4509 = 11305 lookup_char_property calls per Fprevious_single_property_change ... 
that sounds a bit excessive.

Now lets just double the input file (cat input input > input2) and
perform the same experiment on the new file.
 
  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
 37.86     12.09    12.09 203594871     0.00     0.00  lookup_char_property
 21.20     18.86     6.77 203351394     0.00     0.00  previous_interval
 17.38     24.41     5.55 814793814     0.00     0.00  Fcdr
  5.98     26.32     1.91     9018     0.00     0.00  Fprevious_single_property_change

203594871/9018 = 22576