slow output in *compilation* buffer

slow output in *compilation* buffer

[Dan Nicolaescu]

Running a compilation job the produces a lot of text output with M-x
compile is much slower than running it in a shell.

For example

With emacs/lisp as the current directory, doing
M-x compile RET grep -nH -e emacs *.el */*.el RET
takes 25 seconds 
The output is 4500 lines

Running the same command in an xterm takes 1.5 seconds!


gprof data:

  %   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

Observations:
- there's a lot of garbage collection going on
- Fprevious_single_property_change is probably mostly called from
  compilation-error-properties

Doing 
M-x (setq compilation-error-regexp-alist nil) RET
then
M-x compile RET grep -nH -e emacs *.el */*.el RET
takes 3 seconds.

So it seems that fontification (and things related to it) are very very expensive.

Can someone familiar with the code in question take a look and figure
out how to optimize this?

Thanks

        --dan

Re: slow output in *compilation* buffer

[Stefan Monnier]

>   %   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.
- why does the gprof data only seem to account for a bit less than 10s
  when you say it takes 25s to complete?
- 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).

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.


        Stefan

Re: slow output in *compilation* buffer

[Dan Nicolaescu]

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

Re: slow output in *compilation* buffer

[Dan Nicolaescu]

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
  > 
  > compile.el does its work via font-lock, so I do expect most/all of the
  > time to be spent there.

Another data point, take the process output out of the equation: 
grep -nH -e emacs *.el */*.el > /tmp/t.grep

emacs -Q /tmp/t.grep
M-x compilation-mode RET
M-x font-lock-fontify-buffer RET    [this might not be necessary]


  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
 35.13      5.54     5.54 102003560     0.00     0.00  lookup_char_property
 22.45      9.08     3.54 101705026     0.00     0.00  previous_interval
 13.57     11.22     2.14 408455379     0.00     0.00  Fcdr
  6.59     12.26     1.04     9018     0.00     0.00  Fprevious_single_property_change
  5.83     13.18     0.92 101946549     0.00     0.00  Fassq
  2.98     13.65     0.47    18460     0.00     0.00  Fsetcar
  1.71     13.92     0.27  9370435     0.00     0.00  mark_object
  1.59     14.17     0.25 102003522     0.00     0.00  textget
  1.46     14.40     0.23    54635     0.00     0.00  re_search_2
  1.14     14.58     0.18   134737     0.00     0.00  Fbyte_code
  0.95     14.73     0.15                             adjust_for_invis_intang
  0.95     14.88     0.15   525629     0.00     0.00  re_match_2_internal
  0.82     15.01     0.13   262725     0.00     0.00  next_interval
  0.63     15.11     0.10     2698     0.00     0.00  Frassq
  0.44     15.18     0.07       22     0.00     0.02  Fgarbage_collect
  0.32     15.23     0.05   541671     0.00     0.00  Ffuncall
  0.32     15.28     0.05    22906     0.00     0.00  mark_vectorlike
  0.19     15.31     0.03   584428     0.00     0.00  balance_an_interval
  0.13     15.33     0.02  2333591     0.00     0.00  multibyte_char_to_unibyte_safe
  0.13     15.35     0.02   315105     0.00     0.00  find_interval
  0.13     15.37     0.02   133764     0.00     0.00  funcall_lambda
  0.13     15.39     0.02    91236     0.00     0.00  add_properties
  0.13     15.41     0.02    18261     0.00     0.00  set_point_both
  0.13     15.43     0.02     9448     0.00     0.00  balance_intervals_internal
  0.13     15.45     0.02     5316     0.00     0.00  set_buffer_internal_1
  0.13     15.47     0.02       92     0.00     0.00  mark_glyph_matrix
  0.13     15.49     0.02                             Fmemory_limit
  0.06     15.50     0.01  1006998     0.00     0.00  specbind
  0.06     15.51     0.01   718455     0.00     0.00  Fcons
  0.06     15.52     0.01   621053     0.00     0.00  Faref

Re: slow output in *compilation* buffer

[Chong Yidong]

Dan Nicolaescu <dann@ics.uci.edu> writes:

> Another data point, take the process output out of the equation:
> grep -nH -e emacs *.el */*.el > /tmp/t.grep
>
> emacs -Q /tmp/t.grep
> M-x compilation-mode RET
> M-x font-lock-fontify-buffer RET    [this might not be necessary]

Could you also try with the Emacs 22 version of
compilation-error-regexp-alist-alist?

Re: slow output in *compilation* buffer

[Dan Nicolaescu]

