Closed Bug 466877 Opened 16 years ago Closed 5 years ago

GC called during startup

Categories

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

x86
Linux
defect

Tracking

(fennec1.0-)

RESOLVED WONTFIX
fennec1.0b1
Tracking Status
fennec 1.0- ---

People

(Reporter: taras.mozilla, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: perf, Whiteboard: [ts])

Attachments

(1 file)

See bug 466281
Depends on: 466281
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?
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
Flags: blocking-fennec1.0+
Priority: -- → P3
Target Milestone: --- → Fennec A3
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.
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...
Attached file oprofile callgraph
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?
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?
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.
Would you offer some wisdom as to how to unbork this?
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...
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).
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.
Oh, and the 1/20 thing is basically a random number.  It just needs to happen "every so often".
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...
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.
Blocks: 459117
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.
Summary: Unhiding pref container caused 1.2second startup regression → GC called during startup
tracking-fennec: --- → 1.0+
tracking-fennec: 1.0+ → 1.0-
Flags: blocking-fennec1.0+ → wanted-fennec1.0+
Whiteboard: [ts]
Blocks: 447581
Closing all opened bug in a graveyard component
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.