1121423 - [FFOS7715 v2.1][AudioChannel]music mixes with alarm when it starts to alarm.

Status: RESOLVED WONTFIX

(Firefox OS Graveyard :: AudioChannel, defect)

Description

[jingmei.zhang]

STR:

1.play music
2.set a timer in clock

when clock begins to alarm,music and alarm come out at the same time.

Comment 1

[jingmei.zhang]

Hi Alastor,
I check the logs in AudioChannel:

01-15 00:36:02.020  1477  1477 I * JINGMEI * ==>: AudioChannelAgent::SetVisibilityState oldVisibility 1 visible 1
01-15 00:36:02.020  1477  1477 I * JINGMEI * ==>: AudioChannelAgent::StartPlaying mAudioChannelType 3
01-15 00:36:02.280  1477  1477 I * JINGMEI * ==>: AudioChannelServiceChild::GetState mChannel 3 state 0
01-15 00:36:02.280  1477  1477 I * JINGMEI * ==>: HTMLMediaElement::CanPlayChanged canPlay 0
01-15 00:36:02.300  1477  1477 I * JINGMEI * ==>: HTMLMediaElement::NotifyOwnerDocumentActivityChanged()
01-15 00:36:02.300  1477  1477 I * JINGMEI * ==>: AudioChannelAgent::SetVisibilityState oldVisibility 1 visible 1
01-15 00:36:02.520  1477  1477 I * JINGMEI * ==>: AudioChannelServiceChild::GetState mChannel 3 state 0
01-15 00:36:02.520  1477  1477 I * JINGMEI * ==>: HTMLMediaElement::CanPlayChanged canPlay 0
01-15 00:36:03.460  1363  1363 I * JINGMEI * ==>: AudioChannelServiceChild::GetState mChannel 1 state 1
01-15 00:36:03.460  1363  1363 I * JINGMEI * ==>: HTMLMediaElement::CanPlayChanged canPlay 1

It first to start alarm then go to mute the music.

before music is muted,we can hear both alarm and music.

Should not we mute music first?

Need your help for the issue~

Comment 2

[Alastor Wu [:alwu]]

Hi, JingMei,
I can't reproduce this bug on following version.
Could you give me your device version?

Gaia-Rev        9946a490a9264b42e65385d703b28fa055ab2d42
Gecko-Rev       https://hg.mozilla.org/mozilla-central/rev/3d846527576f
Build-ID        20150113010202
Version         38.0a1
Device-Name     flame
FW-Release      4.4.2
FW-Incremental  eng.cltbld.20150113.043738
FW-Date         Tue Jan 13 04:37:49 EST 2015
Bootloader      L1TC00011880

Comment 3

[jingmei.zhang]

Hi Alastor,

this might be a SPRD(dolphin) issue,My device version are as follows:

Gaia-Rev        6957ac8a322234ec99c8abb7cc18dc6a2e0176db
Gecko-Rev       f6a4b637c4f59581ad64e4dfec3689442e98e268
Build-ID        20150115170936
Version         34.0
Device-Name     scx15_sp7715ea
FW-Release      4.4.2
FW-Incremental  76
FW-Date         Wed Jan 14 18:34:37 CST 2015

could you get a dolphin device in you side? A 5/5 issue in dolphin.

Comment 4

[Alastor Wu [:alwu]]

I degrade my flame to the version 34, but still can't reproduce this bug.
I don't have a dolphin device, maybe Wanyne could help to check this problem?

Gaia-Rev        d24610eff8dbe4de776a31c44ef97a19c6a181fc
Gecko-Rev       https://hg.mozilla.org/releases/mozilla-b2g34_v2_1/rev/0d1101a1a76a
Build-ID        20150114161214
Version         34.0
Device-Name     flame
FW-Release      4.4.2
FW-Incremental  eng.alastor.20150109.190131
FW-Date         五  1月  9 19:02:21 CST 2015
Bootloader      L1TC00011880

Comment 5

[Wayne Chen [:xwaynec]]

Hi Alastor,

This issue can be reproduced in dolphin. As Jingmei said, I found the log has some place we can discuess. 

1. start play music
01-16 11:18:25.333 I/WAYNE   ( 1422): AudioChannelAgent::SetVisibilityState mAudioChannelType:1, mVisible:1
01-16 11:18:25.333 I/WAYNE   ( 1422): AudioChannelAgent::StartPlaying mAudioChannelType:1
01-16 11:18:25.643 I/WAYNE   ( 1422): AudioChannelAgent::NotifyAudioChannelStateChanged mAudioChannelType:1, CanPlayChanged:0
01-16 11:18:25.653 I/WAYNE   ( 1422): AudioChannelAgent::NotifyAudioChannelStateChanged mAudioChannelType:1, CanPlayChanged:0



