939369 - dom/imptests/conformance/editing tests do funny things to vsize and contiguous free space

Status: RESOLVED DUPLICATE of bug 1194860

(Core :: JavaScript Engine, defect)

Description

[Nathan Froyd [:froydnj]]

Mochitest-2 on Windows 7 log:

https://tbpl.mozilla.org/php/getParsedLog.php?id=30616573&tree=Mozilla-Inbound&full=1

First interesting result from the bug 939137 logging, first test:

17:17:31     INFO -  18 INFO TEST-INFO | MEMORY STAT vsize after test: 401723392
17:17:31     INFO -  19 INFO TEST-INFO | MEMORY STAT heapAllocated not supported in this build configuration.
17:17:31     INFO -  20 INFO TEST-INFO | MEMORY STAT largestContiguousVMBlock after test: 744685568
17:17:31     INFO -  21 INFO TEST-END | /tests/content/xul/content/test/test_bug486990.xul | finished in 1443ms

That looks OK, though 400MB vsize seems a little high.

[...time passes...]

17:25:16     INFO -  9034 INFO TEST-PASS | /tests/dom/imptests/editing/conformancetest/test_event.html | Editing event tests: Elided 41 passes or known failures.
17:25:16     INFO -  9035 INFO TEST-INFO | MEMORY STAT vsize after test: 879476736
17:25:16     INFO -  9036 INFO TEST-INFO | MEMORY STAT largestContiguousVMBlock after test: 633667584
17:25:16     INFO -  [Parent 2392] WARNING: NS_ENSURE_TRUE(mDisabledJSAndPlugins) failed: file c:\builds\moz2_slave\m-in-w32-d-0000000000000000000\build\editor\composer\src\nsEditingSession.cpp, line 208
17:25:16     INFO -  9037 INFO TEST-END | /tests/dom/imptests/editing/conformancetest/test_event.html | finished in 1907ms

Notice that our vsize has more than doubled.

[...time passes...]

17:27:01     INFO -  10847 INFO TEST-PASS | /tests/dom/imptests/editing/conformancetest/test_runtest.html | HTML editing conformance tests: Elided 13 passes or known failures.
17:27:01     INFO -  10848 INFO TEST-INFO | MEMORY STAT vsize after test: 1288536064
17:27:01     INFO -  10849 INFO TEST-INFO | MEMORY STAT largestContiguousVMBlock after test: 305528832
17:27:04     INFO -  10850 INFO TEST-END | /tests/dom/imptests/editing/conformancetest/test_runtest.html | finished in 107754ms

That's 400MB added to vsize.

One test later:

17:27:07     INFO -  10852 INFO TEST-PASS | /tests/dom/imptests/editing/selecttest/test_Document-open.html | Selection Document.open() tests: Elided 2 passes or known failures.
17:27:07     INFO -  10853 INFO TEST-INFO | MEMORY STAT vsize after test: 1348767744
17:27:07     INFO -  10854 INFO TEST-INFO | MEMORY STAT largestContiguousVMBlock after test: 232124416
17:27:08     INFO -  10855 INFO TEST-END | /tests/dom/imptests/editing/selecttest/test_Document-open.html | finished in 565ms

About 60MB+.  Next test:

17:27:31     INFO -  11663 INFO TEST-PASS | /tests/dom/imptests/editing/selecttest/test_addRange.html | Selection.addRange() tests: Elided 69 passes or known failures.
17:27:31     INFO -  11664 INFO TEST-INFO | MEMORY STAT vsize after test: 1487904768
17:27:31     INFO -  11665 INFO TEST-INFO | MEMORY STAT largestContiguousVMBlock after test: 136245248
17:27:32     INFO -  11666 INFO TEST-END | /tests/dom/imptests/editing/selecttest/test_addRange.html | finished in 24703ms

About 140MB+.  Notice how our contiguous heap size has decreased dramatically.  Nothing much changes until the end:

17:30:42     INFO -  14033 INFO TEST-PASS | /tests/dom/imptests/html/webgl/test_uniformMatrixNfv.html | uniformMatrix*fv: Elided 4 passes or known failures.
17:30:42     INFO -  14034 INFO TEST-INFO | MEMORY STAT vsize after test: 1486708736
17:30:42     INFO -  14035 INFO TEST-INFO | MEMORY STAT largestContiguousVMBlock after test: 136245248
17:30:42     INFO -  14036 INFO TEST-END | /tests/dom/imptests/html/webgl/test_uniformMatrixNfv.html | finished in 1149ms

