[MLton-user] MLton on mswin7 absurdly slow ?

[John B Thiel]

Thanks, Wesley and Matthew.  Yes, my setups definitely do not
facilitate any single program running off with 1/2 of physical RAM.
That seems to me not the best default nowadays - 10 or 20% maybe, ok.
 12+ apps is about my minimum working set and I never have half the
core just sitting around unused, regardless of qty.  I'd say it should
default to a lower % heap limit, and let the user dial up as needed.
(and be more aggressive with GC, see below).  If it fails early with
"out of memory"; then at least the user has feedback to
research/adjust parameters.  (such parameter could also be set 1-time
in a user-specific config/ini file).

In regards the actual allocation, I traced those gc-messages, Matthew,
see below.  The "major mark-compact" is very successful at trimming
the heap, but is only invoked when allocation hits the limit.  See
gc#15, and gc#36 in first trace (1) excerpt below (100MB heap limit).
It looks like the high water mark of live data is around 62+M
remaining allocated after the "major mark compact" in gc#15.
(confirmed with further test -- helloworld compile succeeds with 75MB
max-heap, fails with 70MB. Same with fixed-heap.)

The second trace (2) excerpt below illustrates running with no heap
limit.  I did not see any "major mark compact" calls at all, and the
heap rapidly balloons to 256MB, with the coup-de-grace in gc#19 of a
heap-to-heap "major Cheney copy":
	[GC: Starting major Cheney-copy;]
	[GC:    from heap at 0x60000000 of size 256,770,048 bytes,]
	[GC:    to heap at 0x08000000 of size 256,770,048 bytes.]

So there's the expected 512MB allocation rail.

Since there is really only at most 75M of live data at this point,
this appears to be a theoretical 6x+ overallocation (or 3x if the 75M
also involved a heap-heap "major Cheny copy", but in fact I did not
see one in that trace).   Whether 6x or 3x, that is still a pretty
high GC overhead, so it looks like some GC tuning development work
could be helpful, with at least part of the answer being more  "major
mark compacts" to keep the heap size down.  I would rather spare the
300ms for those in lieu of allocations.

Meanwhile, looks like the "fixed-heap" option is the way to go.

-- jbthiel



TRACE 1:  GC TRACE with 100MB HEAP LIMIT -- COMPILE SUCCESSFUL