2. click home key and then go to clock to set time
01-16 11:18:38.093 I/WAYNE   ( 1422): AudioChannelAgent::SetVisibilityState mAudioChannelType:1, mVisible:0
01-16 11:18:38.133 I/WAYNE   ( 1422): AudioChannelAgent::NotifyAudioChannelStateChanged mAudioChannelType:1, CanPlayChanged:0


3. When clock is alarming, should we stop music (channeltype:1) first? I think it's because dolphin CPU is slow, so if start alarm first, the situation will be obvious than flame.

01-16 11:19:54.473 I/WAYNE   ( 1444): AudioChannelAgent::SetVisibilityState mAudioChannelType:3, mVisible:1
01-16 11:19:54.483 I/WAYNE   ( 1444): AudioChannelAgent::StartPlaying mAudioChannelType:3
01-16 11:19:54.963 I/WAYNE   ( 1444): AudioChannelAgent::StopPlaying mAudioChannelType:3
01-16 11:19:55.003 I/WAYNE   ( 1444): AudioChannelAgent::SetVisibilityState mAudioChannelType:3, mVisible:1
01-16 11:19:55.003 I/WAYNE   ( 1444): AudioChannelAgent::StartPlaying mAudioChannelType:3
01-16 11:19:55.063 I/WAYNE   ( 1444): AudioChannelAgent::NotifyAudioChannelStateChanged mAudioChannelType:3, CanPlayChanged:0
01-16 11:19:55.113 I/WAYNE   ( 1444): AudioChannelAgent::NotifyAudioChannelStateChanged mAudioChannelType:3, CanPlayChanged:0
01-16 11:19:55.113 I/WAYNE   ( 1444): AudioChannelAgent::NotifyAudioChannelStateChanged mAudioChannelType:3, CanPlayChanged:0
01-16 11:19:55.113 I/WAYNE   ( 1444): AudioChannelAgent::SetVisibilityState mAudioChannelType:3, mVisible:1
01-16 11:19:55.523 I/WAYNE   ( 1422): AudioChannelAgent::NotifyAudioChannelStateChanged mAudioChannelType:1, CanPlayChanged:1
01-16 11:19:55.533 I/WAYNE   ( 1422): AudioChannelAgent::NotifyAudioChannelStateChanged mAudioChannelType:1, CanPlayChanged:1
01-16 11:19:55.543 I/WAYNE   ( 1422): AudioChannelAgent::NotifyAudioChannelStateChanged mAudioChannelType:1, CanPlayChanged:1
01-16 11:19:58.313 I/WAYNE   ( 1444): AudioChannelAgent::StopPlaying mAudioChannelType:3
01-16 11:19:58.893 I/WAYNE   ( 1422): AudioChannelAgent::NotifyAudioChannelStateChanged mAudioChannelType:1, CanPlayChanged:0

Comment 6

[Alastor Wu [:alwu]]

Hi, Wayne,

In our present audio channel architecture, when we run into the audio competition problem, we would start the incoming audio first, then stop another one. This behavior results in the latency issue.

From this log, it seems that the notification of visibility changing came late. Although the alarm was starting playback, the music didn't yet receive the stop notification of visibility changing.

I will check it later :)

Comment 7

[jingmei.zhang]

Hi  Alastor,

The issue don't occur when I play music and then go to clock->timer->sound and select a alarm ringtone to play,

Are there anything different between clock start to alarm & select a alarm ringtone to play?

Comment 8

[jingmei.zhang]

