1122649 - [mozSettings] mozSettings access has a synchronous penalty

Status: RESOLVED WONTFIX

(Firefox OS Graveyard :: General, defect)

Description

[Julien Wajsberg [:julienw]]

Attachment: 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.

Comment 1

[Julien Wajsberg [:julienw]]

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.

Comment 2

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

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

Comment 3

[:gerard-majax]

(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?

Comment 4

[:gerard-majax]

(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 ?

Comment 5

[Julien Wajsberg [:julienw]]

(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.

Comment 6

[:gerard-majax]

Attachment: Trivial measurement

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.

Comment 7

[:gerard-majax]

Attachment: Console output on a 50-set run

Comment 8

[:gerard-majax]

Attachment: navigator.mozSettings.createLock() only

Comment 9

[:gerard-majax]

Attachment: navigator.mozSettings.createLock(), then get()

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");
}

Comment 10

[:gerard-majax]

Attachment: Profile for several createLock() then get()

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

Comment 11

[:gerard-majax]

Attachment: Profile for several createLock().get()

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

Comment 12

[:gerard-majax]

  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

Comment 13

[:gerard-majax]

Attachment: perfs-settings.diff

Comment 14

[Julien Wajsberg [:julienw]]

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?

Comment 15

[:gerard-majax]

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

Comment 16

[:gerard-majax]

(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.

Comment 17

[:gerard-majax]

(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.