See bug 834622 comment 48. I suspect this is due to gaia not "unhiding" the app window (removing the screenshot overlay) until it sees the mozbrowserfirstpaint event. If that's true, we can instead put the app frame over the screenshot and leave it visible during load (it will just be unpainted), and remove the screenshot after we see mozbrowserfirstpaint.

Hmmm, if I'm reading the code correctly we block on getting a new screenshot from the launched app before unhiding it. That's not good.

I don't think I understand this code well enough anymore to prototype this :/. Vivien, have you already fixed this in your set of gaia patches?

With the caveat that we're down into startup times that are hard for me to measure with the stopwatch, disabling screenshots yields the fastest startup timing I've recorded so far, 650ms. So looks like they're costing around 100ms on critical startup path.

Another problem here: the ".active" class on #windows uses style.top to show/hide the element, which is always going to force a full-expense reflow. We should be able to use a translation to get a cheaper empty transaction, if we're careful.

(In reply to Chris Jones [:cjones] [:warhammer] from comment #4) > Another problem here: the ".active" class on #windows uses style.top to > show/hide the element, which is always going to force a full-expense reflow. > We should be able to use a translation to get a cheaper empty transaction, > if we're careful. This is a very old style definition..we could remove it now and also #wiindow.active

gandalf, may I trouble you to take some measurements with your high-speed camera? I'm just not fast enough to use my stopwatch for these :/. Please check with this setup (1) Apply attachment 709312 [details] [diff] [review] on top of gecko cedbc43dfa7602f37ba451d2bdb6c3536fea823b (2) Apply this patch here to gaia Note the changes to window_manager.js; ideally I'd like to get startup measurements of Template (first time non-grayed-out pixels appear on screen) in these configurations A. screenshotsEnabled = false / setOpeningClassEarly = true B. screenshotsEnabled = false / setOpeningClassEarly = false C. screenshotsEnabled = true / setOpeningClassEarly = true D. screenshotsEnabled = true / setOpeningClassEarly = false What I see is approximately the following - without this gaia patch, startup is ~750ms - with patch and screenshotsEnabled = true / setOpeningClassEarly = false, startup is ~650ms. So the animation is slowing down startup by ~100ms still. - with patch and screenshotsEnabled = false / setOpeningClassEarly = true, startup is ~530ms. This is about the fastest we can be right now, although it would break UX's heart to do so ;). I'm having trouble getting reliable enough numbers to test the two other cases. I'm particularly interested in screenshotsEnabled = true / setOpeningClassEarly = true.

awesome! I'm at work week but I'll try to test it today. Also, if you really want to get "fastest that we can" then comment out call to https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/window_manager.js#L493 - this will stop us from polling screenshot database and setting the background screenshot overall, and with that and animation off we can get around 300ms on Template IIRC.

The patch above makes the use of screenshots configurable at "build time".

Patch from Vivien. With this and the other patches dep'd on bug 834622, Template layers are first in the composited tree in 300-350ms and stopwatch says they first appear onscreen in ~440ms (take with grain of salt). This is where we want to be. Let's see where we can get back to from here ...

With the tip of gecko-18, we're around 400ms first-in-composited tree and ~530ms first onscreen. So this is where most of the win is left.

Slow going ...

Disabling screenshots, with animations enabled and no compositor changes, shaves about 60-90ms off stopwatch start time.

From what I can tell so far, the .appWindow <divs> are visibility:hidden until they're either transitioning or active. That will make the child <iframe> hidden as well. But it appears that the animation starts from setting the .opening class, which should also be resetting visibility:visible. At that point, we should have a display item for the <iframe> and create a layer for it in the layer tree. Indeed, if we didn't do that we wouldn't see the remote tree ID resolved on the compositor. So for the specific problem of the appearance of the app window lagging behind when it's first published, we seem to be doing something wrong in the creation of the <iframe> layer.

Once I worked through the rocket science of NSPR logging in opt builds again, I was able to find that - we start running the animation *without* the Template RefLayer in the tree - we composite a couple times with that RefLayer unresolved (no subtree) - we composite one time with it only have a single container child At this point the touchstart->first-resolved-in-tree logging prints STARTUP: XXX.XXX ms elapsed between touchstart and first composite of subtree 7 - then it's composited with what should be the "real" content Interestingly, after that we composite several more times with the "real" content and what looks like the app screenshot beneath it in the tree. So it might be that we're already doing the right thing here and my eyes just can't tell. Could really use a high-speed camera or HDMI capture right now ... This shows that we're doing at least one unnecessary shadow layers transaction, even with the fix from bug 836198 applied. This isn't showing up in the gecko profiler. It also shows that the touchstart->first-resolved-in-tree monitoring may be telling us something misleading, since there's only an unpainted container layer in the shadow tree when it fires.

Some new numbers, now that I have a fixed Template app and touchstart -> window-first-appears-in-compositor code. vanilla gecko-18 || all deps of bug 834622 nice things | no nice things* || nice things | no nice things +------------+-----------------++-------------+---------------- stopwatch | 660-690ms | 500-530ms || 530-560ms | <400ms+ first-appear | 500-575ms | 350-400ms || 400-450ms | 300-350ms * "no nice things" means |appStartupOnly = true| + literally too fast for me to measure with a stopwatch So the unlanded gecko wins in bug 834622 save us around 100-150ms, turning off all the nice things also saves us 100-150ms, and both together save 200-300ms. Sigh.

gandalf or A-team folks, if you get a chance to check my stopwatch timings against a high-speed camera or HDMI capture, that'd really help know whether there really is any discrepancy here. If so ping me and I'll help get a build set up.

Yeah, the amount of patches that I need to play with is killing me. Do you want me to test only against the latest patch here applied on master?

(In reply to Chris Jones [:cjones] [:warhammer] from comment #16) > gandalf or A-team folks, if you get a chance to check my stopwatch timings > against a high-speed camera or HDMI capture, that'd really help know whether > there really is any discrepancy here. > > If so ping me and I'll help get a build set up. We can't really use HDMI capture for B2G at this time, since unagi's don't support it, and graphics perf on pandas is terrible. See Will's blog at http://wrla.ch/blog/2013/02/eideticker-for-firefoxos/. We can make camera captures of the unagi, but then have to perform stopwatch measurements against them, since we haven't yet adapted Eideticker to handle the noisy videos generated by the camera. Would this be useful? We could compare them to videos we captured last week, to see if there were any user-visible improvements. If so, we'll need a new unagi_eng build with the necessary patches.

Thanks! We caught up a bit on IRC. Here's the specific experiment I'd like to do here 1. Produce a build with attachment 711170 [details] [diff] [review] applied to gecko and attachment 711174 [details] [diff] [review] applied to gaia 2. Start the Template app once (to warm pagecache and get initial screenshot) 3. Using a recorder (jgriffin says we have elmo available), launch and record Template startup several times 4. After that, run $ adb logcat -d | grep STARTUP and save the output. 5. Analyze the elmo capture to count time between touchstart (finger down) and the first non-grayed-out paint that appears on screen, as accurately as possible. (Will have 33-66ms noise, no worries.) Then I want to compare the times reported in step (4) to what we manually count in step (5).

I assume this gecko patch should be applied to mozilla-inbound; it didn't apply cleanly to mozilla-b2g18, but did to m-i. I'm going ahead with a build made from m-i. The gaia patch mentioned in comment #19 has already landed in the Gaia repo, so there was nothing to apply there.

The gaia patch isn't in v1-train (or wasn't before my lunchtime), but it shouldn't matter which gaia branch you test with. If Template has a pink background instead of white, then you have the right code applied.

Results from elmo were hard to interpret due to low-quality data gathered. Based on wlach's best guess the frame seemed to be displayed within 50-60ms after the time gecko reported. My gf's little pocket camera can do 60fps captures (although playback showed they're actually 30fps), and the data quality was considerably better. Using that I counted 33 frames between finger-down and screen showing non-screenshot paint. That's (theoretically) 16.667ms * (33-1) ~= 533ms. Gecko reported 528ms. So I think the lag in the stopwatch measurement is looking like human overhead.