Re: slow output in *compilation* buffer

[Dan Nicolaescu]

Stefan Monnier <address@hidden> 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