Re: (seeks while reading) Re: Performance, argh

[Greg Badros <gjb@cs.washington.edu>]

Telford Tendys <telford@eng.uts.edu.au> writes:

<snip>

> I'm still fiddling with the libguile.so.4 from the Debian slink binary
> release so I'm not up with the latest snapshots. However, when I do an
> strace on a guile program I notice horribly large numbers of seek() and
> read() operations happening. It seems to read ahead a long way and then
> seek back for each and every character! Am I out of touch and this is
> a known bug that is already fixed? Is it on the TODO list? My guess is
> that this is what is eating the startup time.

<snip>

Well, there was a horrible performance bug in guile-1.3;  if you're
guile is not using this patch:

--- libguile/ports.h    1998/10/30 08:22:50     1.33
+++ libguile/ports.h    1998/11/05 16:02:55     1.34
@@ -93,7 +93,7 @@
 #define SCM_CRDY       (32L<<16) /* Should char-ready? return #t? */
 
 /* A mask used to clear the char-ready port flag. */
-#define SCM_CUC                0x001fffffL
+#define SCM_CUC                (~SCM_CRDY)
 
 #define SCM_PORTP(x) (SCM_TYP7(x)==scm_tc7_port)
 #define SCM_OPPORTP(x) (((0x7f | SCM_OPN) & SCM_CAR(x))==(scm_tc7_port | SCM_OP
N))


Then it will be much slower than it needs to be.

That said, guile does seem to spend an inordinate amount of time in
system calls (on PPro200, Linux 2.2.x, libc5, with guile installed in a
directory read via NFS):

% strace -c guile -c '(+ 1 2)' 
execve("/uns/bin/guile", ["guile", "-c", "(+ 1 2)"], [/* 92 vars */]) = 0
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 42.89    0.184235        2193        84        70 access
 28.05    0.120460        2231        54        40 stat
 17.43    0.074850        1826        41           read
  6.63    0.028495         750        38        22 open
  3.17    0.013606        1512         9           fstat
  1.06    0.004544         126        36           mmap
  0.29    0.001257          31        40           select
  0.13    0.000579          17        35           times
  0.13    0.000562          35        16           munmap
  0.11    0.000467          21        22           brk
  0.06    0.000259          16        16           close
  0.02    0.000106          15         7           mprotect
  0.02    0.000071          36         2           ioctl
  0.00    0.000013          13         1           personality
  0.00    0.000010          10         1           time
  0.00    0.000006           6         1           getpid
------ ----------- ----------- --------- --------- ----------------
100.00    0.429520                   403       132 total

% strace -c perl -e '1 + 2;'  
execve("/uns/bin/perl", ["perl", "-e", "1 + 2;"], [/* 92 vars */]) = 0
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 29.55    0.000476          20        24           mmap
 25.45    0.000410          41        10         2 open
 18.56    0.000299          20        15           brk
  7.57    0.000122          17         7           munmap
  7.08    0.000114          16         7           mprotect
  4.90    0.000079          10         8           close
  1.55    0.000025           8         3           sigprocmask
  1.12    0.000018           9         2           getpid
  0.99    0.000016          16         1           personality
  0.87    0.000014          14         1           fstat
  0.56    0.000009           9         1           time
  0.50    0.000008           8         1           getuid
  0.50    0.000008           8         1           getgid
  0.43    0.000007           7         1           getegid
  0.37    0.000006           6         1           geteuid
------ ----------- ----------- --------- --------- ----------------
100.00    0.001611                    83         2 total

Greg