Closed Bug 973596 Opened 6 years ago Closed 6 years ago

[tarako] ringtone takes too long to start when playing music in background

Categories

(Firefox OS Graveyard :: Gaia::Ringtones, defect, P1, blocker)

ARM
Gonk (Firefox OS)
defect

Tracking

(blocking-b2g:1.3T+, b2g-v1.3T ?)

RESOLVED DUPLICATE of bug 990003
1.4 S6 (25apr)
blocking-b2g 1.3T+
Tracking Status
b2g-v1.3T --- ?

People

(Reporter: kk1fff, Assigned: kk1fff)

References

Details

(Keywords: perf, Whiteboard: [c=progress p= s= u=tarako] eta:4/11)

Attachments

(4 files, 4 obsolete files)

When making a phone call to tarako, caller needs to wait about 4~5 ringtones before tarako start to ring if the tarako is playing musics in background.
We did some test and observed:

1. When RIL receives a call state change, it takes 700 ms-1.5 sec to start to launch communication app.
2. After communication app started, it takes about 1 sec to finish loading first page. In the first page, communication app handle system message and find there is a phone call, so it load oncall.html in a new window.
3. oncall.html gets ringtone and volume from settings, and check telephony object for current call state. It takes about 3 seconds before it get current state, then start to handle the incoming call.
4. after about 1 sec, settings value is returned in callback, and ringtone starts.

