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:

  1. There are a few GCs before the tool starts — it can’t report anything about them.
  2.  If you have multiple places, it will only report information from the initial place. Fixing this will require  more information from Racket.
  3. 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.

About these ads

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.