Profile of current guile HEAD

[Andy Wingo]

Hey,

Some more data points. I just profiled a run of guile -c 1 from HEAD.
This is what callgrind says about which functions are taking the most
time:

cumulative   self      total
 percent    percent    calls    file:function
   23.15     19.30     151231   
ports.c:scm_getc[/opt/guile-head/lib/libguile.so.18.0.0]
16928.38      7.08      12577   
read.c:scm_read_expression[/opt/guile-head/lib/libguile.so.18.0.0]
    6.45      6.45      93110   ???:pthread_getspecific[/lib/libpthread-2.6.so]
    6.16      6.12        372   
gc-card.c:scm_i_sweep_card[/opt/guile-head/lib/libguile.so.18.0.0]
  106.76      4.83       9747   
inline.h:ceval[/opt/guile-head/lib/libguile.so.18.0.0]
    4.12      4.11      27101   
ports.c:scm_ungetc[/opt/guile-head/lib/libguile.so.18.0.0]
   27.79      4.04      66030   
gc-mark.c:scm_gc_mark[/opt/guile-head/lib/libguile.so.18.0.0]
   23.63      3.71      14562   
gc-mark.c:scm_gc_mark_dependencies[/opt/guile-head/lib/libguile.so.18.0.0]
   17.20      2.93      28946   
pairs.c:scm_cons[/opt/guile-head/lib/libguile.so.18.0.0]
    2.68      2.22       8810   
symbols.c:lookup_interned_symbol[/opt/guile-head/lib/libguile.so.18.0.0]
  411.68      2.21      16758   
inline.h:flush_ws[/opt/guile-head/lib/libguile.so.18.0.0]
    5.80      1.91          6   
weaks.c:scm_i_mark_weak_vectors_non_weaks[/opt/guile-head/lib/libguile.so.18.0.0]
    2.38      1.74       2052   ???:0x0000AB30[/lib/ld-2.6.so]
    1.65      1.60      19977   
ports.c:scm_fill_input[/opt/guile-head/lib/libguile.so.18.0.0]
    1.43      1.43        288   
gc-card.c:scm_i_init_card_freelist[/opt/guile-head/lib/libguile.so.18.0.0]
   24.34      1.21     151126   
???:0x000DE440[/opt/guile-head/lib/libguile.so.18.0.0]
   18.50      1.16       8800   
symbols.x:scm_i_c_mem2symbol[/opt/guile-head/lib/libguile.so.18.0.0]
    1.15      1.15       8810   
hash.c:scm_string_hash[/opt/guile-head/lib/libguile.so.18.0.0]
    2.60      1.10       6674   
alist.c:scm_acons[/opt/guile-head/lib/libguile.so.18.0.0]
    7.29      1.05       2052   ???:0x0000AFC0[/lib/ld-2.6.so]
    1.02      1.02       6572   ???:pthread_mutex_lock[/lib/libpthread-2.6.so]

There are more, of course. I think that the 0x0000* functions are the
PLT entries, which callgrind on PPC doesn't know how to filter out
(apparently).

The summary of this is that we (meaning, erm, Ludovic) kicked some ass
in making the reader not create so much garbage. The biggest win now
would probably be some kind of byte compilation so that the reader can
be simpler, strings and symbols can be encoded with their lengths, etc.
Probably older hands know of good strategies; is it normal that startup
cost is 40-50% in `read'?

I still think that the TLS patch can help with the pthread_getspecific
stuff; I should profile with that patch. Later maybe.

FWIW, here's a profile of (use-modules (oop goops)):

cumulative   self      total
 percent    percent    calls    file:function
   13.74     11.62     238008   
ports.c:scm_getc[/opt/guile-head/lib/libguile.so.18.0.0]
 1332.06     10.32      56710   
eval.i.c:ceval[/opt/guile-head/lib/libguile.so.18.0.0]
    9.31      9.31     351261   ???:pthread_getspecific[/lib/libpthread-2.6.so]
    7.92      7.88       1386   
gc-card.c:scm_i_sweep_card[/opt/guile-head/lib/libguile.so.18.0.0]
  104.30      6.28      57497   
gc-mark.c:scm_gc_mark_dependencies[/opt/guile-head/lib/libguile.so.18.0.0]
  109.48      5.00     207620   
gc-mark.c:scm_gc_mark[/opt/guile-head/lib/libguile.so.18.0.0]
 9107.65      4.52      20827   
read.c:scm_read_expression[/opt/guile-head/lib/libguile.so.18.0.0]
   15.28      2.83      73045   
pairs.c:scm_cons[/opt/guile-head/lib/libguile.so.18.0.0]
    2.62      2.61      44968   
ports.c:scm_ungetc[/opt/guile-head/lib/libguile.so.18.0.0]
    6.34      2.14         15   
weaks.c:scm_i_mark_weak_vectors_non_weaks[/opt/guile-head/lib/libguile.so.18.0.0]
    8.65      1.79      28332   
alist.c:scm_acons[/opt/guile-head/lib/libguile.so.18.0.0]
    1.77      1.46      14287   
symbols.c:lookup_interned_symbol[/opt/guile-head/lib/libguile.so.18.0.0]
  231.59      1.35      27545   
inline.h:flush_ws[/opt/guile-head/lib/libguile.so.18.0.0]
    1.41      1.05      17112   
hashtab.c:scm_hash_fn_get_handle[/opt/guile-head/lib/libguile.so.18.0.0]
    1.05      1.01      33135   
ports.c:scm_fill_input[/opt/guile-head/lib/libguile.so.18.0.0]

Reading is still probably the highest cost here, but seeing ceval so
high normally means that most of the time is spent in Scheme code.
Obviously a fair bit of garbage is being generated as well. Perhaps with
microoptimizations in scm_getc() (or avoiding calling it) and with the
TLS patch, we can lower (oop goops) load time to 1.6 levels.

Regards,

Andy.
-- 
http://wingolog.org/