The very first requests done by settings.js at boot. For instance, the first one is: > 01-22 13:35:19.469 16481 16481 I Gecko : -*- SettingsManager: get ({12692ae5-cc6f-4a92-b100-0a6103003086}): debug.console.enabled > 01-22 13:35:19.759 16481 16481 I Gecko : -*- SettingsRequestManager: Received getRequest from {12692ae5-cc6f-4a92-b100-0a6103003086} > 01-22 13:35:22.429 16481 16481 I Gecko : -*- SettingsRequestManager: Running Get task on lock {12692ae5-cc6f-4a92-b100-0a6103003086} > 01-22 13:35:22.439 16481 16481 I Gecko : -*- SettingsRequestManager: Replying getRequest for {12692ae5-cc6f-4a92-b100-0a6103003086} Then the one blocking shell.start(): > 01-22 13:35:19.479 16481 16481 I Gecko : -*- SettingsManager: get ({7c0850ca-d0af-4f65-a9fe-0e60887c3c2f}): language.current > 01-22 13:35:19.769 16481 16481 I Gecko : -*- SettingsRequestManager: Received getRequest from {7c0850ca-d0af-4f65-a9fe-0e60887c3c2f} > 01-22 13:35:22.479 16481 16481 I Gecko : -*- SettingsRequestManager: Running Get task on lock {7c0850ca-d0af-4f65-a9fe-0e60887c3c2f} > 01-22 13:35:22.489 16481 16481 I Gecko : -*- SettingsRequestManager: Replying getRequest for {7c0850ca-d0af-4f65-a9fe-0e60887c3c2f}

Looks like all the settings.js locks gets queued behind a lock from SettingsService.

Looks like the very first setting being used during boot is bluetooth.enabled, and it takes 5 secs just to get the |Settings:CreateLock| message sent from SettingsServiceLock and received by SettingsRequestManager: > 708 01-22 14:41:46.849 21387 21387 I Gecko : *** [PERF] SettingsRequestManager: SettingsServiceLock:sendAsyncMessage:{b3c9c95e-7596-488f-a2cc-41165b279541}: 62ms [...] > 1034 01-22 14:41:51.889 21387 21387 I Gecko : -*- SettingsRequestManager: receiveMessage Settings:CreateLock: {"lockID":"{b3c9c95e-7596-488f-a2cc-41165b279541}","isServiceLock":true,"lockStack":"SettingsServiceLock@jar:file:///system/b2g/omni.ja!/components/SettingsService.js:94:17\ncreateLock@jar:file:///system/b2g/omni.ja!/components/SettingsService.js:285:16\n"}

