It takes a really long time (~3s) for the on-call screen to come up when an incoming call is registered. There's several things at play here, so this is mostly a highlevel description of what's going on and a meta bug for individual fixes in both Gecko and Gaia. An incoming call is first registered by the RIL worker thread. Then the RadioInterfaceLayer component on the main thread is notified which in turn sends off a system message into Gaia land: 11-14 18:41:53.651 106 227 I Gecko : RIL Worker: Handling parcel as UNSOLICITED_CALL_RING 11-14 18:41:54.322 106 227 I Gecko : RIL Worker: Handling parcel as UNSOLICITED_RESPONSE_CALL_STATE_CHANGED 11-14 18:41:54.332 106 227 I Gecko : RIL Worker: Handling parcel as REQUEST_GET_CURRENT_CALLS 11-14 18:41:54.342 106 106 I Gecko : -*- RadioInterfaceLayer: Received message from worker: {"rilMessageType":"callStateChange",... 11-14 18:41:54.342 106 106 I Gecko : -- SystemMessageInternal 1352947314351 : Broadcasting telephony-new-call {"number":"4155256471","state":11} 11-14 18:41:54.552 106 106 I Gecko : -- SystemMessageInternal 1352947314567 : Asking to open {"uri":"app://communications.gaiamobile.org/dialer/index.html#keyboard-view","manifest":"app://communications.gaiamobile.org/manifest.webapp","type":"telephony-new-call"} 11-14 18:41:54.562 106 106 I GeckoDump: shell.js: sendSystemMessage {"uri":"app://communications.gaiamobile.org/dialer/index.html#keyboard-view","manifest":"app://communications.gaiamobile.org/manifest.webapp","type":"telephony-new-call"} 11-14 18:41:54.642 106 106 E GeckoConsole: Content JS LOG at app://system.gaiamobile.org/js/window_manager.js:1123 in anonymous: window_manager.js: received open-app event {"type":"open-app","url":"app://communications.gaiamobile.org/dialer/index.html#keyboard-view","manifestURL":"app://communications.gaiamobile.org/manifest.webapp","isActivity":false} 11-14 18:41:54.642 106 106 E GeckoConsole: Content JS INFO at app://system.gaiamobile.org/js/window_manager.js:927 in createFrame: %%%%% Launching Phone as remote (OOP) It takes ~1s for Gecko from first being notified by the RIL daemon about an incoming call to triggering the event in in-process content (the system app)! Some areas for further analysis: * ~300-500ms are "wasted" because we don't actually respond to the UNSOLICITED_CALL_RING parcel. We wait until we have processed REQUEST_GET_CURRENT_CALLS and then detect there are new calls. We should consider adding a shortcut from the RIL worker's UNSOLICITED_CALL_RING handler straight to the 'telephony-new-call' message. We would not be able to notify the number yet at that point, but I don't think that's really necessary. We just want to start bringing up the dialer content process while the modem is getting ready to tell us more. * ~200ms are spent between broadcasting the system message and opening the handler. We should profile that part of the code to see if we can optimize it. We now bring up the dialer content process which takes another ~1.5s until the content is loaded, the top-level JS is executed, and the system message is received. 11-14 18:41:54.793 395 395 I Gecko : ###################################### forms.js loaded 11-14 18:41:55.323 395 395 E GeckoConsole: Content JS LOG at app://communications.gaiamobile.org/dialer/index.html#keyboard-view:22 in anonymous: dialer index.html 11-14 18:41:55.603 395 395 I Gecko : -*- RILContentHelper: Requesting enumeration of calls for callback: [xpconnect wrapped nsIRILTelephonyCallback] 11-14 18:41:55.613 106 227 I Gecko : RIL Worker: Received DOM message {"requestId":"{8a6fe244-885a-4639-b7a0-40f9e066dc40}","rilMessageType":"enumerateCalls"} 11-14 18:41:55.613 106 227 I Gecko : RIL Worker: Sending all current calls 11-14 18:41:55.613 106 106 I Gecko : -*- RadioInterfaceLayer: Received message from worker: {"requestId":"{8a6fe244-885a-4639-b7a0-40f9e066dc40}","rilMessageType":"enumerateCalls","calls":[{"state":4,"callIndex":1,"toa":129,"isMpty":false,"isMT":true,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"4155256471","numberPresentation":0,"name":"","namePresentation":0,"uusInfo":null,"isActive":false}]} 11-14 18:41:55.613 106 106 I Gecko : RadioInterfaceLayer.js: received enumerate calls result from worker. 11-14 18:41:55.954 395 395 I Gecko : -*- RILContentHelper: Received message 'RIL:EnumerateCalls': {"requestId":"{8a6fe244-885a-4639-b7a0-40f9e066dc40}","rilMessageType":"enumerateCalls","calls":[{"state":11,"callIndex":1,"toa":129,"isMpty":false,"isMT":true,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"4155256471","numberPresentation":0,"name":"","namePresentation":0,"uusInfo":null,"isActive":false}]} 11-14 18:41:55.964 395 395 I Gecko : -- SystemMessageManager 1352947315969 : receiveMessage SystemMessageManager:GetPendingMessages:Return - telephony-new-call for app://communications.gaiamobile.org/manifest.webapp (app://communications.gaiamobile.org/manifest.webapp) 11-14 18:41:55.964 395 395 I Gecko : -- SystemMessageManager 1352947315970 : Dispatching {"number":"4155256471","state":11} Some areas for investigation here: * Why is "forms.js" not already loaded in the pre-allocated process? * What are we spending the ~0.5s until top-level JS ("dialer index.html" log messages) executes on? Presumably loading HTML/CS/JS. We should see if we can cut this down. * The system message dispatched *after* all the top-level content JS has run (so that the JS has time to set up event handlers and such). But it takes 300ms! That's a lot, we should investigate what it spends that time on and see if we can optimize some stuff there. I will look into the aforementioned points and file individual bugs once I know more. If anybody else finds anything peculiar, please file rigorously.

Lots of similar issues have been investigated at Bug 804707. Due to some RIL wakelock issues, actually we would have another worse situation which takes even 9 seconds to pop up the oncall page after receiving the incoming call message: 1. If the device is not on power. 2. The screen is off. 3. The Dialer App is not yet launched The .broadcastMessage() in the system message mechanism is using linear search to decide which page(s) to open. I guess we can have some improvements there (like hashing) to speed up the system message routing algorithm. I might be able to support that part.

(In reply to Gene Lian [:gene] from comment #1) > The .broadcastMessage() in the system message mechanism is using linear > search to decide which page(s) to open. I guess we can have some > improvements there (like hashing) to speed up the system message routing > algorithm. I might be able to support that part. Fire Bug 812080 to keep track of whether we could speed up the ~200ms process of .broadcastMessage().

Pointer to Github pull-request

Comment on attachment 683030 [details] Pointer to Github pull request: https://github.com/mozilla-b2g/B2G/pull/174 Please disregard the last comments, I got the wrong bug in my log entry and noticed it only after having had this entry automatically created, sorry for the inconvenience :-(

Just leaving a note to update the current performance. With the patches recently landed at bug 812368 and bug 830425: - The home screen can wake up very fast before hearing the first "doo-doo" sound. - The Dialer app can then come up exactly at the end of the first "doo-doo" sound. Again, the above test is conducted based on the worse case: - Unplug the USB line. - Dialer app is not launched. - Turn-off the screen. If either one condition is not satisfied, then the Dialer app can even come up earlier within the time period of the first "doo-doo" sound.

Lots of code has changed in the last weeks. We should get new numbers here. Jon will take a look.

Current log looks like this: 10:32:33.350 105/247 Gecko I RIL Worker: Handling parcel as UNSOLICITED_CALL_RING 10:32:33.370 105/105 Gecko I -- SystemMessageInternal 1359646353381 : Broadcasting telephony-new-call {} 10:32:33.380 105/105 Gecko I -- SystemMessageInternal 1359646353394 : Asking to open {"uri":"app://communications.gaiamobile.org/dialer/index.html#keyboard-view","manifest":"app://communications.gaiamobile.org/manifest.webapp","type":"telephony-new-call"} 10:32:33.400 105/105 GeckoDump I %%%%% Launching Phone as remote (OOP) 10:32:33.560 418/418 Gecko I ###################################### forms.js loaded 10:32:33.930 105/247 Gecko I RIL Worker: Handling parcel as UNSOLICITED_RESPONSE_CALL_STATE_CHANGED 10:32:33.930 105/247 Gecko I RIL Worker: Handling parcel as REQUEST_GET_CURRENT_CALLS 10:32:33.940 105/105 Gecko I -*- RILContentHelper: Received message 'RIL:CallStateChanged': {"state":11,"callIndex":1,"toa":145,"isMpty":false,"isMT":true,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"+15194463701","numberPresentation":0,"name":"","namePresentation":0,"uusInfo":null,"direction":"incoming","isActive":false} 10:32:34.271 105/105 Gecko I -- SystemMessageInternal 1359646354281 : received SystemMessageManager:GetPendingMessages telephony-new-call for app://communications.gaiamobile.org/dialer/index.html#keyboard-view @ app://communications.gaiamobile.org/manifest.webapp The broadcast now happens immediately after the UNSOLICITED_CALL_RING, and the handler opens pretty much immediately. The time from the UNSOLICITED_CALL_RING to the form.js loading has gone down from over 1 second to 210 ms. Time for the dialer to open, and the system message being received has dropped from over 1 second to 871 ms. This doesn't seem like much, but we're opening the dialer much earlier in the process now. Note that the time from REQUEST_GET_CURRENT_CALLS to the system message being received is now ~330 ms, and it used to be 1.6 seconds. From a strictly user perspective, the phone feels reasonably responsive when I call it.

Thanks Jon! So the total time is now 871 msec? Lucas, is this good enough?

It sounds much better to me than 3sec but I'm adding Josh as I think UX is ultimately the best arbiter of a good experience here (barring explicit partner requirements).

We do not yet have specific target numbers for Dialer-open-on-incoming-call, but +3 seconds down to .871 is a obviously a big improvement. Let's see what partners say. We're working on generating our own internal numbers, but that's a ways off still.

Tested on a Unagi Device, Build Id: 20130204070202 Git Commit Info : 2013-02-01 13:43:40 , 04e3e923bdae0773b0133ffa4958831... (did an update over the air) Not able to reproduce the issue - Tried calling my Unagi device with a At &T connection from another phone. Incoming calls are displayed immediately on the screen, like every other phone does.

Partner acceptance is 1-2s max in all scenarios. Is that the case? Can we close this now?

See https://bugzilla.mozilla.org/show_bug.cgi?id=847592#c0 Partners are saying between 2-4s for incoming call handling under load.

This issue still reproducing. Incoming calls take a few seconds to display on the Unagi and the Inari. Unagi Build ID: 20130502070205 Kernel Date: Dec 5 Gecko: http://hg.mozilla.org/releases/mozilla-b2g18/rev/499c3627e89a Gaia: 495c46489eb256be598a19ea54d7837ce4fc385b Inari Build ID: 20130502070201 Kernel Date: Feb 21 Gecko: http://hg.mozilla.org/releases/mozilla-b2g18_v1_0_1/rev/5c1d67e0c242 Gaia: 11477c127ae9be5051e4cfbcbf3da1d4150f9967

Jon, all the dependent bugs are fixed but we're still seeing the delay. Any other ideas of what to do here next?

I can't reproduce this. I did a refresh to get the latest b2g18/v1-train, rebuilt it, flashed my unagi, and then called it. The dialer shows up and starts ringing pretty much the instant I hear the ringing start on my calling phone. That message from Angela is over a month old - perhaps they should update and try again?

I am still seeing calls coming in a little delayed but not as delayed as they were a month ago. Here is a video using the latest v1 build on the Unagi device. http://youtu.be/wZ0d_U-IuGM Unagi Build ID: 20130610230207 Gecko: http://hg.mozilla.org/releases/mozilla-b2g18/rev/78de618c071a Gaia: ea18de80fd04110756becaed214656642388401d Platform Version: 18.0

Angela - I can't tell from your video whether the unagi on the left is taking too long to answer, or the one on the right is taking too long to call. How specifically are you differentiating between these two? Certainly there will be some delay as the call is routed. I use my Android (Nexus 4) phone to initiate the call, so I know if there is a delay it is caused by the unagi.

Jon, I was trying to show the delayed display of the incoming call on the left Unagi. At first the screen lights up, then it gets the blue strip, and then it displays the number inside the blue strip. I was seeing the same thing when calling from my personal Android device.

Okay, I see what you're saying. Doing it the other way around (calling my Android phone from my unagi), there is no delay on my Android phone between the screen lighting up and the call starting to ring. I made a video of calling my unagi, and I'm seeing just under a second delay from that, which more or less jives with what Gregor said in comment 8 above. Is this no longer acceptable?

Actually, to be more specific (all times below are from my video, which can be found here: https://www.dropbox.com/s/qvc5v2p6o19qewf/M2U00858.MPG): 8.60 - button lights come on 9.40 - screen comes on 10.37 - blue bar shows up 10.78 - caller name shows up - Jon

Removing the meta designator. While this has a bunch of dependencies, it's describing a concrete defect (delayed call notification) that just happens to have a bunch of moving parts. I'm afraid if we categorize this as a meta and only focus (i.e. block) on the dependencies we'll lose sight of whether the externally-visible issue, the call delay, is a blocker.

Clobbered the whiteboard change by mistake. Restoring.

Etienne, does your fix for Bug 990003 also address this bug?

(In reply to Jean Gong from comment #24) > Etienne, does your fix for Bug 990003 also address this bug? I think it does yes :)

Etienne, Is your fix for bug 990003 Tarako-only or will it land on 1.4 and 2.0 as well?

(In reply to Mike Lee [:mlee] from comment #26) > Etienne, > > Is your fix for bug 990003 Tarako-only or will it land on 1.4 and 2.0 as > well? It landed on master, then 1.3t. Definitely not tarako only, feel free to ask for uplift on any branch where it's required, I can help with merge conflicts.

Duping against bug 990003 per Etienne's comment 26 and comment 27.