1038134 - [271MB] A2DP audio choppiness for 2 secs when home button is tapped during audio playback through BT headset

Status: VERIFIED FIXED

(Firefox OS Graveyard :: AudioChannel, defect)

Description

[Pooja]

Steps to Reproduce:
1.	Bootup the target
2.	Pair and connect a Bluetooth headset.
3.	Start playing a music file.
4.	Tap home button.
5.	Audio breaks for 2 secs.

Expected behavior:
Audio should be continuous without any pause when switching from Music app to Home screen app OR any other app.

Actual behavior:
There is a pause of 2 sec between transition from Music app to Home screen app

Comment 1

[bhavana bajaj [:bajaj]]

Adding qawanted to confirm the issue and see if we can reproduce this regression.

Comment 2

[Jayme Mercado [:JMercado] (Inactive 3/4/2016)]

I was unable to reproduce this issue on the latest Flame 2.1, Flame 2.0, Flame 1.4, or Buri 2.0.

Environmental Variables:
Device: Flame Master
BuildID: 20140714061512
Gaia: 88e0a972280bb35847c010b8c3f1481fa80f3847
Gecko: 340b19c14d3d
Version: 33.0a1 (Master) 
Firmware Version: v122
User Agent: Mozilla/5.0 (Mobile; rv:33.0) Gecko/33.0 Firefox/33.0

Environmental Variables:
Device: Flame 2.0
BuildID: 20140714000202
Gaia: ca022f811bcbbda0f89086094a9e92bb220fea18
Gecko: 376889ab0e02
Version: 32.0a2 (2.0) 
Firmware Version: v122
User Agent: Mozilla/5.0 (Mobile; rv:32.0) Gecko/32.0 Firefox/32.0

Environmental Variables:
Device: Flame 1.4
BuildID: 20140711225112
Gaia: b7d36622c7df92c976c37520ccab25199c7ada91
Gecko: dbebcdab47aa
Version: 30.0 (1.4) 
Firmware Version: v122
User Agent: Mozilla/5.0 (Mobile; rv:30.0) Gecko/30.0 Firefox/30.0


Environmental Variables:
Device: Buri 2.0
BuildID: 20140714000202
Gaia: ca022f811bcbbda0f89086094a9e92bb220fea18
Gecko: 376889ab0e02
Version: 32.0a2 (2.0) 
Firmware Version: v1.2device.cfg
User Agent: Mozilla/5.0 (Mobile; rv:32.0) Gecko/32.0 Firefox/32.0

Music plays without interruption when home is tapped.

Comment 3

[Hema Koka [:hema]]

Pooja, We need more information on the device that you are testing with. See comment 2, our QA is unable to reproduce this on Flame.

Thanks
Hema

Comment 4

[Pooja]

Please note playback is through BT headset 

Device details:
Target: 8x10 QRD
Gaia: "35a9b715e7348ec738ff6c8a59f50190390a06f2"
Gecko "2fb60c777d3f82d580cba249e5e01a167a01de39"
Version 32.0a2
Build ID 20140710185233

Comment 5

[Pooja]

BT Headset Details:

Sony Ericsson
Model: HPM-78

Comment 6

[bhavana bajaj [:bajaj]]

Jayme, can you please give information on what Bluetooth device did you use here, Inder/I discussed this and he said manier times the issue ends up  being a Bluetooth related in these cases.

In parallel, Inder also is going to see if CAF is reproducing this on Flames.

Comment 7

[Eric Chou [:ericchou] [:echou]]