Loading the second window takes much time. And we tried loading ringtone in the first page, with preallocated process ready, the callee ringtone can start after 1~3 ringtones on caller side.
Fabrice was working on a patch to run the dialer in the main process which helped a lot here.
We probably want to fix bug 873284 for this too. That bug was originally filed precisely for this kind of issues. I'll refresh the patch there as it's bit-rotted.
Depends on: 959966
I think tuning communication app is also worth to try, thus we can keep communication app oop.
Attached patch 0001-ringtone-test.patch (obsolete) — Splinter Review
Hi Etienne, it's a test WIP that move ringtone and vibrate related logic from oncall to dialler directly. Do you think it's feasible to take this changes? It seems risky to derive the ringtone/vibrate logic from call screen.
Besides of that, it still has a bug that settings_url.js could not be loaded in LazyLoader and we could not get phoneSoundURL in the patch... If you feel ok to give this patch a try, do you have any idea about the timing for loading settings_url? Thanks.
Attachment #8377565 - Flags: feedback?(etienne)
Attached patch 0001-ringtone-test.patch (obsolete) — Splinter Review
settings_url seems not available for lazyload, so I move it to html part for testing.
Hi Patrick, here is the WIP patch that will trigger the ringtone before opening the call screen. The vibration part has some problem but ringtone is working, thanks.
Attachment #8377565 - Attachment is obsolete: true
Attachment #8377565 - Flags: feedback?(etienne)
Attachment #8377996 - Flags: feedback?(pwang)
Attached patch Rebased on 1.3t (obsolete) — Splinter Review
(In reply to Patrick Wang (Chih-Kai Wang) (:kk1fff) from comment #7)
> Created attachment 8378120 [details] [diff] [review]
> Rebased on 1.3t

Note that I moved openCallScreen() to the line after handleFirstIncoming(), so ringtone can start before attempting to open a new window.
Comment on attachment 8377996 [details] [diff] [review]
0001-ringtone-test.patch

Review of attachment 8377996 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks, Steve. This does help. In my local test, with this patch, tarako can start to ring within 2-3 ringtones on caller side.
Attachment #8377996 - Flags: feedback?(pwang) → feedback+
Comment on attachment 8378120 [details] [diff] [review]
Rebased on 1.3t

Review of attachment 8378120 [details] [diff] [review]:
-----------------------------------------------------------------

Sorry I missed the feedback for Etienne.
Hi Etienne, this patch is our quick test patch that move all the ringtone/vibrate logic from call screen to dialer call handler(before opening call screen). The performance of the screen opening should be improved for the best case, but we might still need a backup solution in gaia dialer side. Do you think moving the ringtone play timing is a feasible solution here, or it might cause side effect which could not be fixed easily ?
Attachment #8378120 - Flags: feedback?(etienne)
blocking-b2g: --- → 1.3T?
Comment on attachment 8378120 [details] [diff] [review]
Rebased on 1.3t

Review of attachment 8378120 [details] [diff] [review]:
-----------------------------------------------------------------

feeback- because of the lack of consideration for outgoing calls.

But I don't think this approach is going to work, in order to vibrate we need our document to be visible.
The main app window's document *isn't* when the app is in background. And even if the app is in foreground, when the call screen comes in it will hide the main app window and stop the vibration.

So without gecko a change, the vibration needs to happen in the call screen. And I feel pretty strongly that ringing and vibrating should be handled in the same place.

Sorry :/

::: apps/communications/dialer/js/dialer.js
@@ +173,5 @@
>      telephony.oncallschanged = function dialer_oncallschanged(evt) {
>        if (telephony.calls.length !== 0) {
>          openCallScreen();
> +        if (telephony.calls.length === 1) {
> +          handleFirstIncoming(telephony.calls[0]);

you did not check that this was an incoming call...
We don't want to to ring/vibrate on outgoing calls :)
Attachment #8378120 - Flags: feedback?(etienne) → feedback-
Thanks for the feedback and reminder. I know I ignore some scenario jsut for ringtone work, but default vibration behavior[1] make this patch not possible to be applied. I agree ringtone and vibration should be handled in the same place, and I see not much benifit but regression if we change the vibration behavior for futher workaround.

[1] http://dxr.mozilla.org/mozilla-central/source/dom/base/Navigator.cpp#729
(In reply to Steve Chung [:steveck] from comment #12)
> Thanks for the feedback and reminder. I know I ignore some scenario jsut for
> ringtone work, but default vibration behavior[1] make this patch not
> possible to be applied. I agree ringtone and vibration should be handled in
> the same place, and I see not much benifit but regression if we change the
> vibration behavior for futher workaround.

I don't think we should change the behavior of vibration, either.

I've tried preloading another tab to shorten latency of opening oncalls.html, but it doesn't seem help much.
(In reply to Patrick Wang (Chih-Kai Wang) (:kk1fff) from comment #13)
> (In reply to Steve Chung [:steveck] from comment #12)
> > Thanks for the feedback and reminder. I know I ignore some scenario jsut for
> > ringtone work, but default vibration behavior[1] make this patch not
> > possible to be applied. I agree ringtone and vibration should be handled in
> > the same place, and I see not much benifit but regression if we change the
> > vibration behavior for futher workaround.
> 
> I don't think we should change the behavior of vibration, either.
> 
> I've tried preloading another tab to shorten latency of opening
> oncalls.html, but it doesn't seem help much.

We worked a lot on making index.html load fast in the past, but never looked at oncall.html.
We could probably do the same kind of work (lazy loading...) to help on the gaia side.

Let us know if we need to prioritize that.
(In reply to Etienne Segonzac (:etienne) from comment #14)
> We worked a lot on making index.html load fast in the past, but never looked
> at oncall.html.
> We could probably do the same kind of work (lazy loading...) to help on the
> gaia side.
> 
> Let us know if we need to prioritize that.

Thanks, Etienne! It would be good if you can prioritize that. We will need improve the ringtone latency for 1.3T.
Summary: [tarako] ringtone takes too long to start → [tarako] ringtone takes too long to start when playing music in background
I used boot image from today's QA build, now the callee ringtone can start in 2-3 ringtones.
Made some good progress, will have patches tomorrow.
But note that I'm working on the call screen load time itself, nothing related to the audio channels when having a music in the background. We should probably use separate bugs.
triage: 1.3T+, this is needed for tarako
blocking-b2g: 1.3T? → 1.3T+
Depends on: 979406
Depends on: 979419
Depends on: 979426
I found 3 ways to make the performance better on the gaia side and filed corresponding bugs.

We should see it as a buffet, and land/uplift only the ones to our taste in term of gain/risk :)

* bug 979406 is really simple and not risky at all, for a ~600ms gain
* bug 979419 will be a bigger patch, risky but manageable, for a ~300ms gain on a keon (probably a bit more on a tarako)
* bug 979426 will probably be too risky anyway for an uplift, it's here for investigation, we're probably looking at a ~300ms gain here too
Thanks! Etienne! I will run task tracer to see how we can improve from Gecko.
Flags: needinfo?(ttsai)
Waiting for dependencies to resolve.
Duplicate of this bug: 964606
Update the test result on different kernel build, I record the ringtone 5 times in each build.
1. kernel image on 3/4, commit d55a299649ea077e33cfb9d620ee06819829b9ee
 - The ringtone of tarake (MT) start after 3~4 ringtone of MO device
2. kernel image on 2/25, commit d497083f59b47819c397d3476da3f03d5631f7e8
 - The ringtone of tarake (MT) start after 3~4 ringtone of MO device
3. kernel image on 2/19, commit 2cda7841ce0c4c4d31ef374edbd868c8add6d774
 - The ringtone of tarake (MT) start after 3~4 ringtone of MO device

We also review the kernel change list, and didn't find any change will cause performance improvement recently.

With kernel review and test result, we can confirm there is no improvement in kernel side.

SW version:
Gecko: 0d688e9bda743e80d735b43c4a4c8e205b2e5100
Gaia: d9907660806748c5c06c95b097de2d7b1fc118d8
Flags: needinfo?(ttsai)
Attached the test image I used
Whiteboard: [SI-testing-blocker]
I did some experiment on killing/suspending other apps during incoming call and measure the time cost from RIL gets call state change to ringtone start. I did each test 5 times, each time I kill comms app and go back to homescreen, then turn the screen off. Here's the average values.

1. Killing all apps (include music app) when receiving a call: 3.7592
2. Killing all apps that not holding audio channel: 4.5144
3. Suspend (SIGSTOP) all apps: 5.9012
4. Change OOM_ADJ to get more memory (1024,1280,1536,4096,5120,6144): 9.4994
5. Don't do anything: 4.6736 (about 2 ringback tones)

As the result suggests, the ringtone starts slowly when memory is not enough, even other apps are not competing for CPU.
Depends on: 980984
We're changing strategy on the gaia side.

We discussed it a lot with Vivien, and vibrating/ringing from the system app is less risky and yields *way* better results.

I'll close bug 979419 and bug 979426 in favor of bug 980984.
Component: General → Gaia::Ringtones
patrick, seems like you have been working on this. assign this to you for now. please reassign if you are not working on this. thanks
Assignee: nobody → pwang
I tried patch for bug 980984 on tarako, the ringtone starts almost the same time as ringback starts.
Patrick, do you mind providing some update on this bug? thanks
Flags: needinfo?(pwang)
As test in comment 25, it appears that we need to kill music app for launching dialer faster. We will try  to kill music when it affects performance too much (or some import event, like incoming call, is fired), and resume the music app after phone call.

It needs some changes in system app and music app to save the position where music app is playing before it is killed, and relaunch music app and continue to play music after end of phone call.
Flags: needinfo?(pwang)
Could you find some one to handle this?  Store states of playing music before being killed.
Flags: needinfo?(timdream)
Patrick?Thinker, bug 980984 is not enough to improve the situation? It has not been uplifted yet.
(In reply to Fabrice Desré [:fabrice] from comment #33)
> Patrick?Thinker, bug 980984 is not enough to improve the situation? It has
> not been uplifted yet.

I have made a rebased version and tried the patch locally. With it, ringtone does start earlier a lot. But UI of answering call still need several rings to show, we need to improve that to make user able to answer/decline the call earlier.
Ok. Reading this bug again, Gabriele has a patch in bug 873284 that could help and never landed. I'd like to not have to kill the music player or run the dialer in-process...
(In reply to Thinker Li [:sinker] from comment #32)
> Could you find some one to handle this?  Store states of playing music
> before being killed.

Please ping me again, and :hema and dkuo if this is what we want to do.
Flags: needinfo?(timdream)
Depends on: 983476
Gabriele, do you think bug 873284 will help? if so, lets try to get it landed. thanks
Flags: needinfo?(gsvelto)
It could be useful if we're triggering that condition. I'm not clearing the needinfo flag because I want to test it tomorrow and see if it helps. One of the reasons why my patch never landed is that it lacks unit tests so I'll try to put those together if it turns out to be useful.
I've tried the patch. It doesn't seem help, since memory pressure is not triggered when receiving a call with music in background.
the team is going to try https://bugzilla.mozilla.org/show_bug.cgi?id=983541#c15 first to see if it helps with this bug
I've tried the patch, it saves about 1 MB (10MB USS -> 8.7MB USS) of RAM. However, UI of answering call doesn't show up sooner. It takes about 8.5 seconds to show, the value is almost the same as how it takes without the patch.

I did some tests to see how long it takes from RIL received call state change to UI is displayed, here's the result:

1. Not playing music, screen off: 4.75 sec
2. playing music in background, screen off: 8.10 sec
3. playing music in background and kill music app when phone call incoming, screen off: 4.92 sec
Attachment #8377996 - Attachment is obsolete: true
Attachment #8378120 - Attachment is obsolete: true
Log timestamp of receving call state change.
If communication app is always in the background as a content process, dailer UI can respond to MT call after a ring tone.
(In reply to Patrick Wang (Chih-Kai Wang) (:kk1fff) from comment #41)
> 
> 1. Not playing music, screen off: 4.75 sec
> 2. playing music in background, screen off: 8.10 sec
> 3. playing music in background and kill music app when phone call incoming,
> screen off: 4.92 sec

3. playing music in background and kill music app when phone call incoming, screen off: 4.92 sec
I'd like to explore this option for lower end devices if we don't get much further on this. ni? product
Flags: needinfo?(gsvelto) → needinfo?(mkhoo)
also Steven for comment 46
Flags: needinfo?(styang)
See Also: → 983476
Whatever happened to running the dialer in the parent process?
Flags: needinfo?(fabrice)
(In reply to Kyle Huey [:khuey] (khuey@mozilla.com) from comment #48)
> Whatever happened to running the dialer in the parent process?

That would be fine if we could run only the dialer. But it's part of the communication app, and as such also runs the contacts app that import 3rd party contacts. So that would be a last resort solution.
Flags: needinfo?(fabrice)
(In reply to Joe Cheng [:jcheng] from comment #46)
> (In reply to Patrick Wang (Chih-Kai Wang) (:kk1fff) from comment #41)
> > 
> > 1. Not playing music, screen off: 4.75 sec
> > 2. playing music in background, screen off: 8.10 sec
> > 3. playing music in background and kill music app when phone call incoming,
> > screen off: 4.92 sec
> 
> 3. playing music in background and kill music app when phone call incoming,
> screen off: 4.92 sec
> I'd like to explore this option for lower end devices if we don't get much
> further on this. ni? product

It's the fundamental requirement. I'm afraid it's not an option for our partner.
Flags: needinfo?(styang)
Another option is that we can play music in system app. I tried playing music in system app, the UI displays after 3~4 seconds (1 ~ 1.5 ringbacks), which is almost the same as not playing music in background.

To play music in system app, we can turn music app into a "controller" which tells system app how to play the music through IAC. When the call is coming, we simply kill all of the apps to release the memory, to make dialer launch sooner. After call ends, system app resumes the music and launches music app, and music app can get necessary info from system and prepare UI in background.
(In reply to Patrick Wang (Chih-Kai Wang) (:kk1fff) from comment #51)
> Another option is that we can play music in system app. I tried playing
> music in system app, the UI displays after 3~4 seconds (1 ~ 1.5 ringbacks),
> which is almost the same as not playing music in background.
> 
> To play music in system app, we can turn music app into a "controller" which
> tells system app how to play the music through IAC. When the call is coming,
> we simply kill all of the apps to release the memory, to make dialer launch
> sooner. After call ends, system app resumes the music and launches music
> app, and music app can get necessary info from system and prepare UI in
> background.

Thanks Patrick, looks like if we put the audio element in system and use it to play the music, not only gets better launch time for the dialer ui, but also saves memory during the call, though these will need extra works to move the audio element from music to system, then communicates with each other via IAC. But since this should be the most workable solution on tarako for now, let's use this approach and I am going to implement in bug 987022.
Depends on: 987022
Whiteboard: [SI-testing-blocker] → [SI-testing-blocker][priority]
As this is fundamental req, keep monitor if 987022 improves here and discuss further actions if needed.
adding Ravi into this bug.
Flags: needinfo?(mkhoo)
Observe of the difference between playing music and not playing music:

playing music:

ring: 5.986

system
user:     44.07% 3.53 sec
sys:      40.70% 3.26 sec
nice:     2.12%
idle:     13.11%
iowait:   0.00%
irq:      0.00%
sirq:     0.00%
pgin:     4397
pgout:    10110
swpin:    1067
swpout:   2471

b2g(81)
majflt:   508
minflt:   6704
utime:    1.29 secs
stime:    0.71 secs

comms(12061)
majflt:   518
minflt:   10308
utime:    2.07 secs
stime:    1.04 secs

not playing music:

ring: 3.998

system
user:     54.05% 3.0 sec
sys:      31.17% 1.73 sec
nice:     0.00%
idle:     14.77%
iowait:   0.00%
irq:      0.00%
sirq:     0.00%
pgin:     245
pgout:    477
swpin:    61
swpout:   78

b2g(81)
majflt:   24
minflt:   2918
utime:    0.89 secs
stime:    0.28 secs

comms(11652)
majflt:   85
minflt:   7841
utime:    2.1 secs
stime:    0.65 secs

Note the idle time is from the value before ringtone start, there is a short period between last sample and actual start time of ringtone. And there are some other processes (slog and logcat) which compete for cpu time, this experiment is done when those processes are killed.
Measure time of launching dialer, majflt/minflt of dialer and b2g during this period and stime/utime of all processes on the phone.
Attachment #8393434 - Attachment is obsolete: true
In some case, I found that a process slog takes about 4 secs system time during incoming call. With this process suspended, the launch time of incoming call screen from 9 secs to 4 secs. The process doesn't present in unagi, is this a devices specific process? and what is this for?
Flags: needinfo?(james.zhang)
Slog is in spreadtrum userdebug build, for filed test and catch adb log.
You can try user build, it hasn't slog process.
Flags: needinfo?(james.zhang)
Severity: normal → blocker
Priority: -- → P1
We have tested WIP patch for bug 987022. It improves the launch time of comms app when playing music background. However, if home screen restarts before comms app, it would slow down the launching of comms app. We will need to prevent home screen from being restarted before comms app launch.
Whiteboard: [SI-testing-blocker][priority] → [SI-testing-blocker][priority][MP_Blocker]
Depends on: 992759
Whiteboard: [SI-testing-blocker][priority][MP_Blocker] → [SI-testing-blocker][priority]
Whiteboard: [SI-testing-blocker][priority] → [priority]
Whiteboard: [priority] → [priority] eta:4/11
Status: NEW → ASSIGNED
Whiteboard: [priority] eta:4/11 → [c=progress p= s= u=tarako] [priority] eta:4/11
Whiteboard: [c=progress p= s= u=tarako] [priority] eta:4/11 → [c=progress p= s= u=tarako] eta:4/11
We should also revisit this when bug 990003 lands.
QAWANTED, to confirm if this bug is still valid after bug 990003 landed
Keywords: qawanted
Mike, pls help to confirm. After check, pls remove qawanted. Thanks.
Flags: needinfo?(mlien)
verify with below build and it's fine
Gaia      c62bff0bfb8b069c962dfae2640e931cc9ad1bdf
Gecko     https://hg.mozilla.org/releases/mozilla-b2g28_v1_3t/rev/7e764399b4fc
BuildID   20140415164003
Version   28.1
Flags: needinfo?(mlien)
Keywords: qawanted
dup to 990003
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → DUPLICATE
Duplicate of bug: 990003
Target Milestone: --- → 1.4 S6 (25apr)
You need to log in before you can comment on or make changes to this bug.