Chong Yidong <cyd@stupidchicken.com> writes:

  > Dan Nicolaescu <dann@ics.uci.edu> writes:
  > 
  > > Another data point, take the process output out of the equation:
  > > grep -nH -e emacs *.el */*.el > /tmp/t.grep
  > >
  > > emacs -Q /tmp/t.grep
  > > M-x compilation-mode RET
  > > M-x font-lock-fontify-buffer RET    [this might not be necessary]
  > 
  > Could you also try with the Emacs 22 version of
  > compilation-error-regexp-alist-alist?

It was easier to just try with emacs 22's version of compile.elc:

 time   seconds   seconds    calls   s/call   s/call  name    
 36.30      5.96     5.96 101988546     0.00     0.00  lookup_char_property
 20.46      9.32     3.36 101705047     0.00     0.00  previous_interval
 16.69     12.06     2.74 408403635     0.00     0.00  Fcdr
  6.03     13.05     0.99 101936877     0.00     0.00  Fassq
  4.57     13.80     0.75     9018     0.00     0.00  Fprevious_single_property_change
  3.47     14.37     0.57    18432     0.00     0.00  Fsetcar
  1.52     14.62     0.25  8893438     0.00     0.00  mark_object
  1.46     14.86     0.24  1393971     0.00     0.00  re_match_2_internal
  1.16     15.05     0.19        2     0.10     0.10  adjust_for_invis_intang
  1.10     15.23     0.18   134046     0.00     0.00  Fbyte_code
  0.97     15.39     0.16 101988546     0.00     0.00  textget
  0.97     15.55     0.16    51481     0.00     0.00  re_search_2
  0.73     15.67     0.12     2686     0.00     0.00  Frassq
  0.37     15.73     0.06   259939     0.00     0.00  next_interval
  0.37     15.79     0.06       21     0.00     0.02  Fgarbage_collect
  0.30     15.84     0.05    19575     0.00     0.00  mark_vectorlike
  0.24     15.88     0.04   501674     0.00     0.00  unbind_to
  0.18     15.91     0.03  1046758     0.00     0.00  specbind
  0.18     15.94     0.03   307777     0.00     0.00  find_interval
  0.18     15.97     0.03    11545     0.00     0.00  Flocal_variable_p
  0.12     15.99     0.02   618496     0.00     0.00  Faref
  0.12     16.01     0.02   539810     0.00     0.00  Ffuncall
  0.12     16.03     0.02   116540     0.00     0.00  Fstring_equal
  0.12     16.05     0.02    64204     0.00     0.00  Fadd_text_properties
  0.12     16.07     0.02    63142     0.00     0.00  internal_equal
  0.12     16.09     0.02    28438     0.00     0.00  set_internal
  0.12     16.11     0.02    21596     0.00     0.00  re_compile_pattern
  0.06     16.12     0.01   612304     0.00     0.00  Fcar

Re: slow output in *compilation* buffer

[Dan Nicolaescu]

Dan Nicolaescu <dann@ics.uci.edu> writes:

  > 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
  >   > 
  >   > compile.el does its work via font-lock, so I do expect most/all of the
  >   > time to be spent there.
  > 
  > Another data point, take the process output out of the equation: 
  > grep -nH -e emacs *.el */*.el > /tmp/t.grep
  > 
  > emacs -Q /tmp/t.grep
  > M-x compilation-mode RET
  > M-x font-lock-fontify-buffer RET    [this might not be necessary]
  > 
  > 
  >   %   cumulative   self              self     total           
  >  time   seconds   seconds    calls   s/call   s/call  name    
  >  35.13      5.54     5.54 102003560     0.00     0.00  lookup_char_property
  >  22.45      9.08     3.54 101705026     0.00     0.00  previous_interval
  >  13.57     11.22     2.14 408455379     0.00     0.00  Fcdr
  >   6.59     12.26     1.04     9018     0.00     0.00  Fprevious_single_property_change
  >   5.83     13.18     0.92 101946549     0.00     0.00  Fassq
  >   2.98     13.65     0.47    18460     0.00     0.00  Fsetcar
  >   1.71     13.92     0.27  9370435     0.00     0.00  mark_object
  >   1.59     14.17     0.25 102003522     0.00     0.00  textget
  >   1.46     14.40     0.23    54635     0.00     0.00  re_search_2
  >   1.14     14.58     0.18   134737     0.00     0.00  Fbyte_code
  >   0.95     14.73     0.15                             adjust_for_invis_intang
  >   0.95     14.88     0.15   525629     0.00     0.00  re_match_2_internal
  >   0.82     15.01     0.13   262725     0.00     0.00  next_interval
  >   0.63     15.11     0.10     2698     0.00     0.00  Frassq
  >   0.44     15.18     0.07       22     0.00     0.02  Fgarbage_collect
  >   0.32     15.23     0.05   541671     0.00     0.00  Ffuncall
  >   0.32     15.28     0.05    22906     0.00     0.00  mark_vectorlike
  >   0.19     15.31     0.03   584428     0.00     0.00  balance_an_interval
  >   0.13     15.33     0.02  2333591     0.00     0.00  multibyte_char_to_unibyte_safe
  >   0.13     15.35     0.02   315105     0.00     0.00  find_interval
  >   0.13     15.37     0.02   133764     0.00     0.00  funcall_lambda
  >   0.13     15.39     0.02    91236     0.00     0.00  add_properties
  >   0.13     15.41     0.02    18261     0.00     0.00  set_point_both
  >   0.13     15.43     0.02     9448     0.00     0.00  balance_intervals_internal
  >   0.13     15.45     0.02     5316     0.00     0.00  set_buffer_internal_1
  >   0.13     15.47     0.02       92     0.00     0.00  mark_glyph_matrix
  >   0.13     15.49     0.02                             Fmemory_limit
  >   0.06     15.50     0.01  1006998     0.00     0.00  specbind
  >   0.06     15.51     0.01   718455     0.00     0.00  Fcons
  >   0.06     15.52     0.01   621053     0.00     0.00  Faref