SettingsRequestManager installs message listeners: > 40 01-22 14:53:01.079 22770 22770 I Gecko : *** [PERF] SettingsRequestManager: init:messagelisteners: 39ms And then, SettingsServiceLock sends the |Settings:CreateLock| message: > 50 01-22 14:53:01.089 22770 22770 I Gecko : *** [PERF] SettingsRequestManager: SettingsServiceLock:sendAsyncMessage:{4fcd7d03-ca90-4b55-a59e-189d81a01e1d}: 62ms Which is received much later: > 373 01-22 14:53:05.559 22770 22770 I Gecko : -*- SettingsRequestManager: receiveMessage Settings:CreateLock: {"lockID":"{4fcd7d03-ca90-4b55-a59e-189d81a01e1d}","isServiceLock":true, [...]

More to corroborate: > 45 01-22 17:19:05.815 1118 1118 I Gecko : *** [PERF] SettingsRequestManager: SettingsServiceLock:init:{044d8b7a-c818-4d1a-967d-203e22c7b89d}: 60ms > 46 01-22 17:19:05.815 1118 1118 I Gecko : *** [PERF] SettingsRequestManager: SettingsServiceLock:bind:{044d8b7a-c818-4d1a-967d-203e22c7b89d}: 60ms > 47 01-22 17:19:05.815 1118 1118 I Gecko : *** [PERF] SettingsRequestManager: SettingsServiceLock:addMessageListener:{044d8b7a-c818-4d1a-967d-203e22c7b89d}: 61ms > 48 01-22 17:19:05.815 1118 1118 I Gecko : *** [PERF] SettingsRequestManager: SettingsServiceLock:payload:{044d8b7a-c818-4d1a-967d-203e22c7b89d}: 62ms > 49 01-22 17:19:05.815 1118 1118 I Gecko : nsFrameMessageManager::SendAsyncMessage: aMessageName=Settings:CreateLock > 50 01-22 17:19:05.815 1118 1118 I Gecko : *** [PERF] SettingsRequestManager: SettingsServiceLock:sendAsyncMessage:{044d8b7a-c818-4d1a-967d-203e22c7b89d}: 63ms > 51 01-22 17:19:05.815 1118 1118 I Gecko : *** [PERF] SettingsRequestManager: SettingsServiceLock:dispatch:{044d8b7a-c818-4d1a-967d-203e22c7b89d}: 65ms > 52 01-22 17:19:05.815 1118 1118 I Gecko : -*- SettingsService: Created lock {044d8b7a-c818-4d1a-967d-203e22c7b89d} > 53 01-22 17:19:05.815 1118 1118 I Gecko : -*- SettingsService: get ({044d8b7a-c818-4d1a-967d-203e22c7b89d}): bluetooth.enabled And then, 5 secs later: > 437 01-22 17:19:10.285 1118 1118 I Gecko : nsAsyncMessageToSameProcessParent::ReceiveMessage: aMessageName=Settings:CreateLock > 438 01-22 17:19:10.285 1118 1118 I Gecko : -*- SettingsRequestManager: receiveMessage Settings:CreateLock: {"lockID":"{044d8b7a-c818-4d1a-967d-203e22c7b89d}","isServiceLock":true,"lockStack":"SettingsServiceLock@jar:file:///system/b2g/omni.ja!/components/SettingsService.js:96:17\ncreateLock@jar:file:///system/b2g/omni.ja!/components/SettingsService.js:287:16\n"} So the delay is arelady in the C++ code nsFrameMessageManager::SendAsyncMessage/nsAsyncMessageToSameProcessParent::Run

Kyle, Ben, would you have any nice idea to help investigating why it takes 5 secs at this moment to deliver the async message ? My logs do not show other users of SendAsyncMessage at this point.

I wonder if there's some wait at startup before the message queue is serviced, because we don't expect to be receiving IPC messages that early in boot? The only reasons SettingsService calls SendAsyncMessage was just to make it consistent with SettingsManager, but it could be we need to directly wire it to SettingsRequestManager, since they're both in the parent process. This is a total shot in the dark though, I've done zero research.

Does the profiler show we're idle here? Otherwise it could just be that startup is a busy time...

(In reply to ben turner [:bent] (use the needinfo? flag!) from comment #7) > Does the profiler show we're idle here? Otherwise it could just be that > startup is a busy time... I have not been able to get something clear with the profiler for the whole boot phase. Is there some recommandation for using properly profile.sh for this usecase? Looking at logs with NSPR_LOG_MODULES="all:4" shows that the thread used by SettingsService and SettingsRequestManager is indeed quite busy.

Ok, so the current understanding of the issue is the following: - on boot, profile-after-change is triggered - this sets a number of services to start, BluetoothService being one of those - those services are making setting use via the SettingsService SettingsService communicates with SettingsRequestManager via async messages. During this boot phase, delivery of those takes a couple of seconds. While |Settings:CreateLock| is being in flight, it means: - SettingsRequestManager has not yet started it - any further .get()/.set() on the lock will be pending - any other lock will be made waiting until the first one is started (via |Settings:Run| message) The consequence of this is the following: - BluetoothService, WifiWorker, RadioInterfaceLayer (and maybe others) do query settings, quite early in the boot phase - there locks and queries are being put on hold in the queue - when shell.html and shell.js tries to query its needed values, it is being put at the end of this waiting list - given that we see a first delay of 5 secs for the very first |Settings:CreateLock| and then ~3 secs when shell tries to query, total boot time is probably delayed by ~6-8 secs ; those figures have been corroborated by :jlorenzo so far. At this point, the issue we want to fix is the following: avoiding a delay of 5 seconds. We want to do this, because this way, then we won't have a queue growing and putting latency on the shell.js startup. Based on this fact, and considering that for now SettingsService and SettingsRequestManager do live in the same process, I decided to make the communication more direct and avoiding sending/receiving async messages. So we export SettingsRequestManager object, make it used directly by SettingsService, and vice-versa. This proved to be fixing the first side of our issue: - SettingsService queries a |Settings:CreateLock|, and this is executed in sync (because of the direct call instead of async message) - then queuing the |get| task is also done instantly So, at this point, we have been able to reduce the latency and the call |gSettingsService.createLock().get("bluetooth.enabled")| takes ~10ms to complete queuing the "get" tasks in SettingsRequestManager, while this was above 5secs before. One tasks have been queued, SettingsRequestManager waits for either |Settings:Run| or |Settings:Finalize| message to trigger the execution of the task and return the values to the caller. This task is dependant on running the "closeHelper" bit of code living in SettingsServiceLock. This little helper is ran thanks to the following construction: > Services.tm.currentThread.dispatch(closeHelper, Ci.nsIThread.DISPATCH_NORMAL); During boot phase, and with the fix for async messages, we now see that the |closeHelper| gets executed 5-6 seconds after the task is queued.

And it looks like: > Services.tm.currentThread.dispatch(SettingsRequestManager.consumeTasks.bind(this), Ci.nsIThread.DISPATCH_NORMAL); in SettingsRequestManager also gets delayed at boot time.

So the CloseHelper is how we deal with waiting for the lock to scope out so we can act on it, and the dispatch for ConsumeTasks is so we spin between lock consumption and don't block the main thread for very long. I'm going to guess that the wait is due to bent's idea that startup is a very busy time and we're getting stuck on the end of the queue after a whole bunch of other startup tasks.

A few figures, to see how busy the system is. Original status: > alex@portable-alex:~/codaz/Mozilla/b2g/devices/Flame/B2G.KK$ egrep 'Starting bootanimation|settings.js: preload: |shell.js: start:|shell_start: ' settings-perfs4.log > 01-24 14:36:14.320 13538 13538 I : Starting bootanimation with (1) format framebuffer > 01-24 14:36:21.810 13538 13538 I GeckoDump: *** [PERF] settings.js: preload: 0ms > 01-24 14:36:22.180 13538 13538 I GeckoDump: *** [PERF] shell.js: start: 0ms > 01-24 14:36:25.520 13538 13538 I GeckoDump: *** [PERF] shell.js: shell_start: 3340ms So that's ~11.2s Direct communication between SettingsService and SettingsRequestManager, current startup code with settings.js triggering shell.start(): > alex@portable-alex:~/codaz/Mozilla/b2g/devices/Flame/B2G.KK$ egrep 'Starting bootanimation|settings.js: preload: |shell.js: start:|shell_start: ' settings-perfs4.log > 01-24 14:22:55.320 12120 12120 I : Starting bootanimation with (1) format framebuffer > 01-24 14:23:00.700 12120 12120 I GeckoDump: *** [PERF] settings.js: preload: 0ms > 01-24 14:23:01.060 12120 12120 I GeckoDump: *** [PERF] shell.js: start: 0ms > 01-24 14:23:04.150 12120 12120 I GeckoDump: *** [PERF] shell.js: shell_start: 3087ms So that's ~8.8s Direct communication between SettingsService and SettingsRequestManager, hacked startup code with addEventListener('load') triggering shell.start() in shell.js: > alex@portable-alex:~/codaz/Mozilla/b2g/devices/Flame/B2G.KK$ egrep 'Starting bootanimation|settings.js: preload: |shell.js: start:|shell_start: ' settings-perfs4.log > 01-24 14:28:51.620 12807 12807 I : Starting bootanimation with (1) format framebuffer > 01-24 14:28:57.920 12807 12807 I GeckoDump: *** [PERF] settings.js: preload: 0ms > 01-24 14:28:58.290 12807 12807 I GeckoDump: *** [PERF] shell.js: start: 0ms > 01-24 14:28:59.170 12807 12807 I GeckoDump: *** [PERF] shell.js: shell_start: 877ms So that's ~7.55s

This patch allows for measuring boot time, settings activity/lock ups and contains the hacks to go down from ~11.2s to ~7.55s for calling shell.start()

Updated attachment 8554162 [details] [diff] [review] on top of current master