1150170 - ~20MiB regression after landing bug 1107706

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect)

Description

[Eric Rahm [:erahm]]

We're seeing a rather large regression in AWSY around 2015/03/26 corresponding with the landing of bug 1107706.

As AWSY relies on marionette [1] to run it's memory tests this is a particularly problematic issue.

[1] https://github.com/mozilla/areweslimyet/blob/master/benchtester/test_memory_usage.py

Comment 1

[Jonathan Griffin (:jgriffin)]

I'd be interested to see if this persists after bug 1149347 is tested.

Comment 2

[Eric Rahm [:erahm]]

Looking at an about:memory diff before and after the regression shows a majority of the overhead is in strings. The prominent ones are mostly related to the memory results we pass back to execute_async_script [1]. Also note that these strings are leftover from the previous snapshot ("TabsOpenForceGC"), so it seems like something changed for the worse in the serialization of the results object.

Additionally we see:
- 0.23 MiB of strings related to "GeckoDriver.prototype.createExecuteSandbox"
- 2.87 MB increase of the inProcessTabChildGlobal compartment
- A large increase in the amount of compartments

Diff of the TabsClosed measurement:

> 15.89 MB (100.0%) -- explicit
> ├──14.23 MB (89.58%) -- js-non-window
> │  ├──14.29 MB (89.94%) -- zones/zone(0xNNN)
> │  │  ├───9.37 MB (59.01%) -- strings
> │  │  │   ├──-6.29 MB (-39.61%) ++ string(length=2198213, copies=3, "{"from":"0","value":{"label":"TabsOpenForceGC","timestamp":{},"memory":{"Main":{"resident":459460608,"explicit/preferences":377064,"preference-service/referent/strong":{"unit":"cnt","val":678} (truncated))
> │  │  │   ├──4.27 MB (26.85%) ++ string(length=2232500, copies=2, "{"from":"0","value":{"label":"TabsOpenForceGC","timestamp":{},"memory":{"Main": (truncated))
> │  │  │   ├──2.73 MB (17.16%) ++ string(<non-notable strings>)
> │  │  │   ├──2.40 MB (15.10%) ++ string(length=2232508, copies=1, "2232500:{"from":"0","value":{"label":"TabsOpenForceGC","timestamp":{},"memory":{"Main":{"explicit/window-objects/top(http:////////localhost:8086////tp5////xunlei.com////xunlei.com////index.html, id=2615)/ (truncated))
> │  │  │   ├──-2.36 MB (-14.85%) ++ string(length=2198221, copies=1, "2198213:{"from":"0","value":{"label":"TabsOpenForceGC","timestamp":{},"memory":{"Main":{"resident":459460608,"explicit/preferences":377064,"preference-service/referent/strong": (truncated))
> │  │  │   ├──2.14 MB (13.45%) ++ string(length=2239898, copies=1, "{'explicit/window-objects/top(http:////////localhost:8086////tp5////xunlei.com////xunlei.com////index.html, (truncated))
> │  │  │   ├──2.14 MB (13.45%) ++ string(length=2239905, copies=1, "{Main:{'explicit/window-objects/top(http:////////localhost:8086////tp5////xunlei.com////xunlei.com////index.html, (truncated))
> │  │  │   ├──2.14 MB (13.45%) ++ string(length=2239953, copies=1, "{label:"TabsOpenForceGC", timestamp:{}, memory:{Main:{'explicit/window-objects/top(http:////////localhost:8086////tp5////xunlei.com////xunlei.com////index.html, id=2615)/active/window(http:////////localhost:8086////tp5////xunlei.com////xunlei.com//// (truncated))
> │  │  │   ├──2.14 MB (13.45%) ++ string(length=2240035, copies=1, "({from:"0", value:{label:"TabsOpenForceGC", timestamp:{}, memory:{Main:{'explicit/window-objects/top(http:////////localhost:8086////tp5////xunlei.com////xunlei.com////index.html, id=2615)/active/window(http:////////localhost:8086////tp5////xunlei.com/ (truncated))
> │  │  │   ├──0.23 MB (01.44%) ++ string(length=1329, copies=116, "GeckoDriver.prototype.createExecuteSandbox/<@chrome://marionette/content/driver.js:834:16/nGeckoDriver.prototype.createExecuteSandbox@chrome://marionette/content/driver.js:832:3/nGeckoDriver.prototype.execute@chrome://marionette/content/driver.js:979:20/nTaskImpl_run@resource://gre/modules/Task.jsm:330:41/nTaskImpl@resource://gre/modules/Task.jsm:275:3/ncreateAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:249:14/nTask_spawn@resource://gre/modules/Task.jsm:164:12/nTaskImpl_handleResultValue@resource://gre/modules/Task.jsm:381:1/nTaskImpl_run@resource://gre/modules/Task.jsm:322:13/nTaskImpl@resource://gre/modules/Task.jsm:275:3/ncreateAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:249:14/nTask_spawn@resource://gre/modules/Task.jsm:164:12/nCommandProcessor.prototype.execute@chrome://marionette/content/command.js:158:13/nDispatcher.prototype.onPacket@chrome://marionette/content/dispatcher.js:75:5/nDebuggerTransport.prototype._onJSONObjectReady/<@resource://gre/modules/devtools/dbg-clien" (truncated))
> │  │  │   └──-0.14 MB (-0.88%) ++ (28 tiny)
> │  │  ├───2.87 MB (18.05%) -- compartment([System Principal], inProcessTabChildGlobal?ownedBy=chrome://browser/content/browser.xul)
> │  │  │   ├──1.53 MB (09.66%) ++ scripts
> │  │  │   ├──1.33 MB (08.36%) -- classes
> │  │  │   │  ├──0.79 MB (04.96%) ++ class(Function)/objects
> │  │  │   │  ├──0.41 MB (02.59%) ++ class(Object)
> │  │  │   │  └──0.13 MB (00.81%) -- (4 tiny)
> │  │  │   │     ├──0.05 MB (00.32%) ++ class(<non-notable classes>)
> │  │  │   │     ├──0.04 MB (00.27%) ++ class(Block)
> │  │  │   │     ├──0.02 MB (00.13%) ── class(ContentFrameMessageManager)/shapes/gc-heap/dict
> │  │  │   │     └──0.02 MB (00.10%) ++ class(Array)
> │  │  │   └──0.01 MB (00.04%) ++ (3 tiny)
> │  │  ├──-1.61 MB (-10.15%) ++ compartment([System Principal], [anonymous sandbox] (from: chrome://marionette/content/marionette-server.js:848))
> │  │  ├───1.58 MB (09.92%) ++ compartment([System Principal], [anonymous sandbox] (from: chrome://marionette/content/driver.js:827))
> │  │  ├───0.96 MB (06.07%) ++ compartment([System Principal], chrome://marionette/content/elements.js)
> │  │  ├──-0.95 MB (-5.97%) ++ compartment([System Principal], jar:file:///tmp/tmpFaxPEvBuildGetter_firefox/firefox/omni.ja!/components/marionettecomponent.js)
> │  │  ├──-0.94 MB (-5.89%) ++ compartment([System Principal], chrome://marionette/content/marionette-elements.js)
> │  │  ├───0.78 MB (04.88%) ++ (151 tiny)
> │  │  ├───0.73 MB (04.59%) ++ compartment([System Principal], chrome://marionette/content/driver.js)
> │  │  ├───0.36 MB (02.29%) ++ object-groups
> │  │  ├───0.28 MB (01.74%) ── unused-gc-things [32]
> │  │  ├───0.26 MB (01.64%) ++ compartment([System Principal], chrome://marionette/content/server.js)
> │  │  ├───0.23 MB (01.42%) ++ compartment([System Principal], resource://gre/modules/Promise.jsm)
> │  │  ├───0.21 MB (01.29%) ++ compartment([System Principal], chrome://marionette/content/command.js)
> │  │  ├───0.17 MB (01.04%) ++ compartment([System Principal], resource://gre/modules/AddonWatcher.jsm)
> │  ├──-0.12 MB (-0.75%) ++ runtime
> │  └───0.06 MB (00.39%) ── gc-heap/chunk-admin
> ├──-5.31 MB (-33.42%) ++ heap-overhead
> ├───5.45 MB (34.30%) ── heap-unclassified
> ├───1.16 MB (07.28%) ++ images/content/raster
> ├───0.19 MB (01.18%) ── dom/event-listener-managers-hash
> └───0.17 MB (01.07%) ++ (9 tiny)

Comment 3

[David Burns :automatedtester]

There appears to be 1.61 MB being used on a file that is no longer in the tree... why is that?

 ├──-1.61 MB (-10.15%) ++ compartment([System Principal], [anonymous sandbox] (from: chrome://marionette/content/marionette-server.js:848))

Comment 4

[Eric Rahm [:erahm]]

(In reply to David Burns :automatedtester from comment #3)
> There appears to be 1.61 MB being used on a file that is no longer in the
> tree... why is that?
> 
>  ├──-1.61 MB (-10.15%) ++ compartment([System Principal], [anonymous
> sandbox] (from: chrome://marionette/content/marionette-server.js:848))

It's not super clear, but there's a '-' prefixing the value, indicating it wasn't present in the 'after' snapshot (which would certainly make sense if it was removed).

Comment 5

[Eric Rahm [:erahm]]

Also of note is a 5.45 MiB increase of heap-unclassified which indicates we're using a lot more of something that isn't being reported.

Comment 6

[Andreas Tolfsen ❲:ato❳]

(In reply to Eric Rahm [:erahm] from comment #4)
> (In reply to David Burns :automatedtester from comment #3)
> > There appears to be 1.61 MB being used on a file that is no longer in the
> > tree... why is that?
> > 
> >  ├──-1.61 MB (-10.15%) ++ compartment([System Principal], [anonymous
> > sandbox] (from: chrome://marionette/content/marionette-server.js:848))
> 
> It's not super clear, but there's a '-' prefixing the value, indicating it
> wasn't present in the 'after' snapshot (which would certainly make sense if
> it was removed).

marionette-server.js was renamed to driver.js in this patch.  Parts of it was split out to dispatcher.js and server.js.

Similarly marionette-listener.js was renamed listener.js.  This also applies to a few more self-explaining files.

Comment 7

[Andreas Tolfsen ❲:ato❳]

Does “anonymous sandbox” imply something run inside a Sandbox object (https://developer.mozilla.org/en/docs/Components.utils.Sandbox)?  If so, that's arbitrary JS injected through Marionette's executeScript/executeAsyncScript routines.

Comment 8

[Eric Rahm [:erahm]]

(In reply to Andreas Tolfsen (:ato) from comment #7)
> Does “anonymous sandbox” imply something run inside a Sandbox object
> (https://developer.mozilla.org/en/docs/Components.utils.Sandbox)?  If so,
> that's arbitrary JS injected through Marionette's
> executeScript/executeAsyncScript routines.

Yes, we see two references to anonymous sandboxes (one increase, one decrease), our diff got confused b/c the path of where the sandbox came from changed. If we normalize the paths we'd see a delta of '-0.03 MB', so this can be ignored.

ie:

> │  │  ├──-1.61 MB (-10.15%) ++ compartment([System Principal], [anonymous sandbox] (from: chrome://marionette/content/marionette-server.js:848))
> │  │  ├───1.58 MB (09.92%) ++ compartment([System Principal], [anonymous sandbox] (from: chrome://marionette/content/driver.js:827))

becomes:

> │  │  ├──-0.03 MB (...) ++ compartment([System Principal], [anonymous sandbox] (from: chrome://...))

Comment 9

[Eric Rahm [:erahm]]

:chmanchester tested out a patch that disables logging of packet contents [1] which seems to have reduced the amount of 2.14MB intermediate strings in a custom AWSY run [2]. This accounts for a large portion of the strings and is definitely something we should avoid.

[1] https://hg.mozilla.org/mozilla-central/annotate/883e17fc475f/testing/marionette/dispatcher.js#l263
[2] https://areweslimyet.com/?series=cm_mn&evenspacing

Comment 10

[Chris Manchester (limited bugmail, email directly)]

(In reply to Eric Rahm [:erahm] from comment #9)
> :chmanchester tested out a patch that disables logging of packet contents
> [1] which seems to have reduced the amount of 2.14MB intermediate strings in
> a custom AWSY run [2]. This accounts for a large portion of the strings and
> is definitely something we should avoid.
> 
> [1]
> https://hg.mozilla.org/mozilla-central/annotate/883e17fc475f/testing/
> marionette/dispatcher.js#l263
> [2] https://areweslimyet.com/?series=cm_mn&evenspacing

A diff between the first two points on the "After TP5, tabs closed" graph looks quite a bit like a partial reversal of the diff in comment 2, so this looks promising.

Comment 11

[Chris Manchester (limited bugmail, email directly)]

To clarify, we've always logged the entire response payload so I don't think we should need to turn that off to address the regression. I pushed a few more data points to https://areweslimyet.com/?series=cm_mn&evenspacing that are starting to come in. In order, the graph will show: 
[trunk, no response logging, trunk, trunk, modified formatting of response logs]

Comment 12

[Chris Manchester (limited bugmail, email directly)]

The last push came in and looks good vs. the baseline. erahm points out that there's a penalty for calling JSON.stringify on the large string vs. avoiding the log altogether.

Comment 13

[Chris Manchester (limited bugmail, email directly)]

Attachment: MozReview Request: bz://1150170/chmanchester

/r/6685 - Bug 1150170 - Avoid toSource and string templates when serializing responses, which may be rather large.; r=ato

Pull down this commit:

hg pull -r 378ca0cd4c23c9cc287bead4b25d00768b38bec6 https://reviewboard-hg.mozilla.org/gecko/

Comment 14

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8588842 [details]
MozReview Request: bz://1150170/chmanchester

/r/6685 - Bug 1150170 - Avoid toSource and string templates when serializing responses, which may be rather large.; r=ato

Pull down this commit:

hg pull -r 378ca0cd4c23c9cc287bead4b25d00768b38bec6 https://reviewboard-hg.mozilla.org/gecko/

Comment 15

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8588842 [details]
MozReview Request: bz://1150170/chmanchester

https://reviewboard.mozilla.org/r/6683/#review5571

Please do the same on :67 (https://dxr.mozilla.org/mozilla-central/source/testing/marionette/dispatcher.js#67)

Comment 16

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8588842 [details]
MozReview Request: bz://1150170/chmanchester

/r/6685 - Bug 1150170 - Avoid toSource and string templates when logging requests and responses in marionette to avoid high memory use.; r=ato

Pull down this commit:

hg pull -r c159d337c423e767d0d3615268ae089664c5a380 https://reviewboard-hg.mozilla.org/gecko/

Comment 17

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8588842 [details]
MozReview Request: bz://1150170/chmanchester

https://reviewboard.mozilla.org/r/6683/#review5599

Ship It!

Comment 18

[Chris Manchester (limited bugmail, email directly)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=e09e106778d8

Comment 19

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/3cdb12131f67

Comment 20

[David Burns :automatedtester]

raised https://bugzilla.mozilla.org/show_bug.cgi?id=1152063 for the JS Engine issue about memory usage with templates

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/3cdb12131f67

Comment 22

[Chris Manchester (limited bugmail, email directly)]

The overall graph is a little choppy, but there's a clear improvement after on awsy after this landed. erahm, should we call this fixed?

Comment 23

[Eric Rahm [:erahm]]

Yes it appears to have improved. The fix is very clear on my e10s testing server so I think we can call it good and file follow ups if necessary.

Comment 25

[Chris Manchester (limited bugmail, email directly)]

Attachment: MozReview Request: Bug 1150170 - Avoid toSource and string templates when logging requests and responses in marionette to avoid high memory use.; r=ato

Comment 26

[Firefox Bug Husbandry Bot]

Removing leave-open keyword from resolved bugs, per :sylvestre.