Closed Bug 830545 Opened 11 years ago Closed 11 years ago

700ms regression in settings startup time between 1/07 and 1/10

Categories

(Firefox OS Graveyard :: Gaia::Settings, defect)

Product:
Firefox OS Graveyard
Component:
Gaia::Settings
Platform:
ARM
Gonk (Firefox OS)
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(b2g18+)

Status:
RESOLVED DUPLICATE of bug 808216
Tracking Flags:
Tracking Status
b2g18 + ---

People

(Reporter: cjones, Unassigned)

References

Details

(Keywords: regression, Whiteboard: [EU_TPE_TRIAGED]) 

On an unagi flashed with a 12/30 nightly build, startup time is about 2.3 seconds.  On an otoro flashed with local build from today, startup is about 3.5 seconds.  Startup will be faster on unagi but not this much faster.

Checking unagi with build from today.
blocking-b2g: --- → tef?
Keywords: regressionwindow-wanted
Methodology
 - unpack build, flash
 - go through FTU and set up wifi network
 - open settings, force update check, wait for update notification
 - close settings
 - open, measure with stopwatch until first "real" paint, close, repeat a few times

01/07 - ~2.5s
01/08 - (busted :|)
01/09 - ~3.0s
01/10 - ~3.2s
01/14 - ~3.2s

Guys, know of any changes that might have regressed here?
Summary: Over 1 second regression in settings startup time → 700ms regression in settings startup time between 1/07 and 1/10
(In reply to Chris Jones [:cjones] [:warhammer] from comment #2)
> (In reply to Chris Jones [:cjones] [:warhammer] from comment #1)
> > 01/07 - ~2.5s
> > 01/08 - (busted :|)
> > 01/09 - ~3.0s

Author: Fabien Cazenave <fabien@cazenave.cc>
Date:   Tue Jan 8 18:01:54 2013 +0100

    bug 815852: inline l10n resources to avoid flickering on all localized apps
Blocks: 815852
Note: with some more careful measurements, the regression in comment 3 is actually ~2.4s -> ~2.9s.
I wonder if bug 830521 is related?
(In reply to Chris Jones [:cjones] [:warhammer] from comment #5)
> I wonder if bug 830521 is related?

nope. 

How do you measure startup?
if you apply patch from bug 829869 you can use "show load time".
commit d029e72b4798972c7ac3dca1afe351801301f2c0
Author: Blake Kaplan <mrbkap@gmail.com>
Date:   Wed Jan 9 15:14:22 2013 +0100

    Bug 823783 - Handle various combinations of settings events and wifi events more correctly.
Blocks: 823783
(In reply to Chris Jones [:cjones] [:warhammer] from comment #2)
> (In reply to Chris Jones [:cjones] [:warhammer] from comment #1)
> > 01/09 - ~3.0s
> > 01/10 - ~3.2s

Comment 8 is this ^^^ regression.  More careful measurements show it's ~2.9s -> ~3.0s.
(In reply to Zbigniew Braniecki [:gandalf] from comment #6)
> How do you measure startup?

Stopwatch, measuring from icon tap to first non-screenshot paint of window.
(In reply to Zbigniew Braniecki [:gandalf] from comment #6)
> (In reply to Chris Jones [:cjones] [:warhammer] from comment #5)
> > I wonder if bug 830521 is related?
> 
> nope. 

This patch shaves about 200ms off settings startup.
Depends on: 830521
(In reply to Chris Jones [:cjones] [:warhammer] from comment #11)
> (In reply to Zbigniew Braniecki [:gandalf] from comment #6)
> > (In reply to Chris Jones [:cjones] [:warhammer] from comment #5)
> > > I wonder if bug 830521 is related?
> > 
> > nope. 
> 
> This patch shaves about 200ms off settings startup.

That's weird... OH! IT IS NOT!

So... without this patch we actually fire ALL the code that depends on "localized" event TWICE. That surely adds to the load :)
(In reply to Chris Jones [:cjones] [:warhammer] from comment #9)
> (In reply to Chris Jones [:cjones] [:warhammer] from comment #2)
> > (In reply to Chris Jones [:cjones] [:warhammer] from comment #1)
> > > 01/09 - ~3.0s
> > > 01/10 - ~3.2s
> 
> Comment 8 is this ^^^ regression.  More careful measurements show it's ~2.9s
> -> ~3.0s.

I don't know how. That patch affects only settings/js/wifi.js.  And that file is in a script tag that is commented out. If I understand the settings app architecture correctly, the script is only loaded and run when you go to the wifi panel. So I can't see how that patch could have any impact on settings startup time at all.

As a general thing, I think one of the big problems with the settings app is that each module does its own queries of the setting database.  I suspect there would be a big improvement if the app started off with settings.createLock().get('*') and just queried everything at once.  We've got all kinds of settings API abuse throughout the system app, too, including utility functions that may well be anti-patterns.  Lots to work on for v2!
I should add that I've got a followup patch in bug 823783 which does alter a file that is loaded at application launch, but only adds a single call to settings.createLock().set(), so hopefully it won't be too bad.
Hmm ... it's possible the bisect failed.  The startup regression is about within my margin of error for this measurement method.
No longer blocks: 823783
chris: if you give me two changesets you're certain about I can test it with hfr camera to obtain external measurements.
Do you mean for the second bisect that might have returned bogus results?

good: f8e15c1774ea03332d0fb688b706a6c3cbe1e186
bad:  9d4983b18d5ff79b5900a8075d38eea352635728
I don't see any measurable diff between those two. DOMContentLoaded, window.load and firstPaint stay the same.
I can reliably measure a ~100ms regression between those two with a stopwatch, but maybe not reliably enough in my bisect ...
I tried another bisect but found a different commit that definitely wasn't at fault.  I guess we'll have to let the second regression slide until we have better tools.
blocking-b2g: tef? → -
tracking-b2g18: --- → +
Whiteboard: [EU_TPE_TRIAGED]
Triage: TEF-, tracking-b2g18+, would take a patch
Chris,

Bug 793239 just landed on m-i with a patch to SettingsLock that allows us to tell if a cached SettingsLock object is still valid.  If we get this patch landed on b2g18, we could modify gaia/shared/js/settings_listener.js to use it, which would make the getSettingsLock() method in that file much simpler and more efficient.

This *might* speed up the Settings app startup time.  If you want to pursue this, and can get 793239 landed to b2g18, I'll modify settings_listener.js to match.  Probably too late, but I thought I'd bring it up.  (Because I filed 793239 for exactly this reason: to fix the settings listener utility.)
That sounds like a nice optimization, but I'd like to fix the regressions.  Known 600ms win :/.
Chris, do we have any plans to fix that finally?
Flags: needinfo?(jones.chris.g)
I found the regressing patch and author ;), I consider my work here to be done.

kaze, any way we can make bug 815852 not regress startup so much?
Flags: needinfo?(jones.chris.g) → needinfo?(kaze)
I still have three blockers in my TODO-list… Make this one a blocker (or convince my manager to let me work on it) and I’ll address it right now. :-/
Flags: needinfo?(kaze)
blocking-b2g: - → shira?
You don't need to write all the code, but hypotheses about the regression, or suggestions of how to fix it, would be helpful.

Folks newly CC'd, we need to keep this pretty high in the startup work queue.
We're well below 2s startup with bug 808216.  So I'll call the regression here gone, but I don't have time to test with the base commits above to say that scientifically.
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → DUPLICATE
blocking-b2g: shira? → ---
You need to log in before you can comment on or make changes to this bug.