466877 - GC called during startup

Status: RESOLVED WONTFIX

(Firefox for Android Graveyard :: General, defect, P3)

Description

[(dormant account)]

See bug 466281

Comment 1

[(dormant account)]

Most of the slowdown is caused by <richpref> elements. iframes appear to be innocent.
richpref causes loading of richpref.xbl file(only about 40ms) and then most of the time is spent (800ms?) is spent on <xul:preferences> elements.

So far these are the slowest xbl elements I've encountered. I wonder if there is a good place in the good to instrument how long it takes for a particular xbl element to load?

Comment 2

[(dormant account)]

XBL loading isn't low overhead as I initially thought. it also loads preferences.xml - 70ms, checkbox.xml -39ms, text.xml -39ms

so almost 200ms just for additional xbl loaded

Comment 3

[(dormant account)]

Dug into it depeer and seems that xbl-generated set_value() is thank for perf hit. 
So in the code at 
http://mxr.mozilla.org/mobile-browser/source/chrome/content/preferences/richpref.xml#93
i changed onset to onset="return this.input"
and played with setting input to be 
      <field name="input">{value:0}</field>
or
      <field name="input"></field>

The weird part is that the {value:0} variant takes 130ms longer to execute(vs 7).Even on my laptop i can measure it to take 4ms.

Comment 4

[Boris Zbarsky [:bzbarsky]]

The variant without a value for the field is basically a no-op.  The variant with "{value:0}" takes that string, calls into the JS engine to evaluate it, then defines a property with that value on the content node.

That really shouldn't take 4ms on a laptop, though.

Taras, are you on Mac, by chance?  You might be able to just stick some calls to start/stop shark into nsXBLProtoImplField::InstallField for the case when mName and aBindingDocURI are appropriate and see where the time is spent...

Comment 5

[(dormant account)]

Attachment: oprofile callgraph

Comment 6

[(dormant account)]

bz,
commenting out the call to gc eliminates installfield slowness
http://mxr.mozilla.org/mozilla-central/source/dom/src/base/nsJSEnvironment.cpp#3306 

Apparently we aren't supposed to be calling gc on startup, is there a flag I can use to guard against that?

Comment 7

[Boris Zbarsky [:bzbarsky]]

I recall hearing about that, but I don't recall what (if anything) in our code is supposed to enforce that.  jst, do you remember?

Comment 8

[(dormant account)]

it's NS_FIRST_GC_DELAY in http://mxr.mozilla.org/mozilla-central/source/dom/src/base/nsJSEnvironment.cpp#3504

Comment 9

[Boris Zbarsky [:bzbarsky]]

Oh.  That wouldn't affect either GC off the operation callback or the GC that happens in ScriptEvaluated...  It only affects explicit nsIScriptContext::GC calls (which is wrong, btw; those claim to be synchronous!) and what happens when the GC timer fires (in which case first is always false).

Sounds pretty broken all around to me.

Comment 10

[(dormant account)]

Would you offer some wisdom as to how to unbork this?

Comment 11

[Boris Zbarsky [:bzbarsky]]

General unborking would involve making GC() sync and using some other API for whatever async callers we've got now...

Unborking the "GC during startup" thing probabaly means switching the operation callback and ScriptEvaluated GC call to using the GC timer.  Not sure how happy that is in the case of the operation callback...

Comment 12

[(dormant account)]

I'm unsure of what the benefit of explicit gc requests with a strange 1/20 func calls heuristic is. Shouldn't the js engine be able to make a better choice in that regard? 
I can see higher level code issuing full GCs when startup is complete or in response to some other event, but I don't see why calling js_GC as it is atm is beneficial(probably missing some important detail).

Comment 13

[Boris Zbarsky [:bzbarsky]]

The JS engine basically never GCs on its own very much.  As I recall, it'll basically only do it when it hits allocation failure or gets close to the limits of the GC heap size.

So to avoid bloating up to the maximal GC heap size, we GC periodically as code runs.  The operation callback handles long-running code, while the other callsite handles short repeated bits of code (e.g. event handlers, timeouts, etc) which might be creating garbage.

Comment 14

[Boris Zbarsky [:bzbarsky]]

Oh, and the 1/20 thing is basically a random number.  It just needs to happen "every so often".

Comment 15

[Boris Zbarsky [:bzbarsky]]

I should also note that I bet these used to be JS_MaybeGC calls, but now they do a possible cycle collection, so will trigger GC if there's been enough refcounting activity...

Comment 16

[(dormant account)]

Looks like there is only one call to GC from nsJSEnvironment during startup, so this isn't *that* big of a deal. However it did expose the fact that 1second of startup is spent in JS GC, which is interesting.

Comment 17

[Mark Finkle (:mfinkle) (use needinfo?)]

bug 456870 removes the 1.2 sec pref regression during startup by hiding the panel until needed.

I'm leaving this bug open since it has evolved into a more generic issue.

Comment 18

[BMO Automation]

Closing all opened bug in a graveyard component