Re: slow output in *compilation* buffer

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

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.