[racket-dev] gc much slower in DrR?

From: John Clements (clements at brinckerhoff.org)
Date: Thu Oct 11 18:43:49 EDT 2012

I'm trying to run signal-based audio programs, and I'm finding that DrR is using well over 10x the time to perform the same GC's as command-line racket. Let me be more specific: I'm running a program that does a little filtering to combine a couple of oscillators, using big-bang. Running this program in DrR, I see GC logs that look like this:

GC: 0:min @ 711,798K(+89,158K)[+46,912K]; free 32,654K(-32,654K) 66ms @ 2058318
GC: 0:min @ 712,070K(+88,886K)[+46,912K]; free 32,667K(-32,667K) 69ms @ 2059160
GC: 0:min @ 712,421K(+88,534K)[+46,916K]; free 32,724K(-32,724K) 71ms @ 2059963
GC: 0:min @ 712,621K(+88,334K)[+46,916K]; free 32,698K(-32,698K) 68ms @ 2060857
GC: 0:min @ 713,411K(+87,545K)[+46,916K]; free 33,103K(-33,103K) 80ms @ 2061605
GC: 0:min @ 713,424K(+87,532K)[+46,916K]; free 32,815K(-32,815K) 78ms @ 2062341
GC: 0:min @ 714,273K(+86,683K)[+46,916K]; free 33,363K(-33,363K) 75ms @ 2062872
GC: 0:min @ 715,799K(+85,157K)[+46,916K]; free 30,988K(-30,988K) 104ms @ 2063857
…

These GCs are happening about 17 times in every 30 seconds; given the amount freed, this suggests that I'm generating about 18 Megabytes of trash per second, which seems like a lot until you divide by the sample rate of 44.1KHz, when it comes out to be 419 bytes of trash per sample generated, which seems like it's in the right ballpark.

I tried running the same program on the command-line, with "racket -W debug ./interesting-tones.rkt", and the GC traces looked like this:

GC: 0:min @ 124,249K(+26,774K)[+11,396K]; free 32,735K(-32,735K) 5ms @ 14101
GC: 0:min @ 124,282K(+26,741K)[+11,396K]; free 32,737K(-32,737K) 5ms @ 14563
GC: 0:min @ 124,341K(+26,682K)[+11,396K]; free 32,762K(-32,762K) 5ms @ 15032
GC: 0:min @ 124,340K(+26,683K)[+11,396K]; free 32,724K(-49,108K) 7ms @ 15506
GC: 0:min @ 124,383K(+43,024K)[+11,396K]; free 32,733K(-32,733K) 6ms @ 15967
GC: 0:min @ 124,402K(+43,005K)[+11,396K]; free 32,708K(-32,708K) 6ms @ 16419
GC: 0:min @ 124,461K(+42,946K)[+11,396K]; free 32,736K(-32,736K) 5ms @ 16864
GC: 0:min @ 124,513K(+42,894K)[+11,396K]; free 32,743K(-32,743K) 10ms @ 17312
GC: 0:min @ 124,563K(+42,844K)[+11,396K]; free 32,764K(-32,764K) 5ms @ 17767
GC: 0:min @ 124,566K(+42,841K)[+11,396K]; free 32,739K(-32,739K) 6ms @ 18227
GC: 0:min @ 124,595K(+42,812K)[+11,396K]; free 32,733K(-32,733K) 5ms @ 18681
GC: 0:min @ 124,628K(+42,779K)[+11,440K]; free 32,673K(-32,673K) 9ms @ 19161
….

Note that it's collecting about the same amount of trash each time (about 32Meg), but the gc pauses are only 5-10 ms, rather than 60-100. This means no audible pauses, and it sounds quite nice, rather than extremely hiccupy.

I see that DrR's heap is much bigger: 713Meg vs 125Meg. Would this account for the much longer GC times? I'm imagining that these are minor collections, that don't affect much outside of the nursery (and I guess I'm assuming we have a generational collector), so it seems like the bulky background shouldn't affect the GC times, at least not by a factor of 10.  Is there something else going on?

John


P.S.: I should admit that I think I could address this problem in DrR by turning the buffer size up to, say, 200ms, but that's a really slow response rate; if you're trying to play a keyboard, for instance, 200ms feels quite sluggish.

P.P.S.: this version of DrR hasn't been updated in a month… I suppose I should update, and perhaps something magical will happen :).

-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 4800 bytes
Desc: not available
URL: <http://lists.racket-lang.org/dev/archive/attachments/20121011/d2cd31a0/attachment.p7s>

Posted on the dev mailing list.