(In reply to bhavana bajaj [:bajaj] [NOT reading Bugmail, needInfo please] from comment #6)
> Jayme, can you please give information on what Bluetooth device did you use
> here, Inder/I discussed this and he said manier times the issue ends up 
> being a Bluetooth related in these cases.
> 
> In parallel, Inder also is going to see if CAF is reproducing this on Flames.

Quick update: Star and I gave it a try and neither of us could reproduce on Flame.

Comment 8

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

bajaj, can we check 8x10 branch, bluedroid with removing real time scheduling patch(Bug 1002917)? I think it impacts performance a lot. I used to observe sound jitters easily on Nexus4/5 without fixing RT scheduling (Bug 1002917). If I add patch (Bug 1002917) on Nexus4/5, delay (or sound skipping) disappeared.

If bluedroid uses RT scheduling, b2g PPID becomes "-1".


Note: Flame is not a good reference for this bug, because Flame uses JB with bluez stack, and I believe all 2.0+ bugs reported by CAF are KK based with bluedroid stack.

Comment 9

[Pooja]

Have one more finding here that this issue doesn't get reproduced if we increase memory to 512MB

Issue is reported for 8x10 target with 271MB memory.
It looks like Homescreen memory usage is causing this delay.

Comment 10

[Pooja]

(In reply to Shawn Huang [:shuang] [:shawnjohnjr] from comment #8)
 
> Note: Flame is not a good reference for this bug, because Flame uses JB with
> bluez stack, and I believe all 2.0+ bugs reported by CAF are KK based with
> bluedroid stack.

Yes this bug is on KK build with bluedroid stack.

Comment 11

[Jayme Mercado [:JMercado] (Inactive 3/4/2016)]

Since this is not something that can be reproduced on Flame I'm not sure if this will help you, but The device used was a Go Groove AirBAND headset.  It uses Bluetooth 2.1

Comment 12

[Inder]

> bajaj, can we check 8x10 branch, bluedroid with removing real time
> scheduling patch(Bug 1002917)? I think it impacts performance a lot. I used
> to observe sound jitters easily on Nexus4/5 without fixing RT scheduling
> (Bug 1002917). If I add patch (Bug 1002917) on Nexus4/5, delay (or sound
> skipping) disappeared.
> 

Pooja -- can you please try backing this patch and see if it helps in your testing.

Comment 13

[Pooja]

(In reply to Inder from comment #12)

> 
> Pooja -- can you please try backing this patch and see if it helps in your
> testing.

Issue can still be reproduced after backing the patch in (Bug 1002917)

Comment 14

[Hema Koka [:hema]]

Moving it to the right component, after discussion with Dominic, someone familiar with audiochannel should investigate further

Comment 15

[Eric Chou [:ericchou] [:echou]]

I'll check if we can reproduce by using Flame with Bluedroid.

Shawn,

Please flash a Flame with Bluedroid as Bluetooth backend and give it a try today. Thanks.

Comment 16

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

Playing A2DP music and press home button:
1. Nexus 4 with AOSP version bluedroid without bluedroid patch (in Bug 1002917) : Fail, audio skipping can be seen.
2. Nexus 4 with AOSP version bluedroid with bluedroid patch (in Bug 1002917) : Pass

The same thing also applied to flame device. But apparently CAF 8x10 device shall have that patch but still can reproduce this bug (based on Comment 9), enlarge memory to 512MB, the problem disappeared.

I will reduce memory to 250MB on flame and try again.

Comment 17

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

I actually use flame and reduce memory size to 260MB and change Bluetooth stack to bluedroid (JB + CAF bluedroid). Audio playback skipping around 1 second via BT stream while pressing home button. But it doesn't always happen, it happens on while memory pressure is been triggered.

Pooja, can you provide logcat, and point out when audio skipping happens. Just want to make sure it's related to memory pressure event?

Comment 18

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

http://pastebin.mozilla.org/5572142

Comment 19

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

My testing environment:
1. Flame memory 260MB + bluedroid stack using v2.0 Gecko/Gaia
2. 5 songs (without album cover)

Summary:
1. When I use Music seeking feature, audio skipping via a2dp streaming can be observed. (see Comment 18)
2. Audio playback skipping around 1 second via BT stream while pressing home button. But it doesn't always happen, it happens on while memory pressure is been triggered.

Comment 20

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

Not much I can do from bluetooth side, let :scheng check further.

Comment 21

[Pooja]

(In reply to Shawn Huang [:shuang] [:shawnjohnjr] from comment #17)
> I actually use flame and reduce memory size to 260MB and change Bluetooth
> stack to bluedroid (JB + CAF bluedroid). Audio playback skipping around 1
> second via BT stream while pressing home button. But it doesn't always
> happen, it happens on while memory pressure is been triggered.
> 
> Pooja, can you provide logcat, and point out when audio skipping happens.
> Just want to make sure it's related to memory pressure event?

Hi Shwan,
have problem in my BT headset. Will provide you logs asap.

Comment 22

[Star Cheng [:scheng]]

(In reply to Shawn Huang [:shuang] [:shawnjohnjr] from comment #20)
> Not much I can do from bluetooth side, let :scheng check further.

It's more easier to duplicate in low memory status. When it occurs, I saw the "memory pressure" in the logcat log. The phenomenon seems like memory pressure event is triggered. If wanna to use memory-constraint device, should we tune the oom_adj, notifyLowMemUnderKB and oom_score_adj value for the specific device instead of flame or other device. Now I have no explicit solution to revolve this issue.

Comment 23

[Preeti Raghunath(:Preeti)]

Pooja

Please provide logs here for further investigation

Comment 24

[Pooja]

(In reply to Shawn Huang [:shuang] [:shawnjohnjr] from comment #17)

> Pooja, can you provide logcat, and point out when audio skipping happens.
> Just want to make sure it's related to memory pressure event?

Hi Shawn,
Sorry for delay. Please see attached logs.
I don't see memory pressure event whenever audio pause while tapping home button. Also no sigkill in dmesgs.

And some time it pause and sometime its more like disturbance or break in playback.

Have a query. If its because of memory pressure events then same issue should have happened through wired headset too ?

Comment 25

[Pooja]

Attachment: adb logs

Comment 26

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

(In reply to Pooja from comment #24)
> (In reply to Shawn Huang [:shuang] [:shawnjohnjr] from comment #17)
> 
> > Pooja, can you provide logcat, and point out when audio skipping happens.
> > Just want to make sure it's related to memory pressure event?
> 
> Hi Shawn,
> Sorry for delay. Please see attached logs.
> I don't see memory pressure event whenever audio pause while tapping home
> button. Also no sigkill in dmesgs.
> 
> And some time it pause and sometime its more like disturbance or break in
> playback.
> 
> Have a query. If its because of memory pressure events then same issue
> should have happened through wired headset too ?

May I know which part of the log can represent the audio break during playback? I don't see timestamp in the logcat, it's hard for me to check.

Indeed, in general I don't see any of memory pressure event printed out. It looks like on your platform not related to low memory condition. And how often we can observe audio break? Whenever pressing home button, the audio break (last for 1~2 secs) happens? Is it 100% reproducible?
And as you said the problem cannot be observed under 512MB? If it's not about memory usage, using 512MB memory can avoid this problem occur?

There are several reason we might see audio breaks while playing a2dp streaming:
1. Audio thread/bluedroid audio hw module cannot get CPU resource - (this is what I suspected, since LMK/memory pressure event/OOM might occupy resources) 

2. Bluetooth compatibility - Bluetooth headset sends packets and reject sniff commands (not our case here, because you mentioned it's fine without pressing home button)

3. Co-existence (wifi-bluetooth) - It doesn't look like our case, no wifi connection or wifi scanning in this case.

Comment 27

[Pooja]

(In reply to Shawn Huang [:shuang] [:shawnjohnjr] from comment #26)
> (In reply to Pooja from comment #24)
 
> May I know which part of the log can represent the audio break during
> playback? I don't see timestamp in the logcat, it's hard for me to check.

uploaded new set of logs with timestamp

From audio prospects i am not sure in logs where audio breaks.
But in logs "Changed nice for pid 1077 from 18 to 1" indicates at this point i tapped Home button (And issue reproduced)
pid 1077 - Its homescreen Pid
So any logs related to audio pause should come somewhere near it.

> 
> Indeed, in general I don't see any of memory pressure event printed out. It
> looks like on your platform not related to low memory condition.

Yes No pressure events on  286Mb target.("Memory pressure detected"). 
On 271 Targets device receives memory presssure  very frequently so can't say exactly if its because of 
this (tapping on home).
Possibly you can try with 286 Mb and see if you receives memory pressure events
 
> And how
> often we can observe audio break? Whenever pressing home button, the audio
> break (last for 1~2 secs) happens? Is it 100% reproducible?

With 286Mb In 4-5 attempts . If we keep open many apps in background then it comes in 1-2 attempts it self(Which i feel supports your fact that its because of memory)
Break lasts for 1secs sometime 2 sec.

> And as you said the problem cannot be observed under 512MB? If it's not
> about memory usage, using 512MB memory can avoid this problem occur?
> 
I am suspecting with higher memory it takes higher time to reach at this condition

with 271Mb - every time reproducible
With 286Mb- In 4-5 Attempts. Can reproduce it earlier if we keep open other apps in background
With 512 Mb - Not reproducible.

> There are several reason we might see audio breaks while playing a2dp
> streaming:
> 1. Audio thread/bluedroid audio hw module cannot get CPU resource - (this is
> what I suspected, since LMK/memory pressure event/OOM might occupy
> resources) 
> 
> 2. Bluetooth compatibility - Bluetooth headset sends packets and reject
> sniff commands (not our case here, because you mentioned it's fine without
> pressing home button)
> 
> 3. Co-existence (wifi-bluetooth) - It doesn't look like our case, no wifi
> connection or wifi scanning in this case.

Comment 28

[Pooja]

Attachment: Adb logs with timestamp

Comment 29

[Star Cheng [:scheng]]

Attachment: Bug-1038134-test.patch

To restrict minFrameount buffer.

Comment 30

[Star Cheng [:scheng]]

Hi, Pooja

FxOS use openSL ndk lib to communitcate with Android audio back-end (AudioTrack/AudioFlinger..). And the framecount is decided by paramenters of Audio HAL. In duplicated mixer mode (codec + A2DP), the framecount value is so huge that takes more time to fill the buffer. We restrict the framecount value in order to decrease the filled buffer time.


Can you please help to try the wip patch to your code base.
Thanks

Comment 31

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

Hi, Pooja
Tested the potential fix as Comment 30 mentioned at my end, it looks like huge improvement for latency when the memory is restricted. So please help to test on 8x10. We hope the same results happened on 8x10 with lower memory configuration.

Comment 32

[Pooja]

Sure .will update the result in sometime

Comment 33

[Pooja]

Hi Shawn,

I am having difficulty in getting the same BT headset.

I tested with another one but i don't see any difference in issue. So can we wait till tomorrow,i will try to get that BT headset and will share the exacts results

Marking ni on myself

Comment 34

[Star Cheng [:scheng]]

Attachment: Bug-1038134-wip.patch

add log in the wip patch.

Comment 35

[Star Cheng [:scheng]]

(In reply to Star Cheng [:scheng] from comment #34)
> Created attachment 8462413 [details] [diff] [review]
> Bug-1038134-wip.patch
> 
> 
> add log in the wip patch.

Hi, Pooja 

Could you help to try this? I have added the log in the patch.

Comment 36

[Pooja]

Will update here

Comment 37

[Pooja]

Attachment: Adb logs

Hi star,

Issue still reproducible with latest patch.
Please find attached logs.

Log: Changed nice for pid 1078 from 18 to 1
corresponds to switching to switching from music to homescreen

Comment 38

[bhavana bajaj [:bajaj]]

NI on star to help investigate this given the logs in comment #37

Comment 39

[Star Cheng [:scheng]]

(In reply to Pooja from comment #37)
> Created attachment 8463282 [details]
> Adb logs
> 
> Hi star,
> 
> Issue still reproducible with latest patch.
> Please find attached logs.
> 
> Log: Changed nice for pid 1078 from 18 to 1
> corresponds to switching to switching from music to homescreen


The log[1] is different from my patch (attachment 8462413 [details] [diff] [review] or attachment 8461327 [details] [diff] [review]). Can I confirm with you what is your modification? If that not bother you, can you try to set the framecount value as 4096. 


[1]
01-01 00:11:56.039   214  1385 E AudioFlinger: [star] createTrack_1 minBufCount 4 minFrameCount 10240
01-01 00:11:56.039   214  1385 E AudioFlinger: [star]: force to set framecount tp 2084*4

Comment 40

[Pooja]

Hi Star,

Below are the changes i am trying (i.e combo of above two patches). 

diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index 6bda429..3db1b08 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -1439,14 +1439,20 @@ sp<AudioFlinger::PlaybackThread::Track> AudioFlinger::PlaybackThread::createTrac
         uint32_t minBufCount = latencyMs / ((1000 * mNormalFrameCount) / mSampleRate);
         if (minBufCount < 2) {
             minBufCount = 2;
+        } else {
+          if (minBufCount > 8) {
+             minBufCount = 8;
+          }
         }
         size_t minFrameCount = mNormalFrameCount * minBufCount;
+        ALOGE("[star] createTrack_1 minBufCount %d minFrameCount %d",minBufCount,minFrameCount);
         if (frameCount < minFrameCount) {
             frameCount = minFrameCount;
         }
       }
     }
-
+    ALOGE("[star]: force to set framecount tp 2084*4");
+    frameCount = (2048*4); // [star] force to set
     if (mType == DIRECT) {
         if (((format & AUDIO_FORMAT_MAIN_MASK) == AUDIO_FORMAT_PCM) ||
                 audio_is_compress_voip_format(format)) {


But yes in above log mistakenly i printed frame count (2048*4) as (2084*4),eventhough in code value is correct. Thanks for pointing.

Will try with framecount value as 4096 and update you

Comment 41

[Pooja]

(In reply to Star Cheng [:scheng] from comment #39)
> If that not bother you, can you try to
> set the framecount value as 4096. 
>

Plz find attached logs with frame count 4096. Issue still reproduced.

01-01 00:06:39.789   213   213 I Gonk    : Changed nice for pid 1097 from 18 to 1. When tapped on Homebutton

1097 Pid of Homecreen
1270 Pid of Music

Comment 42

[Pooja]

Attachment: Logs with framecount 4096

Comment 43

[Star Cheng [:scheng]]

Hi, Pooja


1. Could you provide the device model number?
2. Could you provide the video of duplicate STR? We want to clarify the issue is as the same as that we encounter.

Comment 44

[Inder]

BT device details are in Comment 5 and we are testing with QRD.

Pooja -- please provide the video of the STR.

Comment 45

[Star Cheng [:scheng]]

(In reply to Inder from comment #44)
> BT device details are in Comment 5 and we are testing with QRD.
> 
> Pooja -- please provide the video of the STR.

What is the model number of QRD?

Comment 46

[Star Cheng [:scheng]]

(In reply to Star Cheng [:scheng] from comment #43)
> Hi, Pooja
> 
> 
> 1. Could you provide the device model number?
> 2. Could you provide the video of duplicate STR? We want to clarify the
> issue is as the same as that we encounter.

3.Please check weather this line is executed or not.
http://dxr.mozilla.org/mozilla-central/source/widget/gonk/GonkMemoryPressureMonitoring.cpp#212

Comment 47

[Pooja]

Attachment: Video of STR

Comment 48

[Pooja]

(In reply to Star Cheng [:scheng] from comment #46)

> 3.Please check weather this line is executed or not.
> http://dxr.mozilla.org/mozilla-central/source/widget/gonk/
> GonkMemoryPressureMonitoring.cpp#212

HI Star,

I get  above Memory pressure Log when i keep other app open in background specially camera for some time, and device becomes really sluggish.

01-01 01:13:10.929   216   741 I GonkMemoryPressure: Checking to see if memory pressure is over.
01-01 01:13:10.929   216   741 I GonkMemoryPressure: Memory pressure is over.

But if i try only with Music Then i dont see this log. Even though i can observe homescreen becomes lazy a bit.

Comment 49

[Pooja]

Star , I am not sure how to get the device model number.
In settings-> Device information  Model shows as qcom

And Device MCN is 10-NB245~176 if you can track its model number from this info.

Let me know if i can provide you more info

Comment 50

[bhargavg1]

(In reply to Pooja from comment #49)
> Star , I am not sure how to get the device model number.
> In settings-> Device information  Model shows as qcom
> 
> And Device MCN is 10-NB245~176 if you can track its model number from this
> info.
> 
> Let me know if i can provide you more info

Star, the configuration is similar to Flame device (8x12)

Comment 51

[Star Cheng [:scheng]]

Hi, Pooja

Do you have the android kk base(not FxOS base) QRD reference phone with 256M memory (or you can configure the memory size setting)? If yes, could you give a trail according to the same STR.

Comment 52

[Pooja]

Hi Star,

All kk based LA builds are 512Mb so i can't try this STR on LA with 256Mb.

Comment 53

[Star Cheng [:scheng]]

Device : Flame
1) JB base + 256M - Can *Not* Duplicate
2) JB base + 319M - Can *Not* Duplicate
3) KK base + 256M - Can Duplicate
4) KK base + 319M - Can *Not* Duplicate

I tested 4 cases. Only in case 3) I encounter this choppy phenomenon.

Comment 54

[Star Cheng [:scheng]]

Hi, Peter

I tried to configure memory up to 319M, the following err log is disappear. 

213   888 E qdhwcomposer: prepare: wrong params for display screen_w=480                          src_crop_width=480 screen_h=0 src_crop_height=0

Could you tell me what is the err log means? Thanks

Comment 55

[Preeti Raghunath(:Preeti)]

What are the next steps for 3) KK base + 256M - Can Duplicate

Comment 56

[Peter Chang[:pchang]]

(In reply to Star Cheng [:scheng] from comment #54)
> Hi, Peter
> 
> I tried to configure memory up to 319M, the following err log is disappear. 
> 
> 213   888 E qdhwcomposer: prepare: wrong params for display screen_w=480    
> src_crop_width=480 screen_h=0 src_crop_height=0
> 
> Could you tell me what is the err log means? Thanks
HWComposer is used to compose screen and this error indicates it receives screen height as zero. Therefore, it doesn't use HWC for this invalid layer input.

Comment 57

[Star Cheng [:scheng]]

(In reply to peter chang[:pchang][:peter] from comment #56)
> (In reply to Star Cheng [:scheng] from comment #54)
> > Hi, Peter
> > 
> > I tried to configure memory up to 319M, the following err log is disappear. 
> > 
> > 213   888 E qdhwcomposer: prepare: wrong params for display screen_w=480    
> > src_crop_width=480 screen_h=0 src_crop_height=0
> > 
> > Could you tell me what is the err log means? Thanks
> HWComposer is used to compose screen and this error indicates it receives
> screen height as zero. Therefore, it doesn't use HWC for this invalid layer
> input.


Does it mean to use SW Composer to compose screen instead of HW Composer? So there is more cpu utilization. How can I to pass correct width & height to HW Composer?

Comment 58

[Peter Chang[:pchang]]

(In reply to Star Cheng [:scheng] from comment #57)
> (In reply to peter chang[:pchang][:peter] from comment #56)
> > (In reply to Star Cheng [:scheng] from comment #54)
> > > Hi, Peter
> > > 
> > > I tried to configure memory up to 319M, the following err log is disappear. 
> > > 
> > > 213   888 E qdhwcomposer: prepare: wrong params for display screen_w=480    
> > > src_crop_width=480 screen_h=0 src_crop_height=0
> > > 
> > > Could you tell me what is the err log means? Thanks
> > HWComposer is used to compose screen and this error indicates it receives
> > screen height as zero. Therefore, it doesn't use HWC for this invalid layer
> > input.
> 
> 
> Does it mean to use SW Composer to compose screen instead of HW Composer? So
> there is more cpu utilization. How can I to pass correct width & height to
> HW Composer?

You can disable HWC from developer option to check your problem happened for 319M or not.
If it happens, you need to dump the layer tree to figure out why this invalid layer parameters exist.

Comment 59

[Star Cheng [:scheng]]

Hi, Sotaro

Device : Flame
1) JB base + 256M + BT headset - Can *Not* Duplicate
2) JB base + 319M + BT headset - Can *Not* Duplicate
3) KK base + 256M + BT headset - Can Duplicate
4) KK base + 319M + BT headset - Can *Not* Duplicate
5) KK base + 256M + wired headphone  - Can *Not* Duplicate
6) KK base + 319M + wired headphone  - Can *Not* Duplicate

In case 3), I have tried many way to avoid the choppy phenomenon. (eg. set nice value as 1 to music app while in background, decrease the minFrameCount size, enlarge the decoded audio buffer queue to avoid the underrun phenomenon) But, those didn't work. I still can't find the root cause of this issue. You are the expert of media and have very much experience at media related works. Could you give me suggestion about this issue?

My STR as following:
1.	Pair and connect a Bluetooth headset.
2.	Start playing a music file.
3.	Tap home button.
4.	Launch setting app
5.	Audio breaks for 2 secs.

Comment 60

[Star Cheng [:scheng]]

(In reply to Star Cheng [:scheng] from comment #54)
> Hi, Peter
> 
> I tried to configure memory up to 319M, the following err log is disappear. 
> 
> 213   888 E qdhwcomposer: prepare: wrong params for display screen_w=480    
> src_crop_width=480 screen_h=0 src_crop_height=0
> 
> Could you tell me what is the err log means? Thanks


Sorry! Update:

Even I configure memory up to 319M, the log still appears.

Comment 61

[Sotaro Ikeda [:sotaro]]

(In reply to Star Cheng [:scheng] from comment #60)
> (In reply to Star Cheng [:scheng] from comment #54)
> > Hi, Peter
> > 
> > I tried to configure memory up to 319M, the following err log is disappear. 
> > 
> > 213   888 E qdhwcomposer: prepare: wrong params for display screen_w=480    
> > src_crop_width=480 screen_h=0 src_crop_height=0
> > 
> > Could you tell me what is the err log means? Thanks
> 
> 
> Sorry! Update:
> 
> Even I configure memory up to 319M, the log still appears.

I do not think HwComposer composition or OpenGL composition is related to this bug. It seems a problem of how to use cpu time.

Comment 62

[Sotaro Ikeda [:sotaro]]

(In reply to Star Cheng [:scheng] from comment #59)
> Could you give me suggestion about this issue?

I think this is basically threads' priorities problem. It seems better to write down all threads, their priorities and data path that are related to this bug's use case. This bug does not have such information . Without it, it seems very difficult to understand the actual problem. Some thread's priorities are changed during the STR. It is also need to make clear by writing down.

And I do not think it is a good idea to modify AudioFlinger to address the problem. The actual problem seems that gecko's media framework can not fill audio data without underflow.

To analyze the problem the following process seems better. We need to divide the big problem to sub problem and investigate about them one by one.

- [1] Write down all threads and their priorities related to the STR
- [2] based on [1], investigate if the problem is addressed by changing threads' priorities.
- [3] based on [2], investigate which part is actually delaying. 
- [4] based on [2]/[3], investigate if we can address the problem by changing a threads priorities
      in the product.
      If we can not fix the problem. Make clear why the problem can not be fixed
      by changing the priorities.
- [5] If threads priorities change does not fix the problem at [4].
      Think about workarounds by other ways at bottle neck parts.

Comment 63

[Sotaro Ikeda [:sotaro]]

FYI:
 Since Bug 980027 fix, Hal does not reduce threads priorities that are higher than ANDROID_PRIORITY_NORMAL.

http://mxr.mozilla.org/mozilla-central/source/hal/gonk/GonkHal.cpp#1463

Comment 64

[Star Cheng [:scheng]]

(In reply to Sotaro Ikeda [:sotaro] from comment #62)
> (In reply to Star Cheng [:scheng] from comment #59)
> > Could you give me suggestion about this issue?
> 
> I think this is basically threads' priorities problem. It seems better to
> write down all threads, their priorities and data path that are related to
> this bug's use case. This bug does not have such information . Without it,
> it seems very difficult to understand the actual problem. Some thread's
> priorities are changed during the STR. It is also need to make clear by
> writing down.

But it is very strange that there are different result for the different memory size configure. You can see the case 3) & 4) and in commnet 59. And case 3) & 5) are different result because of the output device(BT headset VS wired headset) are different. If the root cause is threads' priorities, the result should be the same.

> 
> And I do not think it is a good idea to modify AudioFlinger to address the
> problem. The actual problem seems that gecko's media framework can not fill
> audio data without underflow.
> 

I add some log to check the underrun case. I add log in AudioStream [1], Cubeb_opensl [2], and AudioTrack [3], but I can't see the underrun occurs. There is a err log in AudioFlinger when you use cas3 3) in comment 59. The err log as followings:

W/AudioFlinger(  196): write blocked for 1048 msecs, 3 delayed writes, thread 0xb5970008

> To analyze the problem the following process seems better. We need to divide
> the big problem to sub problem and investigate about them one by one.
> 
> - [1] Write down all threads and their priorities related to the STR
> - [2] based on [1], investigate if the problem is addressed by changing
> threads' priorities.
> - [3] based on [2], investigate which part is actually delaying. 
> - [4] based on [2]/[3], investigate if we can address the problem by
> changing a threads priorities
>       in the product.
>       If we can not fix the problem. Make clear why the problem can not be
> fixed
>       by changing the priorities.
> - [5] If threads priorities change does not fix the problem at [4].
>       Think about workarounds by other ways at bottle neck parts.


In case 3) in comment 59, I change the nice value of background perceivable[4] as 1, whose priority is as the same as foreground. But the phenomenon still occurs.

[1] http://dxr.mozilla.org/mozilla-central/source/content/media/AudioStream.cpp#1272
[2] http://dxr.mozilla.org/mozilla-central/source/media/libcubeb/src/cubeb_opensl.c#94
[3] http://androidxref.com/4.4.2_r2/xref/frameworks/av/media/libmedia/AudioTrack.cpp#1382
[4] http://dxr.mozilla.org/mozilla-central/source/b2g/app/b2g.js#714

Comment 65

[Sotaro Ikeda [:sotaro]]

> > 
> 
> I add some log to check the underrun case. I add log in AudioStream [1],
> Cubeb_opensl [2], and AudioTrack [3], but I can't see the underrun occurs.
> There is a err log in AudioFlinger when you use cas3 3) in comment 59. The
> err log as followings:
> 
> W/AudioFlinger(  196): write blocked for 1048 msecs, 3 delayed writes,
> thread 0xb5970008

It means audio write is slow. Did you analyzed the route from AudioFliner's playback thread to bt hw out?

Comment 66

[Sotaro Ikeda [:sotaro]]

(In reply to Sotaro Ikeda [:sotaro] from comment #65)
> > > 
> > 
> > W/AudioFlinger(  196): write blocked for 1048 msecs, 3 delayed writes,
> > thread 0xb5970008
> 
> It means audio write is slow. Did you analyzed the route from AudioFliner's
> playback thread to bt hw out?

And it seems better to compare between JB and KK more concretely more than just names of bt stacks.

Comment 67

[[:SalvadorR]]

I believe this is covered in Moztrap testcase: https://moztrap.mozilla.org/manage/case/9066/

"Add STR step: 4. Navigate to different apps with bluetooth still connected.
Expected Result: Sound should play smoothly when switching between apps

Comment 68

[Hema Koka [:hema]]

(In reply to Sotaro Ikeda [:sotaro] from comment #66)
> (In reply to Sotaro Ikeda [:sotaro] from comment #65)
> > > > 
> > > 
> > > W/AudioFlinger(  196): write blocked for 1048 msecs, 3 delayed writes,
> > > thread 0xb5970008
> > 
> > It means audio write is slow. Did you analyzed the route from AudioFliner's
> > playback thread to bt hw out?
> 
> And it seems better to compare between JB and KK more concretely more than
> just names of bt stacks.

Star,

Can you do further investigation based on Sotaro's suggestion? 

Thanks
Hema

Comment 69

[Star Cheng [:scheng]]

Per our investigating, we observe the "kswap" daemon is triggered while the phenomenon occurs. Case [1] is following the STR of comment 0, and case [2] the music app is playing in background. It looks like low memory issue. If wanna to resolve this issue, we have to tune the value which I mentioned in comment 22 or more threshold value.  
 
[1] Press Home key
User 31%, System 56%, IOW 1%, IRQ 0%
User 45 + Nice 45 + Sys 158 + Idle 29 + IOW 3 + IRQ 0 + SIRQ 2 = 282

  PID   TID PR CPU% S     VSS     RSS PCY UID      Thread          Proc
   93    93  1  14% R      0K      0K     root     kswapd0
  201   201  1  10% D 270988K  22216K     root     b2g             /system/b2g/b2g
 1033  1033  0  10% S  82092K  12496K     u0_a1033 Homescreen      /system/b2g/plugin-container
  201   920  0   8% S 270988K  22216K     root     Compositor      /system/b2g/b2g
 1288  1288  1   8% D  93840K  16240K     u0_a1288 Music           /system/b2g/plugin-container
 2711  2711  1   8% R   1408K    444K     root     top             top
  197  1334  1   4% S  28924K    560K  fg media    AudioOut_6      /system/bin/mediaserver
  201   942  1   4% S 270988K  22216K  fg root     A2DP-MEDIA      /system/b2g/b2g
  144   144  0   2% S      0K      0K     root     mmcqd/0
 1288 11924  1   1% S  93840K  16404K  fg u0_a1288 gle.mp3.decoder /system/b2g/plugin-container

[2] Playing in background
User 25%, System 26%, IOW 0%, IRQ 0%
User 33 + Nice 12 + Sys 48 + Idle 87 + IOW 0 + IRQ 0 + SIRQ 0 = 180

  PID   TID PR CPU% S     VSS     RSS PCY UID      Thread          Proc
 4383  4383  0  19% R   1412K    656K     root     top             top
  197  1334  0   3% S  28924K    544K  fg media    AudioOut_6      /system/bin/mediaserver
 1288  4108  0   3% R  81624K  16040K  fg u0_a1288 gle.mp3.decoder /system/b2g/plugin-container
   94    94  0   1% S      0K      0K     root     ksmd
  254   254  0   1% S   6648K    212K     root     adbd            /sbin/adbd
 1288  1288  0   1% S  81624K  16040K     u0_a1288 Music           /system/b2g/plugin-container
 1288  4109  0   1% S  81624K  16040K  fg u0_a1288 OMXCallbackDisp /system/b2g/plugin-container
 1288  4111  0   1% S  81624K  16040K     u0_a1288 Media Decode #2 /system/b2g/plugin-container
 1288  4113  0   1% R  81624K  16040K  fg u0_a1288 AudioTrack      /system/b2g/plugin-container
  201   966  0   1% R 265308K  23388K  fg root     gki timer       /system/b2g/b2g


[Memory info] When the phenomenon occurs, here is the memory information
MemTotal:         156492 kB
MemFree:            1712 kB
Buffers:              68 kB
Cached:            15508 kB
SwapCached:        11960 kB
Active:            31216 kB
Inactive:          28632 kB
Active(anon):      23000 kB
Inactive(anon):    22652 kB
Active(file):       8216 kB
Inactive(file):     5980 kB
Unevictable:        1120 kB
Mlocked:               0 kB

Comment 70

[Star Cheng [:scheng]]

Hi, Pooja

Do you encounter this phenomenon?

We observe the strange phenomenon about "Rescheduling interrupts" while duplicate the STR, and the value is increasing more than 1000. The command and result as following:

star@star:~/work/log$ adb shell cat /proc/interrupts | grep IPI
IPI0:          0         95  CPU start interrupts
IPI1:          0          0  Timer broadcast interrupts
IPI2:     174690     197747  Rescheduling interrupts
IPI3:          0          0  Function call interrupts
IPI4:       1411       1428  Single function call interrupts
IPI5:          0          0  CPU stop interrupts
IPI6:          0          0  CPU backtrace

Comment 71

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

(In reply to Star Cheng [:scheng] from comment #70)
> Hi, Pooja
> 
> Do you encounter this phenomenon?
> 
> We observe the strange phenomenon about "Rescheduling interrupts" while
> duplicate the STR, and the value is increasing more than 1000. The command
> and result as following:
> 

When kswapd is been executed, Rescheduling interrupts was also increasing significantly. It seems that it increased 1000 per second. I saw it on flame kk build.

Comment 72

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

Next part that bluetooth side will try to tune A2DP HAL/stack:
1. Change maximum Audio buffer size in A2DP HAL
2. Set the media channel as L2CAP high priority
Shall have result in tomorrow morning. Meanwhile, still need to know the reason caused phenomenon  that mentioned in Comment 70.

Comment 73

[KTucker [:KTucker][Inactive 3/4/2016]]

Please ignore comment 67. This test case has been updated in moztrap to cover this issue:

https://moztrap.mozilla.org/manage/case/5762/

Comment 74

[Star Cheng [:scheng]]

(In reply to Shawn Huang [:shuang] [:shawnjohnjr] from comment #72)
> Next part that bluetooth side will try to tune A2DP HAL/stack:
> 1. Change maximum Audio buffer size in A2DP HAL
> 2. Set the media channel as L2CAP high priority
> Shall have result in tomorrow morning. Meanwhile, still need to know the
> reason caused phenomenon  that mentioned in Comment 70.

Shawn and I tried this patch and found a2dp choppiness disappeared totally!
Especially we observed whenever kswapd is executing and system is busy, reduce total time of writing socket can improve significantly. However, not sure how 3072 byte is been chosen.

See:
https://www.codeaurora.org/cgit/quic/la/platform/external/bluetooth/bluedroid/commit/?h=LNX.LF.3.5.1_RB1.2&id=bd95522382f2dd10fe70647865e7c8e4c2584d1c

A2DP HAL: Update maximum Audio buffer size
Due to Audio buffer equal to socket buffer size observed A2dp Chopiness randomly because of socket write blocking for long time. Update maximum Audio buffer size to 3072 bytes.
========
Pooja, would you please apply this patch (since it's from CAF, i believe it's good to go) and try?
We already tested this patch on our flame kk build with gecko v2.0, it works.

Comment 75

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

Let's wait for feedback from Pooja. If that patch can fix problem, move tag this bug as vencom, let CAF cherry-pick fix to b2g-kk branch.

Comment 76

[Pooja]

Thanks Shwan and Star,

I tried  with this fix and  issue  is not reproducible.

Comment 77

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

(In reply to Pooja from comment #76)
> Thanks Shwan and Star,
> 
> I tried  with this fix and  issue  is not reproducible.

Pooja, thanks for sharing this good news. :D

Comment 78

[Eric Chou [:ericchou] [:echou]]

Thanks to Star, Shawn and Pooja for your hard work. :)

Bhavana,

Star and Shawn have found the root cause, and there has been already a CAF patch could solve this problem, which has been verified by Pooja (comment 76). In fact, I' not quite sure what flags or keywords or whiteboards should be set in this case, would you mind helping us with next steps?

Comment 79

[bhavana bajaj [:bajaj]]

(In reply to Eric Chou [:ericchou] [:echou] from comment #78)
> Thanks to Star, Shawn and Pooja for your hard work. :)
> 
> Bhavana,
> 
> Star and Shawn have found the root cause, and there has been already a CAF
> patch could solve this problem, which has been verified by Pooja (comment
> 76). In fact, I' not quite sure what flags or keywords or whiteboards should
> be set in this case, would you mind helping us with next steps?

Thanks guys! Discussed this with ikumar, and he is going to talk to pooja and work with her on getting the CAF branch uplifted to the right branch on their side.

Comment 80

[Inder]

Star/Bhavana -- do we know how we come to find a patch on an unrelated branch that would help here?

Comment 81

[bhavana bajaj [:bajaj]]

(In reply to Inder from comment #80)
> Star/Bhavana -- do we know how we come to find a patch on an unrelated
> branch that would help here?

NI: star to figure out the magic ! :)

Comment 82

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

(In reply to Inder from comment #80)
> Star/Bhavana -- do we know how we come to find a patch on an unrelated
> branch that would help here?

We found bluedroid btif_media_task got underflow problem, and gecko actually write data to Audioflinger. Thus, we suspect there is huge delay bewteen audio_a2dp_hw (producer) to btif_media_task (consumer). We reduce buffer size, and it improve a lot. 
Then I found this patch because there are some discussion in cyanogenmod community.

Comment 83

[Star Cheng [:scheng]]

According to Shawn's explain in comment 82, clear the ni? mark.

Comment 84

[Inder]

Thanks all for finding the fix here. Appreciate all the help.
We are pulling the fix in appropriate branch on CAF.

Comment 85

[Paladin]

Attachment: Verify_video.3gp

This issue has been verified successfully on Flame 2.0,2.1

See attachment: Verify_video.3gp
Reproducing rate: 0/5
Flame 2.0 versions:
Gaia-Rev        8d1e868864c8a8f1e037685f0656d1da70d08c06
Gecko-Rev       https://hg.mozilla.org/releases/mozilla-b2g32_v2_0/rev/c756bd8bf3c3
Build-ID        20141130000204
Version         32.0
Flame 2.1 versions:
Gaia-Rev        ccb49abe412c978a4045f0c75abff534372716c4
Gecko-Rev       https://hg.mozilla.org/releases/mozilla-b2g34_v2_1/rev/18fb67530b22
Build-ID        20141130001203
Version         34.0

Comment 86

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/83bff13e5f70