967581 - [b2g][tarako] keyboard audio is delayed or missing on tarako

Status: RESOLVED FIXED

(Core :: Audio/Video, defect, P1)

Description

[Ben Kelly [:bkelly, not reviewing]]

While typing on tarako the click audio is either missing or delayed.

From the log when we get delayed audio:

02-04 11:43:39.930 V/AudioPolicyManagerBase(   90): startOutput() output 1, stream 1, session 171
02-04 11:43:39.930 V/AudioPolicyManagerBase(   90): changeRefCount() stream 1, count 1
02-04 11:43:39.930 V/AudioPolicyManagerBase(   90): getDeviceForStrategy() from cache strategy 0, device 2
02-04 11:43:39.930 V/AudioPolicyManagerBase(   90): getNewDevice() selected device 2
02-04 11:43:39.930 D/AudioPolicyManagerBase(   90): setOutputDevice() output 1 device 2 delayMs 0
02-04 11:43:39.930 V/AudioPolicyManagerBase(   90): setOutputDevice() setting same device 2 or null device for output 1
02-04 11:43:39.930 E/AudioPolicyManagerBase(   90): checkAndSetVolume stream=1, index=15, output=1, device=2
02-04 11:43:39.930 E/AudioPolicyManagerBase(   90): computeVolume, streamDesc=0x247330
02-04 11:43:39.930 V/AudioPolicyManagerBase(   90): VOLUME vol index=[60 100 100], dB=[-11.0 0.0 0.0] ampl=1.00000
02-04 11:43:40.010 V/AudioPolicyManagerBase(   90): stopOutput() output 1, stream 1, session 171
02-04 11:43:40.010 V/AudioPolicyManagerBase(   90): changeRefCount() stream 1, count 0
02-04 11:43:40.010 V/AudioPolicyManagerBase(   90): getNewDevice() selected device 0
02-04 11:43:40.010 D/AudioPolicyManagerBase(   90): setOutputDevice() output 1 device 0 delayMs 290
02-04 11:43:40.010 V/AudioPolicyManagerBase(   90): setOutputDevice() setting same device 0 or null device for output 1
02-04 11:43:40.020 V/AudioPolicyManagerBase(   90): releaseOutput() 1

It appears to be first selecting device 2 and then ultimately select device 1 which actually produces audio.

Perhaps the phone thinks there are headphones since the device has wires coming out the headphone jack?  Or maybe there is another issue here.  It seems to need more investigation.

Comment 1

[Wayne Chen [:xwaynec]]

Do we have AudioHardware log? Maybe we can get more information from AudioHardware.

The hardware of amplifier needs time to warm up and typing music is short data. 
AudioHardware isn't ready to open amplifier but typing music is already out. So the sound is delayed or missing.

Comment 2

[Keven Kuo [:kkuo]]

Hi! Wayne,

Would you like to take this for your 1st bug in Mozilla?

--
Keven

Comment 3

[Wayne Chen [:xwaynec]]

Hi Ben,

1. Is the missing problem occurring when you press the button after long time (about 3 sec)?

2. what kind of delay do you mean? could you describe more details about the situation?

Thanks

Comment 4

[Wayne Chen [:xwaynec]]

I did some experiments.

1. Don't touch keyboard and wait 3 sec
2. The first sound is always missing
3. But if I touch keyboard in 3 sec, the sound is not missing.

Comment 5

[ying.xu]

@cheng.luo
Please check this

Comment 6

[cheng.luo]

Attachment: 6821_kb.log

Comment 7

[cheng.luo]

Attachment: Screenshot-timeline .png

Comment 8

[cheng.luo]

Attachment: Screenshot-function .png

Comment 9

[cheng.luo]

sorry,I could not found any word about "device 1" in the log.
you can see the AudioHardware log as follow:
02-13 14:39:31.570 I/audio_hw_primary(   91): Changing devices: 0x00000002

I found the hotpot in this scene is not related to the audio from Screenshot-function.png which
was generated by DS-5 tool.

Comment 10

[Wayne Chen [:xwaynec]]

Attachment: Screen Shot 2014-02-13 at 3.16.19 PM.png

Comment 11

[Ben Kelly [:bkelly, not reviewing]]

