[racket-dev] gc much slower in DrR?

On Oct 15, 2012, at 5:47 PM, Matthew Flatt wrote:

> Any difference with 9dd83008a6 (just pushed)?

I just built from source.

Short version: yes, much better.

Longer version: DrR still has somewhat longer pauses, but they're now in the 6-10ms range:

GC: 0:min @ 242,118K(+159,225K)[+31,728K]; free 24,751K(-24,751K) 31ms @ 57771
GC: 0:min @ 250,704K(+150,639K)[+31,728K]; free 33,064K(-33,064K) 11ms @ 58198
GC: 0:min @ 250,407K(+150,936K)[+31,728K]; free 32,724K(-32,724K) 5ms @ 58611
GC: 0:min @ 250,466K(+150,877K)[+31,728K]; free 32,738K(-32,738K) 6ms @ 59057
GC: 0:min @ 250,496K(+150,847K)[+31,728K]; free 32,723K(-32,723K) 10ms @ 59452
GC: 0:min @ 250,540K(+150,803K)[+31,728K]; free 32,729K(-32,729K) 5ms @ 59865
GC: 0:min @ 250,610K(+150,733K)[+31,728K]; free 32,754K(-32,754K) 5ms @ 60290
GC: 0:min @ 250,639K(+150,704K)[+31,728K]; free 32,734K(-32,734K) 5ms @ 60758
GC: 0:min @ 250,704K(+150,639K)[+31,728K]; free 32,752K(-32,752K) 6ms @ 61176
GC: 0:min @ 250,720K(+150,623K)[+31,728K]; free 32,720K(-32,720K) 6ms @ 61595
GC: 0:min @ 250,767K(+150,576K)[+31,728K]; free 32,722K(-32,722K) 8ms @ 62003
GC: 0:min @ 250,812K(+150,531K)[+31,728K]; free 32,720K(-32,720K) 6ms @ 62429
GC: 0:min @ 250,860K(+150,483K)[+31,728K]; free 32,725K(-32,725K) 9ms @ 62871
GC: 0:min @ 250,902K(+150,441K)[+31,728K]; free 32,727K(-32,727K) 5ms @ 63270
GC: 0:min @ 250,943K(+150,400K)[+31,728K]; free 32,725K(-32,725K) 5ms @ 63687
GC: 0:min @ 250,985K(+150,358K)[+31,728K]; free 32,718K(-32,718K) 10ms @ 64103

Here's command-line racket:

GC: 0:min @ 121,746K(+43,341K)[+9,788K]; free 32,712K(-32,712K) 5ms @ 7033
GC: 0:min @ 121,801K(+43,286K)[+9,788K]; free 32,736K(-32,736K) 5ms @ 7467
GC: 0:min @ 121,832K(+43,255K)[+9,788K]; free 32,734K(-32,734K) 3ms @ 7906
GC: 0:min @ 121,866K(+43,221K)[+9,788K]; free 32,733K(-32,733K) 3ms @ 8342
GC: 0:min @ 121,900K(+43,187K)[+9,788K]; free 32,734K(-32,734K) 3ms @ 8791
GC: 0:min @ 121,966K(+43,121K)[+9,788K]; free 32,732K(-32,732K) 4ms @ 9221
GC: 0:min @ 122,002K(+43,085K)[+9,788K]; free 32,741K(-32,741K) 5ms @ 9649
GC: 0:min @ 122,029K(+43,058K)[+9,788K]; free 32,732K(-32,732K) 5ms @ 10092
GC: 0:min @ 122,064K(+43,023K)[+9,788K]; free 32,732K(-32,732K) 3ms @ 10533
GC: 0:min @ 122,100K(+42,987K)[+9,788K]; free 32,741K(-32,741K) 2ms @ 10980
GC: 0:min @ 122,127K(+42,960K)[+9,788K]; free 32,732K(-32,732K) 3ms @ 11424
GC: 0:min @ 122,162K(+42,925K)[+9,788K]; free 32,732K(-32,732K) 4ms @ 11847
GC: 0:min @ 122,197K(+42,890K)[+9,788K]; free 32,734K(-32,734K) 4ms @ 12296
GC: 0:min @ 122,231K(+42,856K)[+9,788K]; free 32,736K(-32,736K) 2ms @ 12734
GC: 0:min @ 122,262K(+42,825K)[+9,788K]; free 32,730K(-32,730K) 2ms @ 13171
GC: 0:min @ 122,300K(+42,787K)[+9,788K]; free 32,739K(-32,739K) 3ms @ 13616
GC: 0:min @ 122,393K(+42,694K)[+9,788K]; free 32,732K(-32,732K) 4ms @ 14067
GC: 0:min @ 122,428K(+42,659K)[+9,788K]; free 32,725K(-32,725K) 3ms @ 14504
GC: 0:min @ 122,470K(+42,617K)[+9,788K]; free 32,726K(-32,726K) 2ms @ 14951
GC: 0:min @ 122,512K(+42,575K)[+9,788K]; free 32,734K(-32,734K) 5ms @ 15427
GC: 0:min @ 122,545K(+42,542K)[+9,788K]; free 32,732K(-32,732K) 2ms @ 15881
GC: 0:min @ 122,580K(+42,507K)[+9,788K]; free 32,729K(-32,729K) 4ms @ 16330
GC: 0:min @ 122,618K(+42,469K)[+9,792K]; free 32,731K(-32,731K) 3ms @ 16771

So, it appears that things have improved a lot… maybe for *both* of them. I also see that DrR's memory use is much lower, which may simply be because I haven't been running the process as long. Also, I was a bit more careful this time, and counted the number of GCs; in the case of DrR, I saw 17 pauses in 30 seconds or about 34 pauses per minute, whereas command-line racket has only 23. 

Either way, I'm a happy camper. Thanks!

… will this go into the upcoming release?


John



> 
> At Thu, 11 Oct 2012 15:43:49 -0700, John Clements wrote:
>> 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 :).
>> 
>> 
>> ------------------------------------------------------------------------------
>> [application/pkcs7-signature "smime.p7s"] [~/Desktop & open] [~/Temp & open]
>> _________________________
>>  Racket Developers list:
>>  http://lists.racket-lang.org/dev

-------------- 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/20121016/f8c39114/attachment.p7s>