Re: GC timing

[danny@farallon.com (Danny Brewer)]

In article <9111042017.AA04003@aristotle.ils.nwu.edu>, lynch@aristotle.ils.nwu.edu writes:
> 
> The Man wants some psycho testing done with the program.  No sweat, I say. 
> Then I remember GC.  Is there some way of testing if/when a GC occurs
> and/or how much time it takes?
> "TANSTAAFL" Rich lynch@ils.nwu.edu
> 
[You can skip the explanation and see the answer near the end.]
The TIME macro reports GC times.  The form (TIME <form>) under MCL 2.0b1p3 fully expands into
something like this:

(LET (#:G111 #:G109 #:G110 #:G112)
  (MULTIPLE-VALUE-PROG1 (PROGN
                          (SETQ #:G111
                                (%GET-LONG (%GET-PTR (%INT-TO-PTR 2308))
                                           -310))
                          (SETQ #:G109 (%GET-LONG (%INT-TO-PTR 362)))
                          (SETQ #:G110
                                (%GET-LONG (%GET-PTR (%INT-TO-PTR 2308))
                                           -348))
                          (SETQ #:G112 (CCL::TOTAL-BYTES-ALLOCATED))
                          <FORM>)
    (CCL::REPORT-TIME '<FORM>
                      (- (%GET-LONG (%INT-TO-PTR 362)) #:G109)
                      (- (%GET-LONG (%GET-PTR (%INT-TO-PTR 2308)) -348)
                         #:G110)
                      (- (%GET-LONG (%GET-PTR (%INT-TO-PTR 2308)) -310)
                         #:G111)
                      (- (CCL::TOTAL-BYTES-ALLOCATED) #:G112)))) 

It looks like the first temporary #:G111 is being set to some longword that is -310 bytes
off of A5, which would be one of MCL's global variables.  (Location 2308 is the low memory
global called CurrentA5.)  The second #:G109 gets set to the low memory global Ticks
[location 362].  This is much more efficient than using the trap form (#_TickCount).  And
#:G110 is set to -348 bytes off register A5.

Later, after <form> is evaluated, you can see that the same values are collected again
and passed to CCL::REPORT-TIME.  If you call CCL::REPORT-TIME yourself, you can see how it
uses it's arguments.  (CCL::REPORT-TIME '<form> 123 15 456 789) prints out the following...

<FORM> took 123 ticks (2.050 seconds) to run.
Of that, 108 ticks (1.800 seconds) were spent in The Cooperative Multitasking Experience.
Of that, 456 ticks (7.600 seconds) was spent in GC.
 789 bytes of memory allocated.

The third argument represents the time spent in GC.  (BTW, the 108 = 123-15)

So in answer to your question, You could save the value of
(%GET-LONG (%GET-PTR (%INT-TO-PTR 2308)) -310).  Then later compute this value again, and
the difference would represent the time spent in GC.  BUT SEE THE CAUTION BELOW!!!

The value at -310 off A5 must represent the total time spent in GC since MCL started up.
And the value at -348 off A5 must have something to do with the cooperative multitasking
experience time.

WARNING DANGER WILL ROBINSON -- The values of -310 and -348 off A5 might change in any
future release of MCL.  (Although I believe the values are even the same under MCL 1.3.2.
Maybe somebody could check this out?)