This is the biggest overhead for app startup currently. From bug 781613: Stopwatch profile of BEC itself I/Gecko ( 504): [0ms] INITTCGLOBAL: BEC.js executing ... I/Gecko ( 504): [102ms] INITTCGLOBAL: imported modules ... I/Gecko ( 504): [108ms] INITTCGLOBAL: defined BEC ... I/Gecko ( 504): [338ms] INITTCGLOBAL: created BEC instance ... I/Gecko ( 504): [340ms] INITTCGLOBAL: defined ContentPanning ... I/Gecko ( 504): [342ms] INITTCGLOBAL: inited ContentPanning ... I/Gecko ( 504): [343ms] INITTCGLOBAL: defined KineticPanning ... I/Gecko ( 504): [343ms] INITTCGLOBAL: defined ElementTouchHelper ... I/Gecko ( 504): [344ms] INITTCGLOBAL: BEC.js done So importing modules is hurty, but BrowserElementChild:_init() is costing 200ms+. Youch. Interestingly enough, this logging also ran for master-process content, where I see I/Gecko ( 469): [0ms] INITTCGLOBAL: BEC.js executing ... I/Gecko ( 469): [35ms] INITTCGLOBAL: imported modules ... I/Gecko ( 469): [37ms] INITTCGLOBAL: defined BEC ... I/Gecko ( 469): [65ms] INITTCGLOBAL: created BEC instance ... I/Gecko ( 469): [65ms] INITTCGLOBAL: defined ContentPanning ... I/Gecko ( 469): [65ms] INITTCGLOBAL: inited ContentPanning ... I/Gecko ( 469): [66ms] INITTCGLOBAL: defined KineticPanning ... I/Gecko ( 469): [66ms] INITTCGLOBAL: defined ElementTouchHelper ... I/Gecko ( 469): [66ms] INITTCGLOBAL: BEC.js done for the first load of BrowserElementChild.js, (presumably for the in-process system app). So BEC.js takes 5x longer to run in a content process? W.T.F.!! Smells like a mjit/TI issue ... maybe we're not setting up our runtime properly or something. Could use help here. The first goal is to understand the massive discrepancy in execution time between master process and content process. In bug 781613, I ruled out the content process being starved of CPU, but it's possible that CPU/memory contention during app startup exacerbates this problem. 5x is sure damn high though ...

Help is most appreciated! :)

If I stop the master process from ostensibly doing anything (which has the compositor thread go idle too), then I get a big speedup I/Gecko ( 160): [0ms] INITTCGLOBAL: BEC.js executing ... I/Gecko ( 160): [33ms] INITTCGLOBAL: imported modules ... I/Gecko ( 160): [34ms] INITTCGLOBAL: defined BEC ... I/Gecko ( 160): [109ms] INITTCGLOBAL: created BEC instance ... I/Gecko ( 160): [110ms] INITTCGLOBAL: defined ContentPanning ... I/Gecko ( 160): [111ms] INITTCGLOBAL: inited ContentPanning ... I/Gecko ( 160): [111ms] INITTCGLOBAL: defined KineticPanning ... I/Gecko ( 160): [112ms] INITTCGLOBAL: defined ElementTouchHelper ... I/Gecko ( 160): [112ms] INITTCGLOBAL: BEC.js done More like the main-process numbers but a small overhead. That's more palatable. Damn shame the master-process main thread is uselessly resampling an async CSS animation ...

With main-thread interpolation of async animations turned off, but leaving compositor-thread interpolation on, I see I/Gecko ( 256): [0ms] LAUNCH:INITTCGLOBAL: BEC.js executing ... I/Gecko ( 256): [42ms] LAUNCH:INITTCGLOBAL: imported modules ... I/Gecko ( 256): [44ms] LAUNCH:INITTCGLOBAL: defined BEC ... I/Gecko ( 256): [138ms] LAUNCH:INITTCGLOBAL: created BEC instance ... I/Gecko ( 256): [138ms] LAUNCH:INITTCGLOBAL: defined ContentPanning ... I/Gecko ( 256): [139ms] LAUNCH:INITTCGLOBAL: inited ContentPanning ... I/Gecko ( 256): [140ms] LAUNCH:INITTCGLOBAL: defined KineticPanning ... I/Gecko ( 256): [140ms] LAUNCH:INITTCGLOBAL: defined ElementTouchHelper ... I/Gecko ( 256): [140ms] LAUNCH:INITTCGLOBAL: BEC.js done and my stopwatch says startup is ~1.1s (including my reaction time, ~200ms). The opening animation itself takes 800ms, so this gets us down to starting up within measurement error of the animation.

> So BEC.js takes 5x longer to run in a content process? Is the conclusion that we're getting killed by OS context-switching costs?

Contention seems to be blowing things up the worst. But with all that removed, we're looking at ~70ms in the best case. I hope we can get to the point where we need to improve that as well.

