MinMutUtilization

= Minimum Mutator Utilization =

often abbreviated "MMU" when clear from context (e.g. please avoid confusion with memory management unit on a processor).

On the incrsumz branch of development, Larceny has command line options that track MMU related information.

Minimum Mutator Utilization (MMU) gathering, dumping, and interpreting

The command line option to turn on the internal log to gather MMU data is:

• -mmusize n : If n is non-negative, turns on MMU statistics gathering; for n=0, uses a built-in default size for the internal MMU event log; otherwise uses n as event log size.

Example usage:

% ./larceny -rrof -mmusize 10
Larceny v0.963 "(incrsumz branch)" (Feb 13 2009 15:25:43, precise:Posix Unix:unified)
larceny.heap, built on Thu Feb 12 23:53:35 EST 2009

> (define l (vector->list (make-vector 1000)))

> (define l2 (map (lambda (x) (map (lambda (y) 1) l)) l))
Larceny Panic: Cannot enqueue event in MMU log of capacity 10 entries (disable MMU or increase its capacity).

This tells us that an event log of size 10 was too small to run this program. The default size (selected using 0 as the size) may fare better:

% ./larceny -rrof -mmusize 0 
Larceny v0.963 "(incrsumz branch)" (Feb 13 2009 15:25:43, precise:Posix Unix:unified)
larceny.heap, built on Thu Feb 12 23:53:35 EST 2009

> (define l (vector->list (make-vector 1000)))

> (define l2 (map (lambda (x) (map (lambda (y) 1) l)) l))

> 

Of course, one may want to access the gathered MMU data. The MMU data is kept in internal collector statistics structures; it is not currently exposed to the Scheme side of Larceny. To see the data printed to the console output (in an s-exp format), use the zero-arity stats-dump-stdout procedure. (One can also use a (stats-dump-on filename) invocation to make the collector dump the statistics to a file, but that dumping occurs after every collection, which you may not care about for the MMU data, since one usually only reports the MMU at the end of the program run.)

Format for MMU data : the "simple" version

Here is a Scheme expression you can run from the Larceny REPL (when built from the incrsumz branch that will print out the MMU data in a somewhat nice manner. Warning: this expression performs file IO -- in particular, it will overwrite the file /tmp/stats-log.

(let* ((file "/tmp/stats-log")
          (stats-dump (begin (stats-dump-on file) (collect) (stats-dump-off) (call-with-input-file file read)))) 
  (cond
    ((>= (vector-length stats-dump) 10) 
     (pretty-print (map (lambda (wnd) (list (quote window-size) (cadr (list-ref wnd 1)) (quote mmu) (cadr (cadr (list-ref wnd 2))))) 
                        (cdr (vector->list (vector-ref stats-dump 9)))))) 
    (else (error (quote must-run-with-mmu-turned-on)))))

FIXME: something should export accessors for such dump formats. But does it really belong in the heap? After all, its the runtime that decides how the stats are going to be dumped... maybe it belongs in a loadable library somewhere.

Here is an example usage of the above expression to discover MMU data (for Larceny's default collector, on the sboyer benchmark):

Chimaera:~/Dev/larcenydev/branches/incrsumz/larceny_src/test/Benchmarking/GC pnkfelix$ ../../../larceny -mmusize 10000
Larceny v0.963 "(incrsumz branch)" (Feb 26 2009 19:01:43, precise:Posix Unix:unified)
larceny.heap, built on Wed Feb 25 02:58:30 EST 2009

> (load "sboyer.fasl")

> (sboyer-benchmark 4 5)

--------------------------------------------------------
5sboyer:4
16445406 rewrites
16445406 rewrites
16445406 rewrites
16445406 rewrites
16445406 rewrites
Words allocated: 67878110
Words reclaimed: 0
Elapsed time...: 14181 ms (User: 13502 ms; System: 256 ms)
Elapsed GC time: 1639 ms (CPU: 1597 in 259 collections.)
{Max pause elapsed: 211 ms, CPU: 210 ms} 
{Max remset scan elapsed: 2 ms, CPU: 1 ms, entries: 48} 
{Avg remset scan elapsed: 35/52 ms, CPU: 163/260 ms, entries: 3649/130} 
{Max words, Mem: 13487232 Heap: 13324288 Remset: 114688 Summaries: 0 Marking: 0 Rts: 25600 Waste: 6272}
Elapsed mark time: 0 (CPU: 0 in 0 marks.)
Elapsed summarization time: 0 (CPU: 0 in 0 summarization.)

> (let* ((file "/tmp/stats-log") (stats-dump (begin (stats-dump-on file) (collect) (stats-dump-off) (call-with-input-file file read)))) (cond ((>= (vector-length stats-dump) 10) (pretty-print (map (lambda (wnd) (list (quote window-size) (cadr (list-ref wnd 1)) (quote mmu) (cadr (cadr (list-ref wnd 2))))) (cdr (vector->list (vector-ref stats-dump 9)))))) (else (error (quote must-run-with-mmu-turned-on)))))
((window-size 100 mmu (real 0 cpu 0))
 (window-size 200 mmu (real 0 cpu 0))
 (window-size 300 mmu (real 79 cpu 79))
 (window-size 400 mmu (real 167 cpu 170))
 (window-size 500 mmu (real 255 cpu 259))
 (window-size 600 mmu (real 342 cpu 343))
 (window-size 700 mmu (real 432 cpu 436))
 (window-size 800 mmu (real 522 cpu 526))
 (window-size 900 mmu (real 610 cpu 614))
 (window-size 1000 mmu (real 698 cpu 702))
 (window-size 2000 mmu (real 1597 cpu 1601))
 (window-size 3000 mmu (real 2508 cpu 2512))
 (window-size 4000 mmu (real 3405 cpu 3402))
 (window-size 5000 mmu (real 4286 cpu 4295))
 (window-size 6000 mmu (real 5050 cpu 5065))
 (window-size 7000 mmu (real 5939 cpu 5953))
 (window-size 8000 mmu (real 6843 cpu 6864))
 (window-size 9000 mmu (real 7752 cpu 7764))
 (window-size 10000 mmu (real 8607 cpu 8619)))

> 

(A pretty nice MMU; of course this is an invocation of sboyer on relatively small arguments compared to our standard runs.)

Format for MMU data : the detailed version

The MMU data is printed within the dumped stats output s-exp; each window (of a set of windows hard-coded into the invocation of create_mmu_log_t within the source code to [source:branches/pnkfelix/incrsumz/larceny_src/src/Rts/Sys/memmgr.c memmgr.c] has its own entry. The data is printed according to the following grammar:

     -> #(gc_mmu_log_t  ... )
     -> (window (size )       )
     -> (mutator   )
  -> (memmgr    
   -> (minorgc   )
   -> (majorgc   )
    -> (summarize   )
    -> (smircy   )
 -> (min )
 -> (curr )
 -> (max )
   -> (real  cpu )

The <NUM>s above are times in milliseconds, presented as non-negative integers.

Note that while the output of stats-dump-stdout looks like an s-exp (and should be able to be read in like an s-exp), that s-exp is not the result of invoking stats-dump-stdout; it really is just output being dumped to the console from C.

(In practice the only values one usually cares about in the end are the size and the min times for the mutator. The other data is reported as a way of helping Felix break down where time is potentially being spent when the MMU is lower than we expect.)