I really wonder what this was before the GC/CC changes Olli made.  Is there any way we can make these tests use less memory?

Comment 1

[Andrew McCreight [:mccr8]]

Note that this is around the point where bug 923614 happens, which looks like it is some kind of OOM thing.  I think I've seen philor complaining about these tests, so maybe he has some more examples.

Comment 2

[Phil Ringnalda (:philor)]

https://bugzilla.mozilla.org/buglist.cgi?quicksearch=imptests%20kw%3Aintermittent. There are more of the completely opaque opt timeouts (https://tbpl.mozilla.org/php/getParsedLog.php?id=29825461&tree=Mozilla-Inbound is unusual in that the "Error 5 in VirtualAllocEx" probably does tell us that it was an OOM), but we're pretty unwilling to file any more of them.

Comment 3

[Andrew McCreight [:mccr8]]

I added the intermittent oranges from philor's link that include "editing" in the name that have happened recently.

Comment 4

[(no longer active)]

FWIW there is no easy way to make these tests use less memory.

Comment 5

[Nathan Froyd [:froydnj]]

(In reply to :Ehsan Akhgari (needinfo? me!) from comment #4)
> FWIW there is no easy way to make these tests use less memory.

Do you know why they use so much memory?  Do share! :)

Comment 6

[(no longer active)]

(In reply to Nathan Froyd (:froydnj) from comment #5)
> (In reply to :Ehsan Akhgari (needinfo? me!) from comment #4)
> > FWIW there is no easy way to make these tests use less memory.
> 
> Do you know why they use so much memory?  Do share! :)

Depends on what you mean by this question!  If you're asking about the high level reason, it's probably because these tests test *a lot* of things.  I haven't delved much lower than that though.

Comment 7

[(no longer active)]

And what I meant to say before was that these tests are very complicated and there is no easy way to rewrite them in a simpler way.

Comment 8

[Andrew McCreight [:mccr8]]

Probably the next step here is to insert more logging at various intermediate points in the middle of the test and seeing if there's a particular point where it gets bad.  Maybe we could insert additional GC slices or something in the middle here to keep the peak memory down.

Comment 9

[Nathan Froyd [:froydnj]]

Attachment: about:memory dump before test_runtests.html

I'm attaching the about:memory dumps from before and after running dom/imptests/editing/conformancetest/test_runtest.html from my local Windows 7 machine, --enable-optimize --enable-debug --enable-jemalloc --enable-profiling

Memory stats, before:

vsize 995012608
vsizeMaxContiguous 1893662720
residentFast 516182016
heapAllocated 71310698

Memory stats after:

vsize 1323720704
vsizeMaxContiguous 1893662720
residentFast 899178496
heapAllocated 269482966

This is the "before" memory dump, taken after test_events.html.

Comment 10

[Nathan Froyd [:froydnj]]

Attachment: about:memory dump after test_runtests.html

This is the after dump.  What jumps out at me is the number of strings that are lying around, particularly the numerous short strings.

Comment 11

[(no longer active)]

The only things I can see in this log are:

1. The http://mochi.test:8888/tests/dom/imptests/editing/conformancetest/test_runtest.html window object which is not yet collected, presumably because the cycle collector has not had a chance to kick in yet.
2. The JS strings.
3. The GC heap fragmentation.

Based on the above, there is not much to be done here in the editor component.  Moving to a more appropriate component.

Comment 12

[Nathan Froyd [:froydnj]]

(In reply to Nathan Froyd (:froydnj) from comment #10)
> Created attachment 8363191 [details]
> about:memory dump after test_runtests.html
> 
> This is the after dump.  What jumps out at me is the number of strings that
> are lying around, particularly the numerous short strings.

Also curious: the "assert_equals: Wrong result returned expected [...elided...]" strings, of which about:memory says there are several thousand of, occur orders of magnitude fewer times in the log.  Could be just garbage accumulating, if the test isn't letting GC happen?