Re: slow output in *compilation* buffer

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

Stefan Monnier <monnier@iro.umontreal.ca> writes:

  > >   %   cumulative   self              self     total           
  > >  time   seconds   seconds    calls   s/call   s/call  name    
  > >  31.19      2.72     2.72 52618323     0.00     0.00  lookup_char_property
  > >  20.30      4.49     1.77 51726150     0.00     0.00  previous_interval
  > >  12.16      5.55     1.06 208889310     0.00     0.00  Fcdr
  > >   5.85      6.06     0.51 52444384     0.00     0.00  Fassq
  > >   5.39      6.53     0.47     4573     0.00     0.00  Fprevious_single_property_change
  > >   2.64      6.76     0.23  8860105     0.00     0.00  mark_object
  > >   2.52      6.98     0.22    10621     0.00     0.00  Fsetcar
  > >   2.29      7.18     0.20 52618300     0.00     0.00  textget
  > >   1.83      7.34     0.16    59828     0.00     0.00  re_search_2
  > >   1.72      7.49     0.15   305181     0.00     0.00  re_match_2_internal
  > >   1.03      7.58     0.09    82087     0.00     0.00  Fbyte_code
  > >   0.80      7.65     0.07     9094     0.00     0.00  adjust_for_invis_intang
  > >   0.80      7.72     0.07   581767     0.00     0.00  find_interval
  > >   0.69      7.78     0.06   295253     0.00     0.00  next_interval
  > >   0.69      7.84     0.06       21     0.00     0.02  Fgarbage_collect
  > >   0.57      7.89     0.05    23886     0.00     0.00  mark_vectorlike
  > 
  > - not sure why it's GCing that much, but it sounds like something that
  >   can be improved.
  > - the re_* part of the profile is hard to improve with a quick fix,
  >   I think: it just represents regexp-searching every one of the regexps
  >   in compilation-error-regexp-alist in turn.  Of course, there is a way
  >   to do that (a lot) faster, by compiling all those regexps into a DFA.

That sounds like a good idea, but it does not look like it will have a
huge impact?

  > - why does the gprof data only seem to account for a bit less than 10s
  >   when you say it takes 25s to complete?

Don't know.  I double checked and it's consistent.  Maybe oprofile can
reveal more, I might try that too when I get a chance  if nobody  beats
me to it.

  > - 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.

BTW, doing the same search with M-x rgrep is MUCH MUCH slower.

  > Another thing: the compilation code currently uses font-lock-keywords,
  > but it should probably be changed to use font-lock-syntactic-keywords
  > instead (which should make it unnecessary to disable jit-lock).
  > 
  > > So it seems that fontification (and things related to it) are very very expensive.
  > 
  > compile.el does its work via font-lock, so I do expect most/all of the
  > time to be spent there.

They time spent there seems a bit excessive, so maybe something strange
is going on...