Closed Bug 812059 Opened 8 years ago Closed 6 years ago

Incoming calls take a long time to display

Categories

(Firefox OS Graveyard :: General, defect, P2)

ARM
Gonk (Firefox OS)
defect

Tracking

(Not tracked)

RESOLVED DUPLICATE of bug 990003
1.4 S6 (25apr)

People

(Reporter: philikon, Unassigned)

References

Details

(Keywords: perf, Whiteboard: [c=progress p= s=2014.04.25 u=])

Attachments

(1 obsolete file)

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().
Depends on: 809670
Depends on: 812368
Attachment #683030 - Flags: review?(dhylands)
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 :-(
Attachment #683030 - Attachment is obsolete: true
Attachment #683030 - Flags: review?(dhylands)
Depends on: 817052
Depends on: 822722
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.
Whiteboard: [perf_tsk]
Whiteboard: [perf_tsk] → [FFOS_perf]
Lots of code has changed in the last weeks. We should get new numbers here.
Jon will take a look.
Assignee: nobody → jhylands
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.
Keywords: perf
Thanks Jon!
So the total time is now 871 msec?
Lucas, is this good enough?
Flags: needinfo?(ladamski)
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).
Flags: needinfo?(ladamski) → needinfo?(jcarpenter)
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.
Flags: needinfo?(jcarpenter)
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
Keywords: qawanted
Whiteboard: [FFOS_perf] → [FFOS_perf] c=
Jon, all the dependent bugs are fixed but we're still seeing the delay. Any other ideas of what to do here next?
Flags: needinfo?(jhylands)
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?
Flags: needinfo?(jhylands)
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
Status: NEW → ASSIGNED
Depends on: 873284
Assignee: jhylands → nobody
Status: ASSIGNED → NEW
Whiteboard: [FFOS_perf] c= → [c= ]
Whiteboard: [c= ] → [c= p= s= u=]
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.
Keywords: meta
Summary: [meta] Incoming calls take a long time to display → Incoming calls take a long time to display
Whiteboard: [c= p= s= u=] → [c= ]
Clobbered the whiteboard change by mistake. Restoring.
Whiteboard: [c= ] → [c= p= s= u=]
Depends on: 990003
No longer depends on: 990003
See Also: → 990003
Etienne, does your fix for Bug 990003 also address this bug?
Flags: needinfo?(etienne)
(In reply to Jean Gong from comment #24)
> Etienne, does your fix for Bug 990003 also address this bug?

I think it does yes :)
Flags: needinfo?(etienne)
Etienne,

Is your fix for bug 990003 Tarako-only or will it land on 1.4 and 2.0 as well?
Flags: needinfo?(etienne)
Priority: -- → P2
Whiteboard: [c= p= s= u=] → [c=progress p= s= u=]
(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.
Flags: needinfo?(etienne)
Duping against bug 990003 per Etienne's comment 26 and comment 27.
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → DUPLICATE
Whiteboard: [c=progress p= s= u=] → [c=progress p= s=2014.04.25 u=]
Target Milestone: --- → 1.4 S6 (25apr)
Duplicate of bug: 990003
You need to log in before you can comment on or make changes to this bug.