Macro

Summary

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

Package

hcl

Signature

extended-time &body body

Arguments

body

The 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. 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 (6 calls) ...

indicates that there were 6 Standard GCs in which the highest generation collected was 1.

Example

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

See also

time