(In reply to Alastor Wu [:alwu] from comment #6)
> From this log, it seems that the notification of visibility changing came
> late. Although the alarm was starting playback, the music didn't yet receive
> the stop notification of visibility changing.
> 
Hi Alastor,
I have a little confusion for the root cause of your explain:

for the visibility of 'content',it changes to '0' when we put music app to the background.As Wayne said in comment5:
> 2. click home key and then go to clock to set time
>01-16 11:18:38.093 I/WAYNE   ( 1422): AudioChannelAgent::SetVisibilityState mAudioChannelType:1, >mVisible:0

and when it starts the alarm,should the visibility of 'content' be changed on a second time?
it seems to be the notification of AudioChannelAgent::NotifyAudioChannelStateChanged that actually put the 'content' to mute.

This is what I want to say: it is the delay of receiving the 'NotifyAudioChannelStateChanged' rather than the visibility change that cause the issue.

Can you help to identify my idea?? ^_^

Comment 9

[Randy Lin [:rlin] - Be Mozillian on 2015/01/26]

(In reply to jingmei.zhang from comment #7)
> Hi  Alastor,
> 
> The issue don't occur when I play music and then go to clock->timer->sound
> and select a alarm ringtone to play,
> 
> Are there anything different between clock start to alarm & select a alarm
> ringtone to play?

Can't you find this issue when you adjust the alarm volume on setting?
The different is the caller process.

Comment 10

[jingmei.zhang]

(In reply to Randy Lin [:rlin] from comment #9)

> Can't you find this issue when you adjust the alarm volume on setting?
> The different is the caller process.

Yes,Issue also does not occur when I play music and then go to 'adjust the alarm volume on setting'.

Comment 11

[Alastor Wu [:alwu]]

Sorry for my mistake. As your said, it should be the latency of audio channel state changing notification. 

I did a test for your question in comment7. When the main thread is too busy, there may have high probability to happen notification latency. So I test the two cases on the dolphin, one is "starting alarm playback from clock app", another is "starting from setting app". 

Case 1 : starting alarm playback from clock app
User 20%, System 11%, IOW 0%, IRQ 0%
User 63%, System 19%, IOW 0%, IRQ 0%
User 79%, System 20%, IOW 0%, IRQ 0% <= display the alarm image & playback

Case 2 : starting alarm playback from setting app
User 17%, System 12%, IOW 0%, IRQ 0%
User 23%, System 11%, IOW 0%, IRQ 0%
User 61%, System 19%, IOW 0%, IRQ 0% <= only playback

The result is that the first one needs more CPU resources than the second one, so I think that is why the second one doesn't has an error.

Comment 12

[jingmei.zhang]

Are there any good solutions for this issue?

Comment 13

[Alastor Wu [:alwu]]

Hi, JingMei,
I would test some workaround to avoid this problem.
Still working in progress, I would give you a patch ASAP.

Comment 14

[Alastor Wu [:alwu]]

Hi, Wayne,
I have a question need your help :(

In our architecture, when the new audio channel is coming, the AudioChannelService would notify all children, then command them coming to ask their playback state.

I found that, in the flame, music app ALWAYS gets the notification before alarm app get it.
But in the dolphin, the order is ALWAYS opposite.

What is that reason? Does the dolphin have some special setting?

I have tried some solution to fix it, but failed. If the alarm app still gets the notification first, I think this problem can't be solved. Need to wait for the completion of audio channel refactor.

How do you think ? 
Thanks :)

Comment 15

[Alastor Wu [:alwu]]

Additional, even I modified the for-loop in |AudioChannelService::Notify|, it also couldn't change the receiving notification order of children.

https://dxr.mozilla.org/mozilla-central/source/dom/audiochannel/AudioChannelService.cpp#708

Comment 16

[Randy Lin [:rlin] - Be Mozillian on 2015/01/26]

Hi Alastor, 
Could you find someone to help check the alarm application which cause high CPU usage at showing the alarm screen?

Comment 17

[Alastor Wu [:alwu]]

Hi, Marcus,
Sorry to bother you, I have a problem need your help :(
Here we encountered a problem that is when the alarm starts, the CPU usage becomes very high. (See Comment11)
Is this normal? Are there any good solutions to reduce the CPU usage?
Thanks a lots :)

Comment 18

[Marcus Cavanaugh [:mcav]]

Hi Alastor,

I don't know what would cause the CPU usage to be so high. We don't do any intensive processing in the Clock app, so my best guess is that the high CPU usage is coming from stuff the System app (or Gecko) is doing, or perhaps that's just Gecko loading the CSS/JS for the alarm screen.

You might have to run a profile on Gecko to see what's causing the CPU load. If you can identify that the problem is in the Clock app's JavaScript, I can help, but I don't know much about the Gecko/System process underneath.

Comment 19

[jingmei.zhang]

Hi Alastor,

Any update for this issue?

Comment 20

[Alastor Wu [:alwu]]

Sorry,
Recently, I solved other issues so that forgot to trace it.
I will update more information later.

Comment 21

[jingmei.zhang]

Hi Alastor,

Sorry to trouble you again.

But I think issue may have something to do with clock app.

I have made a test as:

1.remove the alarm sound play in gaia codes:
2.play music and set a alarm
when it pops the alert screen,music will not play smoothly .

I find it that it will load 'onring.html resources when attention screen is opened.

Can you help to find anyone to run a profile on Gecko and identify if that the problem is in the Clock app's JavaScript?

Comment 22

[Alastor Wu [:alwu]]

I run the profiler to capture the performance time of the clock. The result time was from the no sound to start the alarm sound. 

Here is the result.
http://goo.gl/YLVARI

In the result, it seems that we spend lots of time in the js::runscript which was called in the Timer::fire().

Comment 23

[Yu.Xing]

(In reply to Alastor Wu [:alwu] from comment #22)
> I run the profiler to capture the performance time of the clock. The result
> time was from the no sound to start the alarm sound. 
> 
> Here is the result.
> http://goo.gl/YLVARI
> 
> In the result, it seems that we spend lots of time in the js::runscript
> which was called in the Timer::fire().

  Dear Alastor,
   
  I used the oprofile tool to capture the performance time of the clock. But I cann't get the function name, I just get the libxul.so name the result as following:

***********************************************************************************************
CPU: ARM Cortex-A7, speed 0 MHz (estimated)
Counted CPU_CYCLES events (CPU cycle) with a unit mask of 0x00 (No unit mask) count 150000
samples  %        image name               app name                 symbol name
48706    40.2822  libxul.so                libxul.so                /system/b2g/libxul.so
7492      6.1962  libmozglue.so            libmozglue.so            /system/b2g/libmozglue.so
***********************************************************************************************

Are you used the oprofile tool to capture the performance time of the clock? I suspect that is a question of my symbol library. How do you do set the  symbol library?

Can you help me to solve this issue? Thank you very much!

Comment 24

[Alastor Wu [:alwu]]

Hi, Yu Xing,
I used the built-in profiler to capture the performance :)
You can find more details on following references.

[1] Built-in profiler
http://goo.gl/GdAxNX
http://goo.gl/zei8x7

Comment 25

[Yu.Xing]

(In reply to Alastor Wu [:alwu] from comment #24)
> Hi, Yu Xing,
> I used the built-in profiler to capture the performance :)
> You can find more details on following references.
> 
> [1] Built-in profiler
> http://goo.gl/GdAxNX
> http://goo.gl/zei8x7

ok, thanks a lot!

Comment 26

[Alastor Wu [:alwu]]

Hi, Marcus,
Sorry to bother you again,
Could you help us to take a look the profile result on comment22?
In the result, it seems that we spend lots of time in the js::runscript which was called in the Timer::fire().

Very appreciate :)

Comment 27

[Marcus Cavanaugh [:mcav]]

Looking at that profile, it appears that we are spending:

150ms painting
150ms loading/running assorted scripts
 96ms garbage collecting

That doesn't seem surprising to me, considering that we're loading up the Clock app at the same time as we're trying to play other audio.

This really seems like an AudioChannel or related bug. If music is playing at incorrect times, or overlapping, that's something that the system audio contexts should be dealing with.

Comment 28

[Alastor Wu [:alwu]]

Thanks, Marcus!
My observation is that the music app can't immediately receive the notification of audio channel state changing when the alarm is starting. The notification always be received after the alarm start. 

Our audio flow is like this.
> (1) The Clock's audio channel agent register itself to the AudioChannelService
> (2) AudioChannelService send the notification to every agents
> (3) After receive the notification, agents would ask their playable state from AudioChannelService

In this case, in the step 3, we should get the normal result like this,
> - Normal : Music get notification first  -> ask playable state -> stop music
>            Clock get notification second -> ask playable state -> start clock

But, actually we get this,
> - Error :  Clock get notification first  -> ask playable state -> start clock
>            Music get notification second -> ask playable state -> stop music

I can't let the music app receive the notification first. BUT, If we try to play the alarm from the setting app, this condition would not happen. We would see the normal condition. Because of that, I wonder whether the launching the alarm would interrupt the IPC transportation or something else...

How do you think :) ?
Could you give me some suggestions or you know who can help this issue?

Thanks a lots !!!!
---

And I got the another result to profile the music app. (The result on comment22 is profiling the clock app) 
I found that the executed time of the Timer::Fire() is increasing a lots.

Result : http://goo.gl/H29W4m

Comment 29

[Marcus Cavanaugh [:mcav]]

As I understand it, Gecko is supposed to pause the other AudioChannel when Clock's alarm starts to ring; see [1]: "Whenever an audio channel is used, lower priority channels are automatically paused."

So I think the actual problem here is that we need to file a bug with AudioChannel, saying that it's incorrectly overlapping audio when it isn't supposed to. In other words, no matter which order the notifications arrive in, we shouldn't hear overlapping audio.

[1] https://wiki.mozilla.org/WebAPI/AudioChannels

Comment 30

[Alastor Wu [:alwu]]

Close this bug because we wouldn't land the code for v2.1.