extended-time

extended-time Macro

Summary

Prints useful timing information, including information on garbage collection (GC) activity.

Package

hcl

Signature

extended-time &body body

Arguments

body⇩

The Lisp forms to be timed.

Description

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, all in seconds. The rows of the GC breakdown indicate the type of activity.

In 32-bit LispWorks these rows begin:

`main promote`	indicates promotions from generation 0.
`internal promote`	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.
`fixup`	is a part of the compaction and promotion process.

In 64-bit LispWorks these rows begin:

`Standard gen-num (n calls)`
	indicates `n` Standard GCs (includes automatic GCs and calls to gc-generation) in which the highest generation collected was `gen-num`.
`Marking gen-num (n calls)`
	indicates `n` Marking GCs (includes calls to marking-gc) in which the highest generation collected was `gen-num`.

Thus in the example below:

Standard  1  (    1 calls) ...

indicates that there was 1 Standard GC in which the highest generation collected was 1.

Notes

extended-time does not print Garbage Collector times if it is used while GC timing is on (after start-gc-timing is called, and before get-gc-timing is called with reset non-nil).

Examples

This example illustrates output in 32-bit LispWorks:

CL-USER 57 > (extended-time (foo))
Timing the evaluation of (PROGN (FOO))
 
User time    =       26.703
System time  =        0.109
Elapsed time =       27.047
Allocation   = 40021902832 bytes
0 Page faults
 
                                      total    /   user     /   system
total gc activity              =      3.312500 /   3.312500 /   0.000000
main promote (    1 calls)     =      0.000000 /   0.000000 /   0.000000
mark and sweep ( 7305 calls)   =      3.312500 /   3.312500 /   0.000000
internal promote (    0 calls) =      0.000000 /   0.000000 /   0.000000
promote (    0 calls)          =      0.000000 /   0.000000 /   0.000000
fixup (    1 calls)            =      0.000000 /   0.000000 /   0.000000
compact (    0 calls)          =      0.000000 /   0.000000 /   0.000000
10006387712
0.0

This example illustrates output in 64-bit LispWorks:

CL-USER 3 > (extended-time (foo))
Timing the evaluation of (PROGN (FOO))
 
User time    =       11.433
System time  =        0.268
Elapsed time =       11.197
Allocation   = 80040251696 bytes
5 Page faults
 
                                  total    /   user     /   system
total gc activity          =      2.168062 /   2.126444 /   0.041618
Standard  0  (28545 calls) =      2.153886 /   2.119799 /   0.034087
Standard  1  (    1 calls) =      0.014176 /   0.006645 /   0.007531
10006387712
0.0