Closed Bug 1150170 Opened 5 years ago Closed 5 years ago

~20MiB regression after landing bug 1107706

Categories

(Testing :: Marionette, defect)

defect
Not set

Tracking

(firefox40 affected)

RESOLVED FIXED
Tracking Status
firefox40 --- affected

People

(Reporter: erahm, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: pi-marionette-server, Whiteboard: [MemShrink][awsy])

Attachments

(1 file, 1 obsolete file)

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
I'd be interested to see if this persists after bug 1149347 is tested.
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)
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))
(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).
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.
(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.
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.
(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://...))
Depends on: 1150247
: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
(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.
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]
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.
/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/
Attachment #8588842 - Flags: review?(ato)
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/
Attachment #8588842 - Flags: review?(ato)
Attachment #8588842 - Flags: review?(ato)
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 on attachment 8588842 [details]
MozReview Request: bz://1150170/chmanchester

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

Ship It!
Attachment #8588842 - Flags: review?(ato) → review+
raised https://bugzilla.mozilla.org/show_bug.cgi?id=1152063 for the JS Engine issue about memory usage with templates
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?
Flags: needinfo?(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.
Status: NEW → RESOLVED
Closed: 5 years ago
Flags: needinfo?(erahm)
Resolution: --- → FIXED
Attachment #8588842 - Attachment is obsolete: true
Attachment #8619946 - Flags: review+
Removing leave-open keyword from resolved bugs, per :sylvestre.
Keywords: leave-open
You need to log in before you can comment on or make changes to this bug.