(In reply to cheng.luo from comment #9)
> sorry,I could not found any word about "device 1" in the log.

Sorry, I should have said device 0 and device 2 in comment 0.

Comment 12

[Wayne Chen [:xwaynec]]

Attachment: audio_out_1.pcm

Comment 13

[Wayne Chen [:xwaynec]]

Reply to cheng.luo

I record pcm raw data from AudioFlinger. The keyboard has two click sound. You can see in "Screen Shot 2014-02-13 at 3.16.19 PM.png", However there is only one sound in target. "audio_out_1.pcm" is the record data.

Comment 14

[cheng.luo]

(In reply to Wayne Chen [:xwaynec] from comment #4)
> I did some experiments.
1. Don't touch keyboard and wait 3 sec
2. The first
> sound is always missing
3. But if I touch keyboard in 3 sec, the sound is
> not missing.

after 3 sec,it was in standby mode.
Maybe is a bug of driver.

Comment 15

[Ben Kelly [:bkelly, not reviewing]]

I believe Wayne and I spoke in person about this earlier in the week.

Comment 16

[Wayne Chen [:xwaynec]]

I think this issue can be split into 3 parts.

1. Cold start of first sound will missing.
 -> This is a partner driver issue.

2. Typing keyboard continuously will cause that CPU utilization is too high. Then the sound will be choppy and delayed. The following is captured by Linux top command. and attachment[Screen Shot 2014-02-13 at 3.13.15 PM] is the situation for choppy sound.

User 75%, System 24%, IOW 0%, IRQ 0%
User 84 + Nice 4 + Sys 28 + Idle 0 + IOW 0 + IRQ 0 + SIRQ 0 = 116

  PID   TID PR CPU% S     VSS     RSS PCY UID      Thread          Proc
   82    82  0  47% S 142972K  40448K  fg root     b2g             /system/b2g/b2g
 3067  3067  0  20% S  55944K   2804K  fg root     (Preallocated a /system/b2g/plugin-container
 3545  3545  0   6% R   1056K    468K  fg root     top             top
  342   342  0   5% S  52880K   3056K  fg root     (Nuwa)          /system/b2g/plugin-container
 1003  1003  0   2% R  63224K  19736K  fg app_1003 Messages        /system/b2g/plugin-container
   82   324  0   2% S 142972K  40448K  fg root     Compositor      /system/b2g/b2g
 2853  2853  0   1% S    768K    332K  fg root     oom-msg-logger  /system/bin/sh
   55    55  0   0% S      0K      0K unk root     irq/98-ms-msg21 
   82  3567  0   0% S 142972K  40448K  fg root     Indexed~ans #74 /system/b2g/b2g
   82   303  0   0% S 142972K  40448K  fg root     Gecko_IOThread  /system/b2g/b2g

3. Sometimes typing keyboard continuously, there are some sound will disappear. I record pcm data from AudioFlinger, the data seems not coming. 

I think this bug is to focus on (1) and then I create another two issues to follow (2) bug 972774 & (3) bug 972776.

Comment 17

[Wayne Chen [:xwaynec]]

Attachment: Screen Shot 2014-02-13 at 3.13.15 PM.png

Comment 18

[Wayne Chen [:xwaynec]]

Exact different issues from this one (comment 16), so this issue only needs to be solved by partner (comment 14).

Comment 19

[James Zhang (Spreadtrum)]

We will take audio missing issue, but mozilla should take audio delaying issue.

Comment 20

[Mason Chang [Inactive] [:mchang]]

Triage: From our tarako work week, it was causing a large performance issue. We decided to disable many of the keyboard features including audio, auto suggest, and word suggestions.

Comment 21

[Steven Yang [:styang]]

Hi Marvin, need your input from Product point of view. Thanks!

Comment 22

[Ben Kelly [:bkelly, not reviewing]]

I thought disabling audio was just for the demo.  Are we going to prevent the user from turning it on in the release build?

Comment 23

[Marvin Khoo [:Marvin_Khoo]]

Android do have this audio function /opt, so we need to get them fix.

Comment 24

[Marvin Khoo [:Marvin_Khoo]]

Android default is ON. fyi.

Comment 25

[Marvin Khoo [:Marvin_Khoo]]

Hi Ben,
I just jump in and verify this bug on Build:20140218141551 assume this built is 2014 Feb 18 one.
https://bugzilla.mozilla.org/show_bug.cgi?id=967581

and notice the audio works well in this build, but i only enable audio and turn off others.

to me, seems like this one can be close, however i notice the display a bit slower shall we track this in another bug instead? 

thanks!

BR,
Marvin

Comment 26

[Wayne Chen [:xwaynec]]

Hi Ben,

This issue has two parts, missing problem should be solved by Spreadtrum (comment 19).
The another part (delay problem) should be solved after this commit (https://bugzilla.mozilla.org/show_bug.cgi?id=971651#c25). I'm not sure why I can't see it now.
If using the image after MWC, click sound should be ok.

Thanks

Sincerely,
Wayne

Comment 27

[Andreas Gal :gal]

Wayne, if Mozilla has no work to do here and the rest is with the partner please assign someone from SPRD to this bug for clarity.

Comment 28

[James Zhang (Spreadtrum)]

dafeng will take it.

Comment 29

[Joe Cheng [:jcheng] (please needinfo)]

1.3T+

Comment 30

[Joe Cheng [:jcheng] (please needinfo)]

Hi Dafeng, can you please update on where things are with this bug? does the latest partner image has the fix? if so, our QA will reconfirm. thanks

Comment 31

[Joe Cheng [:jcheng] (please needinfo)]

ni? James as well

Comment 32

[James Zhang (Spreadtrum)]

Sorry, no progress now.

Comment 33

[Joe Cheng [:jcheng] (please needinfo)]

hi James, wonder if there are any further update? thanks

Comment 34

[James Zhang (Spreadtrum)]

It's audio hal issue.
Dafeng will update the status.

Comment 35

[Keven Kuo [:kkuo]]

Hi! James,

Any progress?

--
Keven

Comment 36

[James Zhang (Spreadtrum)]

If tarako use fugu audio hal, tarako still has this issue, but fugu hasn't. And the difference between tarako and fugu is audio codec in kernel, we keep on debugging.

Comment 37

[James Zhang (Spreadtrum)]

The hardware is different, so tarako and fugu must use its own codec.

Comment 38

[James Zhang (Spreadtrum)]

We dump tone ogg from audio hal, the ogg data is empty. It's not audio hal and kerenl issue, maybe gecko and omxcodec issue.
Is any gecko audio expert here?

Comment 39

[Joe Cheng [:jcheng] (please needinfo)]

Star, can you take a look at this one? thanks

Comment 40

[Chris Pearce [:cpearce (Not reading bugmail)]]

You could try transcoding the Ogg sounds to WAV. Wave decodes much faster than Ogg/Vorbis (and Ogg/Opus). If sound is still delayed when we've switched to WAV, the problem must be outside of MediaDecoder. Maybe in libcubeb perhaps.

Comment 41

[Wayne Chen [:xwaynec]]

Attachment: Screen Shot 2014-03-19 at 5.08.42 PM.png

Comment 42

[Wayne Chen [:xwaynec]]

Attachment: 20140319_audio_out.pcm

Comment 43

[Wayne Chen [:xwaynec]]

Hi James,

I used message app to do experiment. Attachment 8393374 [details] is the pcm raw data recorded in audio_hw.cpp and attachment 8393372 [details] is the screenshot. This is yesterday build image. 

1. I touched the keyboard 8 times
2. The screenshot also has 8 pulse, however the sounds only appear 6 times.

The 2 missing sounds happened after AudioHardware is standby 3 secs. I think maybe audio driver launch time is too long?

Sincerely,
Wayne

Comment 44

[Dafeng Xu]

Audioflinger will delay 3 secs enter standby mode after all Audiotrack stopped. 
I see the log and find that the audio flinger can not have chance to deal audio track buffer because it receive a stop commond from gecko, you can see the log:

 01-01 05:30:42.880 E/AudioTrack(   80): IN AudioTrack::AudioTrack() 
01-01 05:30:42.880 V/AudioFlinger(   85): createTrack() sessionId: 5
01-01 05:30:42.880 V/AudioFlinger(   85): createTrack() lSessionId: 5
01-01 05:30:42.880 V/AudioFlinger(   85): Track constructor name 4096, calling thread 80
01-01 05:30:42.880 V/AudioFlinger(   85): acquiring 5 from 80
01-01 05:30:42.880 V/AudioFlinger(   85):  added new entry for 5
01-01 05:30:42.880 E/AudioTrack(   80): AudioTrack::start 0x45e59a80
01-01 05:30:42.880 V/AudioTrack(   80): start 0x45e59a80
01-01 05:30:42.880 V/AudioTrack(   80): start 0x45e59a80 before lock cblk 0x45600000
01-01 05:30:42.880 V/AudioFlinger(   85): start(4096), calling thread 80 session 5
01-01 05:30:42.880 V/AudioFlinger(   85): ? => ACTIVE (4096) on thread 0xdf6e48
01-01 05:30:42.890 V/AudioFlinger(   85): mWaitWorkCV.broadcast
01-01 05:30:42.890 V/AudioFlinger(   85): MixerThread 0xdeaec8 TID 188 waking up
01-01 05:30:42.890 W/AudioFlinger(   85): Thread AudioOut_1 cannot connect to the power manager service
01-01 05:30:42.890 W/AudioFlinger(   85): prepareTracks_l(): track 00001000 , 0 ,0,0,0 ,,,0,0,1
01-01 05:30:42.890 E/AudioTrack(   80): AudioTrack::start 0x45e59a80
01-01 05:30:42.890 V/AudioTrack(   80): start 0x45e59a80
01-01 05:30:42.900 V/AudioTrack(   80): Underrun user: 0, server: 0, flags 0003
01-01 05:30:42.900 W/AudioFlinger(   85): prepareTracks_l(): track 00001000 , 0 ,0,1,0 ,,,1,6965,1
01-01 05:30:42.900 V/AudioFlinger(   85): track 4096 u=00001b35, s=00000000 [OK] on thread 0xdeaec8
01-01 05:30:42.900 E/audio_hw_primary(   85): In audio_hw.c::out_write, bytes = 6400 
01-01 05:30:42.900 I/audio_hw_primary(   85): select_devices_signal starting...
01-01 05:30:42.900 I/audio_hw_primary(   85): select_devices_signal finished.
01-01 05:30:42.900 W/audio_hw_primary(   85): open s_tinycard in
01-01 05:30:42.910 W/audio_hw_primary(   85): open s_tinycard successfully
01-01 05:30:42.910 I/audio_hw_primary(   85): Changing devices: 0x00000002
01-01 05:30:42.910 I/audio_hw_primary(   85): Set 'HeadPhone Function'.0 to 0
01-01 05:30:42.910 I/audio_hw_primary(   85): Set 'Earpiece Function'.0 to 0
01-01 05:30:42.910 I/audio_hw_primary(   85): Set 'Mic Function'.0 to 0
01-01 05:30:42.910 I/audio_hw_primary(   85): Set 'HP Mic Function'.0 to 0
01-01 05:30:42.910 I/audio_hw_primary(   85): Set 'Line Function'.0 to 0
01-01 05:30:42.910 I/audio_hw_primary(   85): Changing devices, mask: 0x00004002
01-01 05:30:42.910 I/audio_hw_primary(   85): Set 'Speaker Function'.0 to 1
01-01 05:30:42.910 W/audio_hw_primary(   85): GetAudio_pga_nv, dac_pga_gain_l:0xc3 adc_pga_gain_l:0xc fm_pga_gain_l:0xff fm_pga_gain_r:0xff device:0x2 vol_level:0x1 
01-01 05:30:42.910 V/AudioTrack(   80): stop 0x45e59a80
01-01 05:30:42.910 V/AudioFlinger(   85): stop(4096), calling thread 80
01-01 05:30:42.910 V/AudioFlinger(   85): (> STOPPED) => STOPPED (4096) on thread 0xdeaec8
01-01 05:30:42.910 V/AudioTrack(   80): stop 0x45e59a80
01-01 05:30:42.910 V/AudioTrack(   80): stop 0x45e59a80

Comment 45

[Dafeng Xu]

Audioflinger will delay 3 secs enter standby mode after all Audiotrack stopped. 
I see the log and find that the audio flinger can not have chance to deal audio track buffer because it receive a stop commond from gecko, you can see the log:

 01-01 05:30:42.880 E/AudioTrack(   80): IN AudioTrack::AudioTrack() 
01-01 05:30:42.880 V/AudioFlinger(   85): createTrack() sessionId: 5
01-01 05:30:42.880 V/AudioFlinger(   85): createTrack() lSessionId: 5
01-01 05:30:42.880 V/AudioFlinger(   85): Track constructor name 4096, calling thread 80
01-01 05:30:42.880 V/AudioFlinger(   85): acquiring 5 from 80
01-01 05:30:42.880 V/AudioFlinger(   85):  added new entry for 5
01-01 05:30:42.880 E/AudioTrack(   80): AudioTrack::start 0x45e59a80
01-01 05:30:42.880 V/AudioTrack(   80): start 0x45e59a80
01-01 05:30:42.880 V/AudioTrack(   80): start 0x45e59a80 before lock cblk 0x45600000
01-01 05:30:42.880 V/AudioFlinger(   85): start(4096), calling thread 80 session 5
01-01 05:30:42.880 V/AudioFlinger(   85): ? => ACTIVE (4096) on thread 0xdf6e48
01-01 05:30:42.890 V/AudioFlinger(   85): mWaitWorkCV.broadcast
01-01 05:30:42.890 V/AudioFlinger(   85): MixerThread 0xdeaec8 TID 188 waking up
01-01 05:30:42.890 W/AudioFlinger(   85): Thread AudioOut_1 cannot connect to the power manager service
01-01 05:30:42.890 W/AudioFlinger(   85): prepareTracks_l(): track 00001000 , 0 ,0,0,0 ,,,0,0,1
01-01 05:30:42.890 E/AudioTrack(   80): AudioTrack::start 0x45e59a80
01-01 05:30:42.890 V/AudioTrack(   80): start 0x45e59a80
01-01 05:30:42.900 V/AudioTrack(   80): Underrun user: 0, server: 0, flags 0003
01-01 05:30:42.900 W/AudioFlinger(   85): prepareTracks_l(): track 00001000 , 0 ,0,1,0 ,,,1,6965,1
01-01 05:30:42.900 V/AudioFlinger(   85): track 4096 u=00001b35, s=00000000 [OK] on thread 0xdeaec8
01-01 05:30:42.900 E/audio_hw_primary(   85): In audio_hw.c::out_write, bytes = 6400 
01-01 05:30:42.900 I/audio_hw_primary(   85): select_devices_signal starting...
01-01 05:30:42.900 I/audio_hw_primary(   85): select_devices_signal finished.
01-01 05:30:42.900 W/audio_hw_primary(   85): open s_tinycard in
01-01 05:30:42.910 W/audio_hw_primary(   85): open s_tinycard successfully
01-01 05:30:42.910 I/audio_hw_primary(   85): Changing devices: 0x00000002
01-01 05:30:42.910 I/audio_hw_primary(   85): Set 'HeadPhone Function'.0 to 0
01-01 05:30:42.910 I/audio_hw_primary(   85): Set 'Earpiece Function'.0 to 0
01-01 05:30:42.910 I/audio_hw_primary(   85): Set 'Mic Function'.0 to 0
01-01 05:30:42.910 I/audio_hw_primary(   85): Set 'HP Mic Function'.0 to 0
01-01 05:30:42.910 I/audio_hw_primary(   85): Set 'Line Function'.0 to 0
01-01 05:30:42.910 I/audio_hw_primary(   85): Changing devices, mask: 0x00004002
01-01 05:30:42.910 I/audio_hw_primary(   85): Set 'Speaker Function'.0 to 1
01-01 05:30:42.910 W/audio_hw_primary(   85): GetAudio_pga_nv, dac_pga_gain_l:0xc3 adc_pga_gain_l:0xc fm_pga_gain_l:0xff fm_pga_gain_r:0xff device:0x2 vol_level:0x1 
01-01 05:30:42.910 V/AudioTrack(   80): stop 0x45e59a80
01-01 05:30:42.910 V/AudioFlinger(   85): stop(4096), calling thread 80
01-01 05:30:42.910 V/AudioFlinger(   85): (> STOPPED) => STOPPED (4096) on thread 0xdeaec8
01-01 05:30:42.910 V/AudioTrack(   80): stop 0x45e59a80
01-01 05:30:42.910 V/AudioTrack(   80): stop 0x45e59a80

Comment 46

[Wayne Chen [:xwaynec]]

Attachment: Screen Shot 2014-03-20 at 10.18.27 AM.png

Comment 47

[Wayne Chen [:xwaynec]]

Hi Danfeng,

I think AudioFlinger is correct because the data size of keyboard click sound is very tiny(0.002 sec attachment 8393919 [details]). We actually need to confirm when is the open and close time of audio hardware. This log shows that audio_hw starts to play sounds in 01:09:50.360 and enters standby mode after 3 sec (01:09:53.510). 

I wanna ask that does audio need to spend more time in each open scenario? Becuase the click sound is only 0.002 sec and each missing problem happened in first time.

Thanks

01-02 01:09:50.210 V/AudioPolicyManagerBase(   86): getDeviceForStrategy() from cache strategy 0, device 2
01-02 01:09:50.210 V/AudioPolicyManagerBase(   86): getOutput() stream 1, samplingRate 0, format 0, channels 3, flags 0
01-02 01:09:50.220 V/AudioPolicyManagerBase(   86): startOutput() output 1, stream 1, session 2
01-02 01:09:50.220 V/AudioPolicyManagerBase(   86): startReadingThread
01-02 01:09:50.220 V/AudioPolicyManagerBase(   86): changeRefCount() stream 1, count 1
01-02 01:09:50.220 V/AudioPolicyManagerBase(   86): getDeviceForStrategy() from cache strategy 0, device 2
01-02 01:09:50.220 V/AudioPolicyManagerBase(   86): getNewDevice() selected device 2
01-02 01:09:50.220 D/AudioPolicyManagerBase(   86): setOutputDevice() output 1 device 2 delayMs 0
01-02 01:09:50.220 V/AudioPolicyManagerBase(   86): setOutputDevice() setting same device 2 or null device for output 1
01-02 01:09:50.220 E/AudioPolicyManagerBase(   86): checkAndSetVolume stream=1, index=15, output=1, device=2
01-02 01:09:50.220 E/AudioPolicyManagerBase(   86): computeVolume, streamDesc=0x1763bb8
01-02 01:09:50.220 V/AudioPolicyManagerBase(   86): VOLUME vol index=[60 100 100], dB=[-11.0 0.0 0.0] ampl=1.00000
01-02 01:09:50.230 V/AudioPolicyManagerBase(   86): ThreadWrapper 0x1763b40
01-02 01:09:50.230 V/AudioPolicyManagerBase(   86): threadFunc in
01-02 01:09:50.240 W/AudioFlinger(   86): Thread AudioOut_1 cannot connect to the power manager service
01-02 01:09:50.240 V/AudioPolicyManagerBase(   86): stopOutput() output 1, stream 1, session 2
01-02 01:09:50.240 V/AudioPolicyManagerBase(   86): stopReadingThread
01-02 01:09:50.310 I/Gecko   (   81): ContactDB: 'contains' only works for 'tel'. Falling back to 'startsWith'.
01-02 01:09:50.310 I/Gecko   (   81): ContactDB: 'contains' only works for 'tel'. Falling back to 'startsWith'.
01-02 01:09:50.330 V/AudioPolicyManagerBase(   86): threadFunc exit
01-02 01:09:50.330 V/AudioPolicyManagerBase(   86): changeRefCount() stream 1, count 0
01-02 01:09:50.330 V/AudioPolicyManagerBase(   86): getNewDevice() selected device 0
01-02 01:09:50.330 D/AudioPolicyManagerBase(   86): setOutputDevice() output 1 device 0 delayMs 290
01-02 01:09:50.330 V/AudioPolicyManagerBase(   86): setOutputDevice() setting same device 0 or null device for output 1
01-02 01:09:50.340 V/AudioPolicyManagerBase(   86): startOutput() output 1, stream 1, session 2
01-02 01:09:50.340 V/AudioPolicyManagerBase(   86): changeRefCount() stream 1, count 1
01-02 01:09:50.340 V/AudioPolicyManagerBase(   86): getDeviceForStrategy() from cache strategy 0, device 2
01-02 01:09:50.340 V/AudioPolicyManagerBase(   86): getNewDevice() selected device 2
01-02 01:09:50.340 D/AudioPolicyManagerBase(   86): setOutputDevice() output 1 device 2 delayMs 0
01-02 01:09:50.340 V/AudioPolicyManagerBase(   86): setOutputDevice() setting same device 2 or null device for output 1
01-02 01:09:50.340 E/AudioPolicyManagerBase(   86): checkAndSetVolume stream=1, index=15, output=1, device=2
01-02 01:09:50.340 E/AudioPolicyManagerBase(   86): computeVolume, streamDesc=0x1763bb8
01-02 01:09:50.340 V/AudioPolicyManagerBase(   86): VOLUME vol index=[60 100 100], dB=[-11.0 0.0 0.0] ampl=1.00000
01-02 01:09:50.360 I/audio_hw_primary(   86): select_devices_signal starting...
01-02 01:09:50.360 I/audio_hw_primary(   86): select_devices_signal finished.
01-02 01:09:50.360 W/audio_hw_primary(   86): open s_tinycard in
01-02 01:09:50.360 W/audio_hw_primary(   86): open s_tinycard successfully
01-02 01:09:50.360 I/audio_hw_primary(   86): Changing devices: 0x00000002
01-02 01:09:50.360 I/audio_hw_primary(   86): Set 'HeadPhone Function'.0 to 0
01-02 01:09:50.360 I/audio_hw_primary(   86): Set 'Earpiece Function'.0 to 0
01-02 01:09:50.360 I/audio_hw_primary(   86): Set 'Mic Function'.0 to 0
01-02 01:09:50.360 I/audio_hw_primary(   86): Set 'HP Mic Function'.0 to 0
01-02 01:09:50.360 I/audio_hw_primary(   86): Set 'Line Function'.0 to 0
01-02 01:09:50.360 I/audio_hw_primary(   86): Changing devices, mask: 0x00004002
01-02 01:09:50.490 I/audio_hw_primary(   86): Set 'Speaker Function'.0 to 1
01-02 01:09:50.490 V/AudioPolicyManagerBase(   86): stopOutput() output 1, stream 1, session 2
01-02 01:09:50.490 V/AudioPolicyManagerBase(   86): changeRefCount() stream 1, count 0
01-02 01:09:50.490 V/AudioPolicyManagerBase(   86): getNewDevice() selected device 0
01-02 01:09:50.490 D/AudioPolicyManagerBase(   86): setOutputDevice() output 1 device 0 delayMs 290
01-02 01:09:50.490 V/AudioPolicyManagerBase(   86): setOutputDevice() setting same device 0 or null device for output 1
01-02 01:09:50.490 W/audio_hw_primary(   86): GetAudio_pga_nv, dac_pga_gain_l:0xc3 adc_pga_gain_l:0xc fm_pga_gain_l:0xff fm_pga_gain_r:0xff device:0x2 vol_level:0x1
01-02 01:09:50.500 V/AudioPolicyManagerBase(   86): releaseOutput() 1
01-02 01:09:50.500 D/audio_pga(   86): 'speaker-l' apply
01-02 01:09:50.500 I/audio_pga(   86): 'Master Playback Volume' set to 12
01-02 01:09:50.510 I/audio_pga(   86): 'Inter PA Playback Volume' set to 12
01-02 01:09:50.510 I/audio_pga(   86): 'VBC DACL DG Set' set to 0
01-02 01:09:50.510 I/audio_pga(   86): 'VBC DACL DG Switch' set to 0
01-02 01:09:50.510 D/audio_pga(   86): 'speaker-r' apply
01-02 01:09:50.510 I/audio_pga(   86): 'Master Playback Volume' set to 12
01-02 01:09:50.510 I/audio_pga(   86): 'Inter PA Playback Volume' set to 12
01-02 01:09:50.510 I/audio_pga(   86): 'VBC DACR DG Set' set to 0
01-02 01:09:50.510 I/audio_pga(   86): 'VBC DACR DG Switch' set to 0
01-02 01:09:50.510 W/audio_hw_primary(   86): SetAudio_gain_by_devices out, devices:0x2
01-02 01:09:50.510 I/audio_hw_primary(   86): stream_routing_thread looping done.
01-02 01:09:50.510 I/audio_hw_primary(   86): stream_routing_thread looping now...
01-02 01:09:53.510 W/audio_hw_primary(   86): do_output_standby.mode:0

Sincerely,
Wayne

Comment 48

[Dafeng Xu]

Hi Wayne,
    The audio need to spend more time in each open scenario.

Comment 49

[Dafeng Xu]

    because the click sound is very tiny, when audiotrack prepare buffer to send to audioflinger, the decoder thread is end, so it send the stop signal to audioflinger, the audioflinger do not deal the data from audiotrack, so the first key sound is missed.
    I try to reduse the buffer's size that transfer data from audiotrack to audioflinger, the situation has improved.

Comment 50

[Andreas Gal :gal]

We can fill the buffer with dummy data after the actual audio.

Comment 51

[Dafeng Xu]

Yes, I just want to write zero data to ogg file to make it longer.

Comment 52

[James Zhang (Spreadtrum)]

I don't think it's spreadtrum POVB issue. It's gecko issue.
We found hamachi on v1.3 branch also has the similar issue, no touch panel sound whether audio touch tones is short or long.

Comment 53

[Star Cheng [:scheng]]

│ Your Target Build: PVT.v130.hamachi                                      │
│ URL:                                                                     │
│ https://pvtbuilds.mozilla.org/pvt/mozilla.org/b2gotoro/nightly/mozilla-a │
│ urora-hamachi-eng/latest/                                                │
│ ENG Ver: true                                                            │
│ Flash: Full Image.                                                       │
│                                                                          │
│ Gaia      53edbf08b0a750c31e8c6b2c20f2b1315b1412d1                       │
│ Gecko                                                                    │
│ https://hg.mozilla.org/releases/mozilla-aurora/rev/9b482d6994fd          │
│ BuildID   20140320160207                                                 │
│ Version   30.0a2                                                         │
│ ro.build.version.incremental=eng.cltbld.20140320.192530                  │
│ ro.build.date=Thu Mar 20 19:25:43 EDT 2014  


I have flashed v1.3 SW on hamachi device. And followings below steps:

1.launch settings app and select keyboard item in setting menu.
2.enter "Built-in keyboard" item and check "Click sound" 
3.press home key and launch message app
4.try to select some english letter through touching the virtual keyboard on the screen 

I can hear the click sound despite waiting for 4 seconds or more.

Comment 54

[Chris Pearce [:cpearce (Not reading bugmail)]]

(In reply to Andreas Gal :gal from comment #50)
> We can fill the buffer with dummy data after the actual audio.

This is similar to problems we used to get on other platforms, where we'd not write enough audio samples to the audio hardware and so audio playback would not start. I thought libcubeb or mozilla::AudioStream should already ensure enough audio samples are written to the audio device for playback to start. padenot? Matthew?

When I enable keyboard click sounds on Tarako with branch=1.3t, the only keyboard click sound that fails to play is the first. Click sounds for keypresses after the first play fine. If I wait a while, I hear a click (which sounds like the audio speaker being turned off), and then on the next keypress the keyboard click sound fails to play, but all keypresses after that play click sounds as expected.

When using a custom-gecko of mozilla-central, I lots of sounds are dropped (silent).

(In reply to Dafeng Xu from comment #51)
> Yes, I just want to write zero data to ogg file to make it longer.

This will not fix the bug. Other short sounds will still have this problem. We should fix the bug, not work around it.

Comment 55

[Andreas Gal :gal]

We shouldn't emit silence to the ogg file. Instead we should simply write more zeros at the end of the playback but as cpearce says why isn't the audio layer doing that already?

Comment 56

[Paul Adenot (:padenot)]

(In reply to Chris Pearce (:cpearce) from comment #54)
> (In reply to Andreas Gal :gal from comment #50)
> > We can fill the buffer with dummy data after the actual audio.
> 
> This is similar to problems we used to get on other platforms, where we'd
> not write enough audio samples to the audio hardware and so audio playback
> would not start. I thought libcubeb or mozilla::AudioStream should already
> ensure enough audio samples are written to the audio device for playback to
> start. padenot? Matthew?

We don't have this problem anymore. However, what can happen is that the audio subsystem is slow to start because it got shut down by the system (to save energy or the like), and it takes a little while to come back up. The logic in MediaDecoderStateMachine, when it sees that it can't get an audio clock because the stream is slow to start, synthesizes a fake audio clock from mozilla::Timestamp, and before the AudioStream is started, the sound ends (because they are only little clicks). On the second and subsequent presses, the audio subsystem is already up and running, so we hear the sounds correctly.

Short of having a device to poke at, I'm not sure why, when flashing a custom gecko, sounds are dropped. I don't think we changed anything to the low level audio playback layer recently, but I might be misremembering.

Anyway, what we can try here is to warm up the audio stack before we want to play anything. That can be done by creating a AudioContext (and at least one node, like a GainNode so no sound is output, to not run into the fix for bug 952893) we would release when we do the first touch on the keyboard. We should try this before investigating more.

Reading the file keyboard.js, that would be something along the lines of:

(...)
var ac = null;
(...)

function initKeyboard () {
  (...)  
   ac = new AudioContext();
   ac.gain = ac.createGain(); 
  (...)
}

function triggerFeedback(isSpecialKey) {
  if (ac) {
    ac = null;
  }
  (...)
}


(In reply to Andreas Gal :gal from comment #55)
> We shouldn't emit silence to the ogg file. Instead we should simply write
> more zeros at the end of the playback but as cpearce says why isn't the
> audio layer doing that already?

Not in the case of <audio>: the audio stream is simply stopped when we know we have play the last sample (the term is "draining" the stream). Here, we want the opposite: keep the stream alive. This is a job for Web Audio, but it is not ready yet for this exact scenario, but this is being worked on. Maybe just keeping an AudioContext around when we have the keyboard open would be a good enough first step?

Comment 58

[Chris Pearce [:cpearce (Not reading bugmail)]]

(In reply to Paul Adenot (:padenot) from comment #56)
> Anyway, what we can try here is to warm up the audio stack before we want to
> play anything. That can be done by creating a AudioContext (and at least one
> node, like a GainNode so no sound is output, to not run into the fix for bug
> 952893) we would release when we do the first touch on the keyboard. We
> should try this before investigating more.

I tried this, and it prevents the first keypress from being dropped. Other keypresses still sometimes drop.

Comment 59

[James Zhang (Spreadtrum)]

Thanks for Wayen great help.
We fix this bug on my side now.

commit 0df5a7201c121ad4bfec923d77b0cce094a27f9e
Author: zhenfang.wang <[e-mail]>
Date:   Thu Apr 3 17:38:16 2014 -0400

    Bug #279433 Update dolphin driver, add 20ms delay in dac path and remove digital mute.
    
    [bug number  ]
    [root cause  ]
    [changes     ]
    [side effects]
    [reviewers   ]
    [self test   ] test ok
    
    Change-Id: I0659d1c4a0eb854986ac758a1b84c7c4bbcbeb02

Comment 60

[Wayne Chen [:xwaynec]]

James, you're welcome. :)

Comment 61

[James Zhang (Spreadtrum)]

(In reply to Wayne Chen [:xwaynec] from comment #60)
> James, you're welcome. :)

You'll come back ;)

Comment 62

[Derek Harris [:DerekH] - Dont need info. Last day 6/5/15]

This is verified fixed on today's build due to 'Click sounds' being removed. This is related to bug 989268


1.3t Environmental Variables:
Device: Tarako 1.3t
BuildID: 20140501014002
Gaia: d26a776beae0070b0032248a2ce482bbe6321a6d
Gecko: e90f4b655511
Version: 28.1
Firmware Version: sp6821