cl:time in 7.2

[David Wilkins <munnari!munmurra.mu.oz.au!dew@uunet.uu.net>]

I have noticed a remarkable drop in performance in 7.2 and weird
behaviour from cl:time and wonder if anyone can explain these to me.

I am running a system named SIPE on a 3645 w/fpa -- all code run on
7.2 has been compiled in 7.2.  The code makes heavy use of arrays.

SIPE seems to take nearly twice as long to solve the same problem in 7.2
as it did in 7.1.  Is there any reason for this?  This is as reported by
cl:time function --- define ETIME by subtracting time spent in storage
system and processing sequence breaks from the elapsed time.  In 7.2,
ETIME varies wildly (I always do this when the machine is doing nothing
else -- I just sit there and watch it -- and it is serving no one.).  In
7.1, ETIME was always 40-45 sec plus or minus 8 sec on my robot problem.
IN 7.2, it is usually 70 secs plus or minus 50 secs.  Most often it is
about 70 secs, once it was 100 (perhaps something else used the
machine?), BUT a couple times it was around 35 sec and ONCE it was 18
sec!!  I have never got it ever again to run in less than 30 sec.   Any
idea what all this means?  Can SIPE really solve this problem in 18 sec
if things work right?  How come it usually takes 70 seconds?  The 18 sec
run was 18 seconds total elapsed time -- there was no time spent in the
storage system.  Does that have something to do with why it went so fast?

For comparison, I copied all the .lisp files to a new directory and
compiled them in 7.1.  So these time are for exactly the same code in
7.1 and 7.2.  Below are typical results of cl:time:

7.2 with ephemeral and dynamic GCs off:  (this used to take 40 seconds in 7.1!!!)

Evaluation of (RW* (EVAL XX1) (OR CON XX2) XX3 ADVICE) took 99.942741 seconds of elapsed time including:
  1.220 seconds processing sequence breaks,
  12.987 seconds in the storage system (including 11.481 seconds waiting for pages):
    12.483 seconds processing 1769 page faults including 523 fetches,
    0.505 seconds in creating and destroying pages, and
    0.000 seconds in miscellaneous storage system tasks.
91,258 list, 35,348 structure words consed in WORKING-STORAGE-AREA.
4,311 structure words consed in PNAME-AREA.
7,185 structure words consed in SYMBOL-AREA.
2,874 list words consed in PKG-AREA.
14 list, 368 structure words consed in *PRESENTATION-AREA*.

7.2 with ephemeral GC on:

Evaluation of (RW* (EVAL XX1) (OR CON XX2) XX3 ADVICE) took 78.314850 seconds of elapsed time including:
  0.913 seconds processing sequence breaks,
  3.978 seconds in the storage system (including 2.571 seconds waiting for pages):
    2.937 seconds processing 1152 page faults including 100 fetches,
    1.016 seconds in creating and destroying pages, and
    0.026 seconds in miscellaneous storage system tasks.
The garbage collector has flipped; so no consing was measured.


exact same code in 7.1 with GCs off:

Evaluation of (RW* (EVAL XX1) (OR CON XX2) XX3 ADVICE) took 45.454050 seconds of elapsed time
including 1.022 seconds waiting for the disk for 0 faults.
101,610 list, 34,841 structure words consed in WORKING-STORAGE-AREA.
4,311 structure words consed in PNAME-AREA.
7,185 structure words consed in SYMBOL-AREA.
192 structure words consed in *BOX-AREA*.
111 structure words consed in *STRING-AREA*.