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.