Prints useful timing information, including information on garbage collection (GC) activity.
The macro
extended-time
runs the forms in
body
. It then prints a summary of the time taken followed by a breakdown of time spent in the GC.
The three columns of the GC breakdown show, respectively, total time, user time, and system time. The rows of the GC breakdown indicate the type of activity.
In 32-bit LispWorks these rows begin:
indicates promotions from generation 0.
indicates when an attempt to promote from one generation to the next causes promotion of the higher generation, to make room for the objects from the lower generation.
is a part of the compaction and promotion process.
In 64-bit LispWorks these rows begin:
indicates n Standard GCs (includes automatic GCs and calls to gc-generation) in which the highest generation collected was gen-num .
indicates n Marking GCs (includes calls to marking-gc) in which the highest generation collected was gen-num .
Standard 1 (6 calls) ...
indicates that there were 6 Standard GCs in which the highest generation collected was 1.
This example illustrates output in 32-bit LispWorks:
CL-USER 2 > (extended-time (foo))
Timing the evaluation of (FOO)
User time = 7.203
System time = 0.046
Elapsed time = 7.265
Allocation = 84011236 bytes
0 Page faults
Calls to %EVAL 23000075
total / user / system
total gc activity =2.125000/ 2.078125/ 0.046875
main promote (9 calls) =1.640625/ 1.593750/ 0.046875
mark and sweep (12 calls) =0.484375/ 0.484375/ 0.000000
internal promote (3 calls)=0.437500/ 0.421875/ 0.015625
promote (0 calls) =0.000000/ 0.000000/ 0.000000
fixup (21 calls) =0.562500/ 0.562500/ 0.000000
compact (0 calls) =0.000000/ 0.000000/ 0.000000
537870911
This example illustrates output in 64-bit LispWorks:
CL-USER 2 > (extended-time (foo))
Timing the evaluation of (FOO)
User time = 4.468
System time = 0.208
Elapsed time = 4.716
Allocation = 96030696 bytes
0 Page faults
total / user / system
total gc activity = 1.148826 / 0.959855 / 0.188971
Standard 1 (6 calls) = 0.761885 / 0.632905 / 0.128980
Standard 2 (1 calls) = 0.386941 / 0.326950 / 0.059991
1152921504607846975