Monitoring Garbage Collection in Racket

Recently, Matthew Flatt added programmatic logging of garbage collection events in Racket. Based on this, I’ve built a tool for summarizing the GC behavior of Racket programs. Here’s an example of how to use it:

% racket -l gcstats -u my-program.rkt

This says to first require the gcstats module before running my-program.rkt . When you do this you’ll get a big printout after your program runs; below the fold, we’ll take a look at each line in detail.

39,703,916 bytes allocated in the heap 28,890,688 bytes collected by GC 17,083,432 bytes max heap size 16,604,120 bytes max slop 28,229,632 bytes peak total memory use Generation 0: 5 collections, 32ms, 31.71ms elapsed Generation 1: 0 collections, 0ms, 0ms elapsed INIT time 256 ms MUT time 132 ms ( 129.98 ms elapsed) GC time 32 ms ( 31.71 ms elapsed) TOTAL time 420 ms ( 417.69 ms elapsed) %GC time 19.51% ( 19.61% elapsed) Alloc rate 300,787,242 bytes per MUT second

To install, follow the instructions on the GitHub page.

Right now, the tool is preliminary, but useful. There are a few limitations:

There are a few GCs before the tool starts — it can’t report anything about them. If you have multiple places, it will only report information from the initial place. Fixing this will require more information from Racket. The current architecture keeps too much info around during the run of the program. I hope to fix that soon.

Hopefully, this gives people some better information about how the Racket GC behaves. The output formatting and information gathered is inspired by similar output from the GHC runtime system.

Now let’s return to a detailed look at the output.

2,715,625,408 bytes allocated in the heap

How many bytes, total, were allocated by the program

2,687,494,428 bytes collected by GC

How many bytes, total, were collected during the run of the program

73,728,640 bytes max heap size

The largest heap size observed at any GC

66,748,764 bytes max slop

The largest difference between the memory allocated and the memory

the GC has reserved.

85,884,928 bytes peak total memory use

The largest total memory use, including GC overhead.

Generation 0: 147 collections, 1,120ms, 1,157.53ms elapsed

How many nursery collections there were, and how long they took, in both process and elapsed time.

Generation 1: 6 collections, 596ms, 605.63ms elapsed

How many major collections there were, and how long they took, in

both process and elapsed time.

INIT time 260 ms

Time spent in the process prior to the logging happening. This is primarily Racket startup time, and code loading time.

MUT time 8,996 ms ( 9,038.51 ms elapsed)

How much time the “mutator”, i.e. your program, was running.

GC time 1,716 ms ( 1,763.16 ms elapsed)

How much time the GC took.

TOTAL time 10,972 ms ( 11,061.67 ms elapsed)

The total time from the initial invocation.

%GC time 16.02% ( 16.32% elapsed)

What percentage of the time (after initialization) was spent in GC.

Alloc rate 301,870,321 bytes per MUT second

The average rate of allocation, not counting GC time.