Re: [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
Re: [racket-dev] gc much slower in DrR?
Any difference with 9dd83008a6 (just pushed)? 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 _ Racket Developers list: http://lists.racket-lang.org/dev
[racket-dev] gc much slower in DrR?
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 :). smime.p7s Description: S/MIME cryptographic signature _ Racket Developers list: http://lists.racket-lang.org/dev
