939137 - display vsize following each mochitest

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Comment 1

[Nathan Froyd [:froydnj]]

Attachment: display vsize following each mochitest

This is a PoC/strawman patch to get the discussion going.  Is displaying vsize
on a per-test basis sufficient (given that GC etc. means that it might not be
totally accurate)?  Should we be displaying max vsize at the end of the run
only?  Should we be displaying deltas?  Is there a better way to show it so
that it shows up on TBPL directly and we don't have to go hunting through logs?

Comment 2

[Shu-yu Guo [:shu]]

(In reply to Nathan Froyd (:froydnj) from comment #1)
> Created attachment 832961 [details] [diff] [review]
> display vsize following each mochitest
> 
> This is a PoC/strawman patch to get the discussion going.  Is displaying
> vsize
> on a per-test basis sufficient (given that GC etc. means that it might not be
> totally accurate)?  Should we be displaying max vsize at the end of the run
> only?  Should we be displaying deltas?  Is there a better way to show it so
> that it shows up on TBPL directly and we don't have to go hunting through
> logs?

Just having raw numbers for vsize/resident/heapAllocated/etc in the logs would be helpful to start building a history of how much memory mochitests take on different platforms, so when adding new tests people have an idea how much they are contributing to memory use. ASan, for instance, is already very close to the OOM line all the time, see bug 939036.

Comment 3

[Nathan Froyd [:froydnj]]

(In reply to Shu-yu Guo [:shu] from comment #2)
> (In reply to Nathan Froyd (:froydnj) from comment #1)
> > Created attachment 832961 [details] [diff] [review]
> > display vsize following each mochitest
> > 
> > This is a PoC/strawman patch to get the discussion going.  Is displaying
> > vsize
> > on a per-test basis sufficient (given that GC etc. means that it might not be
> > totally accurate)?  Should we be displaying max vsize at the end of the run
> > only?  Should we be displaying deltas?  Is there a better way to show it so
> > that it shows up on TBPL directly and we don't have to go hunting through
> > logs?
> 
> Just having raw numbers for vsize/resident/heapAllocated/etc in the logs
> would be helpful to start building a history of how much memory mochitests
> take on different platforms, so when adding new tests people have an idea
> how much they are contributing to memory use. ASan, for instance, is already
> very close to the OOM line all the time, see bug 939036.

OK, that seems reasonable.  bsmedberg mentioned on IRC that he'd like to see the largest contiguous VM chunk, so we'll probably expose that too.

Comment 4

[Nathan Froyd [:froydnj]]

Attachment: add largestContiguousVMBlock attribute to nsIMemoryReporterManager

This adds all the machinery for measuring the largest contiguous free
space on Windows.  Experimental testing with mochitests shows that
measuring this and displaying it does not add appreciable overhead.

Comment 5

[Nathan Froyd [:froydnj]]

Attachment: display memory statistics following each mochitest

This is a reworked patch for displaying a couple of pertinent statistics
for the memory heap after each mochitest.  browser-chrome and chrome (?)
probably need a different approach, as browser-chrome fires up child test
processes.  I'm assuming plain mochitests don't, though that may not be
a good assumption...

Comment 6

[Benjamin Smedberg]

Comment on attachment 833089 [details] [diff] [review]
add largestContiguousVMBlock attribute to nsIMemoryReporterManager

Why don't you just have LargestContiguousVMBlock return the int64_t, instead of nsresult, since it never fails? r=me in either case

Comment 7

[Nathan Froyd [:froydnj]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/b3995a14d968
https://hg.mozilla.org/integration/mozilla-inbound/rev/86cf2e690f90

Comment 8

[Andrew McCreight [:mccr8]]

follow up to fix mochitest-chrome bustage because you can't call specialpowers there for some odd reason:
https://hg.mozilla.org/integration/mozilla-inbound/rev/a7a6ff24a7b8

Comment 9

[Andrew McCreight [:mccr8]]

I looked at a few Win7 debug M2 logs, at the largest contiguous block stat.  It holds steady at about 880mb, then over the course of a couple of tests plummets to 155mb, where it remains for the rest of the run, which seems bad:

edited this looks like:

16:12:18 vsize after test: 886841344
16:12:18 largestContiguousVMBlock after test: 581304320
16:12:18 TEST-END | /tests/dom/file/test/test_write_read_data.html | finished in 674ms

16:12:20 MEMORY STAT vsize after test: 887955456
16:12:20 MEMORY STAT largestContiguousVMBlock after test: 581304320
16:12:20 TEST-END | /tests/dom/imptests/editing/conformancetest/test_event.html | finished in 1944ms

16:14:08 vsize after test: 1293967360
16:14:08 largestContiguousVMBlock after test: 309133312
16:14:11 TEST-END | /tests/dom/imptests/editing/conformancetest/test_runtest.html | finished in 110916ms

16:14:15 vsize after test: 1353281536
16:14:15 largestContiguousVMBlock after test: 231534592
16:14:15     INFO -  10855 INFO TEST-END | /tests/dom/imptests/editing/selecttest/test_Document-open.html | finished in 645ms

16:14:40 vsize after test: 1492025344
16:14:40 largestContiguousVMBlock after test: 134213632
16:14:41 TEST-END | /tests/dom/imptests/editing/selecttest/test_addRange.html | finished in 25990ms

16:14:49 vsize after test: 1556946944
16:14:49 largestContiguousVMBlock after test: 134213632
16:14:49 TEST-END | /tests/dom/imptests/editing/selecttest/test_collapse.html | finished in 6650ms

16:14:50 vsize after test: 1558589440
16:14:50 largestContiguousVMBlock after test: 134213632
16:14:50 TEST-END | /tests/dom/imptests/editing/selecttest/test_collapseToStartEnd.html | finished in 520ms

Comment 10

[Nathan Froyd [:froydnj]]

(In reply to Andrew McCreight [:mccr8] from comment #9)
> I looked at a few Win7 debug M2 logs, at the largest contiguous block stat. 
> It holds steady at about 880mb, then over the course of a couple of tests
> plummets to 155mb, where it remains for the rest of the run, which seems bad:

Hah, just saw this after filing bug 939369!

Comment 11

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/b3995a14d968
https://hg.mozilla.org/mozilla-central/rev/86cf2e690f90
https://hg.mozilla.org/mozilla-central/rev/a7a6ff24a7b8

Comment 12

[Nicholas Nethercote [inactive]]

I filed bug 939385 for exposing this measurement to about:memory and telemetry.

Comment 13

[Ryan VanderMeulen [:RyanVM]]

This was landed on Aurora as part of a roll-up patch in bug 939385.

https://hg.mozilla.org/releases/mozilla-aurora/rev/d364517977a7