(In reply to Chris Jones [:cjones] [:warhammer] from comment #5) > Contention seems to be blowing things up the worst. At the risk of stating the obvious, we can easily get rid of the animation and increase the priority of the loading process. Do you have any idea whether the problematic animation is the growing rectangle or the progress bar at the top of the screen? I hear on IRC that patryk owns the animations, so we can find him on github once we figure this out.

No one ever said it was hard to get rid of the animation. Similarly, it would be easy to remove loading BrowserElementChild.js. But in both cases, doing so would be detrimental to other goals.

We should just do what roc suggested and avoid resampling animations with an overflow: hidden ancestor.

BrowserElementPromptService.mapWindowToBrowserElementChild(content, this); is taking ~160ms ...

With this instrumentation dump('entering'); BrowserElementPromptService.mapWindowToBrowserElementChild(content, this); dump('exited'); mapWindowToBrowserElementChild: function(win, browserElementChild) { dump('inside BEPS'); //... dump('exited BEPS'); } I see I/Gecko ( 939): [1344626130591 LAUNCH entering BEPS ... I/Gecko ( 939): [1344626130746 LAUNCH inside BEPS ... I/Gecko ( 939): [1344626130749 LAUNCH added to map, exiting ... I/Gecko ( 939): [1344626130749 LAUNCH exited BEPS ... So all the time is going to actually making that function call. Going to need to think about how to debug this further.

For anyone following along, BrowserElementPromptService is Cu.import("resource://gre/modules/BrowserElementPromptService.jsm"); at the top of BrowserElementChild.js.

Is there any GC/CC involved? The log-cat output is always displayed when the whole GC is done and you have to calculate backwards if it interferes with the loading. I see many SET_NEW_DOCUMENT GCs after starting apps.

You could test if GC/CC has anything to do with this by forcing a GC/CC right before the call you're timing, maybe? Bobby, is it possible there's some kind of lazy initialization that happens the first time we make a cross-compartment call to a particular compartment?

We're not doing anything unexpected like loading and initializing the .jsm when the symbol is first referenced. What is literally happening is that making this function call BrowserElementPromptService.mapWindowToBrowserElementChild(content, this); takes 150ms. WTF!?!? jseng folks, any suggestions on debugging further?

It's fun when we all midair each other :)

No GC, no CC. Just a huge-ass function call overhead. Lazy init of something very expensive seems like the most likely candidate.

You could JS_StartProfiling() just before the call. I have no idea if that will actually work, but if you have perf installed, it just /might/.

If I create a dummy Point object, exported from Geometry.jsm, the call is very cheap. So it's some property of this particular usage that's causing the overhead. Something wrapper-ish perhaps?

If I change my dummy point creation to var dummy = new Point(content, this); then I make the overhead go there, and the BrowserElementPromptService call becomes "cheap" again.

And changing it to var dummy = new Point(0/*content*/, this); makes the overhead go back to BrowserElementPromptService.map(content, this). So it's something to do with passing the |content| argument.

(Which is a getter implemented here http://mxr.mozilla.org/mozilla-central/source/content/base/src/nsInProcessTabChildGlobal.cpp#175 .)

var foo = content; makes the overhead go there. So it appears that we're initializing something docshell/outer-window-y in that GetInterface() call and it's hurty.

(In reply to Chris Jones [:cjones] [:warhammer] from comment #21) > (Which is a getter implemented here > http://mxr.mozilla.org/mozilla-central/source/content/base/src/ > nsInProcessTabChildGlobal.cpp#175 .) huh, are you testing non-OOP here? I thought OOP.

Anyhow, do we end up actually creating the window object when GetContent is called.

xpconnect wrapping threw me off the trail temporarily, but back on track now: I/Gecko ( 785): [53s:585ms] LAUNCH DocShell: creating about:blank ... I/Gecko ( 785): [54s:176ms] LAUNCH DocShell: done (debug build, so this is higher) but here's where we're eating time.

All the time is going to DocumentViewerImpl::CreateStyleSet. It's distributed among the various style sheet loads, but nsLayoutStylesheetCache::UserContentSheet() is the hurtiest.

With bug 782006, I/Gecko ( 355): [0ms] LAUNCH:INITTCGLOBAL: BEC.js executing ... I/Gecko ( 355): [98ms] LAUNCH:INITTCGLOBAL: imported modules ... I/Gecko ( 355): [108ms] LAUNCH:INITTCGLOBAL: defined BEC ... I/Gecko ( 355): [245ms] LAUNCH:INITTCGLOBAL: created and _init()d BEC instance ... I/Gecko ( 355): [246ms] LAUNCH:INITTCGLOBAL: BEC.js done so we're down almost 100ms. But still not fast.

Going to close this out and start anew on latest code.