Apply this patch, flash the SMS application, and run WebIDE to run and capture the result of the patch. (this doesn't show up properly in logcat). Result on my Flame with a recent build: mozSettings: 24.85ms mozSettings lock: 7.63ms mozSettings get: 5.17ms This needs to be fixed.

Please note this is not happening in this file only. Also note that merely accessing the mozSettings property, without even calling anything, takes the biggest part of the time, even if the other calls are also bad.

I've got the user timing API review in for review in bug 782751, seems like it might be handy for confirming this.

(In reply to Julien Wajsberg [:julienw] from comment #0) > Created attachment 8550403 [details] [diff] [review] > debug-mozsettings.patch > > Apply this patch, flash the SMS application, and run WebIDE to run and > capture the result of the patch. (this doesn't show up properly in logcat). > > Result on my Flame with a recent build: > > mozSettings: 24.85ms > mozSettings lock: 7.63ms > mozSettings get: 5.17ms > > This needs to be fixed. Are those figures for everytime you access it, or is there some hidden setup cost behind ? i.e., if you do multiple mozSettings use, will you get those values for each, or only big figures for the first one?

(In reply to Julien Wajsberg [:julienw] from comment #0) > Created attachment 8550403 [details] [diff] [review] > debug-mozsettings.patch > > Apply this patch, flash the SMS application, and run WebIDE to run and > capture the result of the patch. (this doesn't show up properly in logcat). > > Result on my Flame with a recent build: > > mozSettings: 24.85ms > mozSettings lock: 7.63ms > mozSettings get: 5.17ms > > This needs to be fixed. Subsequent question, what's the timing for: |var req = window.navigator.mozSettings.createLock().get(_kLocaleTime);| Does it gets 24.85+7.63+5.17=37.65 ?

(In reply to Alexandre LISSY :gerard-majax from comment #3) > > Are those figures for everytime you access it, or is there some hidden setup > cost behind ? > i.e., if you do multiple mozSettings use, will you get those values for > each, or only big figures for the first one? I think we get it each time. See bug 1087329 comment 3: every file that uses mozSettings get a penalty: notify.js, settings.js, time_headers.js, date_time_helper.js. Maybe it's slightly lower the second time, I'm not sure. (In reply to Alexandre LISSY :gerard-majax from comment #4) > Subsequent question, what's the timing for: > |var req = window.navigator.mozSettings.createLock().get(_kLocaleTime);| > > Does it gets 24.85+7.63+5.17=37.65 ? Yep. Also, since it happens at startup time, maybe it competes with other tasks. We could try to measure at a more peaceful moment.

In a dedicated app, nothing else running. I get about 3100ms-3600ms for mozSettings_createLock_get. I also noticed that the first calls costs much, like the very first one around 20ms, then slow decrease (1-2ms per call) until reaching ~5-6ms.

function start() { console.time("mozSettings_createLock_then_get"); for (var i = 0; i < 50; i++) { console.time("mozSettings_createLock_" + i); var req = navigator.mozSettings.createLock(); console.timeEnd("mozSettings_createLock_" + i); console.time("mozSettings_get_" + i); req.get("language.current"); console.timeEnd("mozSettings_get_" + i); } console.timeEnd("mozSettings_createLock_get_then_get"); }

This profile was run against multiple execution of the results presented in attachment 8551324 [details].

This profile was a run of 1000 |navigator.mozSettings.createLock().get()|

1276 01-20 13:21:29.373 10839 10839 I Gecko : *** [PERF] SettingsManager: SettingsManager:createLock:in: 7ms 1277 01-20 13:21:29.373 10839 10839 I Gecko : *** [PERF] SettingsManager: SettingsLock:constr:in: 8ms 1278 01-20 13:21:29.383 10839 10839 I Gecko : *** [PERF] SettingsManager: SettingsLock:constr:before-payload: 12ms 1279 01-20 13:21:29.383 10839 10839 I Gecko : *** [PERF] SettingsManager: SettingsLock:constr:after-payload: 13ms 1280 01-20 13:21:29.383 10839 10839 I Gecko : *** [PERF] SettingsManager: SettingsLock:constr:out: 17ms 1281 01-20 13:21:29.383 10839 10839 I Gecko : *** [PERF] SettingsManager: SettingsManager:createLock:ok: 18ms 1282 01-20 13:21:29.393 10839 10839 I Gecko : *** [PERF] SettingsManager: SettingsManager:createLock:out: 19ms It takes 7ms from loading SettingsManager.js to getting to the top of the SettingsManager.createLock() method. Then it takes 12ms to complete createLock(): - 4ms are spent between: https://dxr.mozilla.org/mozilla-central/source/dom/settings/SettingsManager.js#59 and https://dxr.mozilla.org/mozilla-central/source/dom/settings/SettingsManager.js#69 - it takes 1ms to have createPayload built - then 4ms between sending the message and getting out of the function

I checked again using my own measurement way and I have ~ the same measurements than Alexandre has: * access to the mozSettings object is expensive only the first time * createLock+get lasts between 5 and 10 ms each time (synchronously). Why couldn't we preload mozSettings early when we launch an app that has one of the settings permissions?

So it looks like we have code to preload Settings API, but this do not work: bug 1124102

(In reply to Alexandre LISSY :gerard-majax from comment #15) > So it looks like we have code to preload Settings API, but this do not work: > bug 1124102 We can save 20ms with bug 1124102 when you do the call. There is still a ~10ms coming from the instanciation of SettingsManager itself at this time, and then 15ms for createLock(). Discussing with Vivien, he came with some idea that may help reducing the instanciation penalty, but this needs more documentation to make sure we profit.

(In reply to Julien Wajsberg [:julienw] from comment #14) > I checked again using my own measurement way and I have ~ the same > measurements than Alexandre has: > > * access to the mozSettings object is expensive only the first time > * createLock+get lasts between 5 and 10 ms each time (synchronously). > > Why couldn't we preload mozSettings early when we launch an app that has one > of the settings permissions? Preloading was not done properly previously, this has been fixed in bug 1124102. Now, the next big things that you are hitting on your path are: - ~10ms for creating the first SettingsManager object on Gecko when you call |navigator.mozSettings| ; unfortunately, it will be hard to preload this part ; - ~10-15ms for createLock, and after having a look at this, it's also hard to see where we can improve much more. Pre-creating this when we create the first SettingsManager object just moves the cost from |createLock()| to |navigator.mozSettings| - for the cost of .get() I have not yet had a precise look, but maybe switching the pref |dom.mozSettings.allowForceReadOnly| to true could help for the read only cases like .get() ? Please note that .get()/.set() involves a lot of sendAsyncMessage/receiveMessage and IndexedDB-backed operations, so it may be harder and longer to get speedup there.