And another data point and some explanation.
Using -Q -nw instead of just -Q:

 %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
 34.58      5.19     5.19 101981134     0.00     0.00  lookup_char_property
 21.19      8.37     3.18 101705010     0.00     0.00  previous_interval
 13.06     10.33     1.96 408395117     0.00     0.00  Fcdr
  6.73     11.34     1.01     9018     0.00     0.00  Fprevious_single_property_change
  6.73     12.35     1.01 101923589     0.00     0.00  Fassq
  3.06     12.81     0.46    18459     0.00     0.00  Fsetcar
  1.93     13.10     0.29   514797     0.00     0.00  re_match_2_internal
  1.73     13.36     0.26  5072134     0.00     0.00  mark_object
  1.60     13.60     0.24    31816     0.00     0.00  re_search_2
  1.27     13.79     0.19   133095     0.00     0.00  Fbyte_code
  1.20     13.97     0.18   256789     0.00     0.00  next_interval
  1.07     14.13     0.16     2555     0.00     0.00  Frassq
  1.07     14.29     0.16                             adjust_for_invis_intang
  1.00     14.44     0.15 101981134     0.00     0.00  textget
  0.40     14.50     0.06   300850     0.00     0.00  find_interval
  0.40     14.56     0.06       19     0.00     0.02  Fgarbage_collect
  0.27     14.60     0.04   132114     0.00     0.00  funcall_lambda

so roughly 40% less mark_object calls.

Why?
Although I use LANG=C, when using the X11 version (with this font:
-b&h-lucidatypewriter-medium-r-normal-sans-12-120-75-75-m-70-iso8859-1)

these charsets are read during startup:

emacs/etc/charsets/MULE-tibetan.map
emacs/etc/charsets/MULE-ethiopic.map
emacs/etc/charsets/MULE-ipa.map
emacs/etc/charsets/symbol.map
emacs/etc/charsets/JISX0208.map
emacs/etc/charsets/GB2312.map
emacs/etc/charsets/BIG5.map
emacs/etc/charsets/CNS-1.map
emacs/etc/charsets/KSC5601.map

and it seems that creates a lot of lisp objects.
Is it necessary to read all these charsets?
Creating that many lisp objects has second order effects on GC speed,
and cache performance.

Re: slow output in *compilation* buffer

[Stefan Monnier]

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

No, indeed, luckily.

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

Maybe it's just the user-time vs system-time.

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

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

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

That's also possible.


        Stefan

Re: slow output in *compilation* buffer

[David Kastrup]

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

>>> - 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?
>
> No, indeed, luckily.
>
>>> - 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.
>
> Maybe it's just the user-time vs system-time.
>
>>> - 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.
>
>> 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?
>
>> They time spent there seems a bit excessive, so maybe something strange
>> is going on...
>
> That's also possible.

Does

(setq process-adaptive-read-buffering nil)

make a difference?  I have the suspicion that this still exhibits
pathological behavior sometimes.

-- 
David Kastrup

Re: slow output in *compilation* buffer

[Dan Nicolaescu]

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

Re: slow output in *compilation* buffer

[Stefan Monnier]

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

Yes.  We should remove the call to previous-single-property-change from
that function and move it to next-error instead.

After all, the property we look for is almost never used, so
this previous-single-property-change takes time O(N) where N is the
amount of output that has already been received.  So overall, it causes
an O(N^2) behavior since it is called O(N) times.

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

That's possible, but I'd expect there's something more at play here.

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

Since lookup_char_property will be called for each interval (i.e. chunk
of text with the same text-properties) between point and the previous
position where the property of interest is changed (which will usually
be (point-min) in our case), I think it's about right (let's see: 4500
lines, each line has at least 3-4 chunks with different properties, for
a total of about 20000 chunks, so about 10000 scanned per call on
average).


        Stefan