Re: [racket] debugging memory allocation

[Neil Toronto]

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

____________________
 Racket Users list:
 http://lists.racket-lang.org/users