$ mlton @MLton gc-messages max-heap 0.1g -- -verbose 3 hello.sml
[GC: Found 1,035,444,224 bytes of RAM; using 517,734,400 bytes (50.0% of RAM).]
[GC: Created heap at 0x78000000 of size 3,014,656 bytes (+ 131,072
bytes card/cross map).]
[GC: Starting gc #1; requesting 512 nursery bytes and 0 old-gen bytes,]
...
[GC: Finished gc #14; time 0 ms,]
[GC:    heap at 0x78000000 of size 100,794,368 bytes (+ 917,504 bytes
card/cross map),]
[GC:    with old-gen of size 18,943,224 bytes (18.8% of heap),]
[GC:    and nursery of size 81,851,144 bytes (81.2% of heap).]
[GC: Starting gc #15; requesting 512 nursery bytes and 0 old-gen bytes,]
[GC:    heap at 0x78000000 of size 100,794,368 bytes (+ 917,504 bytes
card/cross map),]
[GC:    with old-gen of size 18,943,224 bytes (18.8% of heap),]
[GC:    and nursery of size 81,851,144 bytes (81.2% of heap),]
[GC:    and nursery using 81,850,680 bytes (81.2% of heap, 100.0% of nursery).]
[GC: Starting major mark-compact;]
[GC:    heap at 0x78000000 of size 100,794,368 bytes.]
[GC: Shrinking stack of size 172,032 bytes to size 86,016 bytes, using
14,044 bytes.]
[GC: Finished major mark-compact; mark compacted 18,687,588 bytes.]
[GC: Growing heap at 0x78000000 of size 100,794,368 bytes (+ 917,504
bytes card/cross map),]
[GC:    to desired size of 106,561,536 bytes (+ 917,504 bytes card/cross map)]
[GC:    and minimum size of 18,743,296 bytes (+ 262,144 bytes card/cross map).]
[GC: Remapped heap at 0x78000000 of size 100,794,368 bytes (+ 917,504
bytes card/cross map)]
[GC:    to heap at 0x78000000 of size 106,561,536 bytes (+ 917,504
bytes card/cross map).]
[GC: Finished gc #15; time 733 ms,]
[GC:    heap at 0x78000000 of size 106,561,536 bytes (+ 917,504 bytes
card/cross map),]
[GC:    with old-gen of size 18,687,588 bytes (17.5% of heap),]
[GC:    and nursery of size 43,936,972 bytes (41.2% of heap).]
[GC: Starting gc #16; requesting 512 nursery bytes and 0 old-gen bytes,]
[GC:    heap at 0x78000000 of size 106,561,536 bytes (+ 917,504 bytes
card/cross map),]
[GC:    with old-gen of size 18,687,588 bytes (17.5% of heap),]
[GC:    and nursery of size 43,936,972 bytes (41.2% of heap),]
[GC:    and nursery using 43,936,464 bytes (41.2% of heap, 100.0% of nursery).]
[GC: Starting minor Cheney-copy;]
[GC:    from nursery at 0x7bbb9334 of size 43,936,464 bytes.]
[GC: Finished minor Cheney-copy; copied 6,740,860 bytes.]
[GC: Finished gc #16; time 187 ms,]
[GC:    heap at 0x78000000 of size 106,561,536 bytes (+ 917,504 bytes
card/cross map),]
[GC:    with old-gen of size 25,428,448 bytes (23.9% of heap),]
[GC:    and nursery of size 40,566,544 bytes (38.1% of heap).]
...
...
[GC: Starting gc #36; requesting 512 nursery bytes and 0 old-gen bytes,]
[GC:    heap at 0x78000000 of size 106,561,536 bytes (+ 917,504 bytes
card/cross map),]
[GC:    with old-gen of size 98,162,176 bytes (92.1% of heap),]
[GC:    and nursery of size 8,399,360 bytes (7.9% of heap),]
[GC:    and nursery using 8,398,872 bytes (7.9% of heap, 100.0% of nursery).]
[GC: Starting major mark-compact;]
[GC:    heap at 0x78000000 of size 106,561,536 bytes.]
[GC: Shrinking stack of size 344,064 bytes to size 72,576 bytes, using
2,268 bytes.]
[GC: Finished major mark-compact; mark compacted 2,648,852 bytes.]
[GC: Shrinking heap at 0x78000000 of size 106,561,536 bytes (+ 917,504
bytes card/cross map)]
[GC:    to size 22,282,240 bytes (+ 262,144 bytes card/cross map).]
[GC: Finished gc #36; time 311 ms,]
[GC:    heap at 0x78000000 of size 22,282,240 bytes (+ 262,144 bytes
card/crossmap),]
[GC:    with old-gen of size 2,648,852 bytes (11.9% of heap),]
[GC:    and nursery of size 9,816,692 bytes (44.1% of heap).]
...
...
[GC: Starting gc #86; requesting 0 nursery bytes and 0 old-gen bytes,]
[GC:    heap at 0x08000000 of size 22,282,240 bytes (+ 262,144 bytes
card/crossmap),]
[GC:    with old-gen of size 2,035,000 bytes (9.1% of heap),]
[GC:    and nursery of size 20,247,240 bytes (90.9% of heap),]
[GC:    and nursery using 9,160,392 bytes (41.1% of heap, 45.2% of nursery).]
[GC: Starting major Cheney-copy;]
[GC:    from heap at 0x08000000 of size 22,282,240 bytes,]
[GC:    to heap at 0x78000000 of size 22,282,240 bytes.]
[GC: Shrinking stack of size 84,736 bytes to size 13,440 bytes, using
420 bytes.]
[GC: Finished major Cheney-copy; copied 313,032 bytes.]
[GC: Finished gc #86; time 0 ms,]
[GC:    heap at 0x78000000 of size 22,282,240 bytes (+ 262,144 bytes
card/crossmap),]
[GC:    with old-gen of size 313,032 bytes (1.4% of heap),]
[GC:    and nursery of size 21,969,208 bytes (98.6% of heap).]
[GC: Shrinking heap at 0x78000000 of size 22,282,240 bytes (+ 262,144
bytes card/cross map)]
[GC:    to size 393,216 bytes (+ 131,072 bytes card/cross map).]
[GC: Releasing heap at 0x08000000 of size 22,282,240 bytes (+ 262,144
bytes card/cross map).]
[GC: Packed heap at 0x78000000 to size 393,216 bytes.]
[GC: Starting gc #87; requesting 512 nursery bytes and 0 old-gen bytes,]
[GC:    heap at 0x78000000 of size 393,216 bytes (+ 131,072 bytes
card/cross map),]
[GC:    with old-gen of size 313,032 bytes (79.6% of heap),]
[GC:    and nursery of size 40,092 bytes (10.2% of heap),]
[GC:    and nursery using 39,588 bytes (10.1% of heap, 98.7% of nursery).]
[GC: Starting minor Cheney-copy;]
[GC:    from nursery at 0x78056364 of size 39,588 bytes.]
[GC: Finished minor Cheney-copy; copied 936 bytes.]
[GC: Finished gc #87; time 0 ms,]
[GC:    heap at 0x78000000 of size 393,216 bytes (+ 131,072 bytes
card/cross map),]
[GC:    with old-gen of size 313,968 bytes (79.8% of heap),]
[GC:    and nursery of size 39,624 bytes (10.1% of heap).]
[GC: Starting minor Cheney-copy;]
[GC:    from nursery at 0x78056538 of size 812 bytes.]
[GC: Finished minor Cheney-copy; copied 208 bytes.]
[GC: Releasing heap at 0x78000000 of size 393,216 bytes (+ 131,072
bytes card/cross map).]

*** COMPILATION SUCCESSFUL ***


=============================================================

TRACE 2: GC TRACE WITH NO HEAP LIMIT  --  PROGRAM USER-TERMINATED DUE
TO RESOURCE EXHAUSTION
	(does complete if allowed to run for 5+ minutes)

$ mlton @MLton gc-messages -- -verbose 3 hello.sml

...
...
[GC: Finished gc #19; time 0 ms,]
[GC:    heap at 0x60000000 of size 256,770,048 bytes (+ 2,097,152
bytes card/cross map),]
[GC:    with old-gen of size 59,736,568 bytes (23.3% of heap),]
[GC:    and nursery of size 197,033,480 bytes (76.7% of heap).]
[GC: Starting gc #20; requesting 512 nursery bytes and 0 old-gen bytes,]
[GC:    heap at 0x60000000 of size 256,770,048 bytes (+ 2,097,152
bytes card/cross map),]
[GC:    with old-gen of size 59,736,568 bytes (23.3% of heap),]
[GC:    and nursery of size 197,033,480 bytes (76.7% of heap),]
[GC:    and nursery using 197,032,992 bytes (76.7% of heap, 100.0% of nursery).]

[GC: Created heap at 0x08000000 of size 256,770,048 bytes (+ 2,097,152
bytes card/cross map).]
[GC: Starting major Cheney-copy;]
[GC:    from heap at 0x60000000 of size 256,770,048 bytes,]
[GC:    to heap at 0x08000000 of size 256,770,048 bytes.]
[GC: Shrinking stack of size 344,064 bytes to size 172,032 bytes,
using 19,176 bytes.]

**** PROGRAM USER-TERMINATED DUE TO RESOURCE EXHAUSTION ****


(* footnote: the test file actual has another tiny function besides
print "hello" *)