[racket] debugging memory allocation

Please, someone answer this man! I need to do the same kind of debugging 
on Pict3D.

One thing I've noticed from just dumping the result of 
(current-memory-use) to the terminal: sometimes memory use will 
repeatedly climb until there's a major GC, and sometimes minor GCs will 
be enough to keep memory use low and thus avoid major GCs altogether. I 
get the two behaviors on different executions of the same program, so it 
looks like it has to do with not only what my program allocates, but 
also the state DrRacket leaves the heap in before executing it.

I don't know how to determine the causes more precisely, though. The 
more information I can extract from the logs, the better. Also, is there 
a way to get even more information?

(FWIW, "don't run games in DrRacket" would be bad advice here because I 
can't display interactive 3D snips outside of DrRacket.)

Neil

On 11/06/2014 10:39 PM, David Vanderson wrote:
> I'm having a UI problem in my game where major GCs cause noticeable,
> frequent pauses (every 5-15 seconds).  Jay's advice was to control
> allocation.  Minor GCs are no problem, and I'm okay with infrequent
> major GCs.
>
> Problem is I don't know how to go about tracking this down, and need
> advice.  So far, all I know to do is run tests like this:
> $ racket -W debug test-refresh.rkt 2>&1 | grep "^GC"
>
> ...wait until I see a stable pattern:
> GC: 0:MAJ @ 137,893K(+-15,317K)[+6,816K]; free 76,189K(-76,189K) 142ms @
> 7259
> GC: 0:MAJ @ 94,536K(+28,039K)[+6,816K]; free 32,910K(-49,278K) 156ms @
> 11879
> GC: 0:min @ 94,457K(+44,486K)[+6,816K]; free 23,981K(-23,981K) 12ms @ 16275
> GC: 0:min @ 103,306K(+35,637K)[+6,816K]; free 23,929K(-23,929K) 9ms @ 20731
> GC: 0:min @ 112,144K(+26,799K)[+6,816K]; free 23,949K(-23,949K) 11ms @
> 25093
> GC: 0:min @ 121,026K(+17,917K)[+6,816K]; free 24,004K(-24,004K) 12ms @
> 29235
> GC: 0:min @ 129,853K(+9,090K)[+6,816K]; free 24,001K(-24,001K) 11ms @ 33361
> GC: 0:min @ 138,683K(+260K)[+6,816K]; free 23,990K(-23,990K) 12ms @ 37540
> GC: 0:min @ 147,524K(+-8,580K)[+6,816K]; free 24,062K(-24,062K) 10ms @
> 41429
> GC: 0:MAJ @ 156,293K(+-17,349K)[+6,816K]; free 94,638K(-88,638K) 139ms @
> 45517
> GC: 0:MAJ @ 94,486K(+38,457K)[+6,816K]; free 33,231K(-14,911K) 164ms @
> 50118
>
> I couldn't find info in the docs about how to interpret these numbers
> (did I miss it?).  I'm taking the first number as a memory growth, and
> the last number as milliseconds, so between major GCs in this run, I'm
> generating about (147,524K - 94,457K) / (41429ms - 16275ms) = 2.1 K / ms
> or about 2.1 M / s.
>
> How should I go about figuring out how much garbage I'm generating? Is
> there a way to trace where it's coming from?
>
> Thanks,
> Dave
> ____________________
>   Racket Users list:
>   http://lists.racket-lang.org/users