1017438 - [dolphin][flame] The audio play for amr file(smaller than 1KB) is not clear. It sounds like some parts was cut off

Status: RESOLVED FIXED

(Core :: Audio/Video, defect)

Description

[Peipei Cheng (needinfo if you need my action)]

Attachment: 1k.amr

Steps to reproduce
----------------------------------------------------------------
1. Download attached audio file and put into SD card
2. Launch Music and Select the audio to play
   --> The audio of this file is not clear. It sounds like fades away immediately when it start playing.

This is reproducible on Flame and Dolphin. (Tarako does not have this problem.)

Comment 1

[James Zhang (Spreadtrum)]

Add 'usleep' can fix this issue.

--- a/content/media/MediaDecoderStateMachine.cpp
+++ b/content/media/MediaDecoderStateMachine.cpp
@@ -11,6 +11,7 @@
 
 #include "mozilla/DebugOnly.h"
 #include <stdint.h>
+#include <unistd.h>
 
 #include "MediaDecoderStateMachine.h"
 #include "AudioStream.h"
@@ -936,6 +937,7 @@ void MediaDecoderStateMachine::AudioLoop()
     // Must hold lock while shutting down and anulling the audio stream to prevent
     // state machine thread trying to use it while we're destroying it.
     ReentrantMonitorAutoEnter mon(mDecoder->GetReentrantMonitor());
+    usleep(1000*1000);
     mAudioStream->Shutdown();
     mAudioStream = nullptr;
     mEventManager.Clear();

Comment 2

[Jason Smith [:jsmith]]

Does this reproduce on 1.3 Flame?

Comment 3

[Jason Smith [:jsmith]]

(In reply to Jason Smith [:jsmith] from comment #2)
> Does this reproduce on 1.3 Flame?

Also - can we get a video?

Comment 4

[Lionel Mauritson]

> can we get a video?

Video: http://youtu.be/O841fJjg_5s

The audio clip does not play fully or is interrupted. Sometimes (~1/5) a voice can be heard for a moment after the clip starts, but most of the time there is just a clicking sound when played.

Build used for video:
Device: Flame
Build ID: 20140530000202
Gaia: fe612fd21389193a8e593aa718831602e5086a62
Gecko: 25011f9a8f26
Version: 30.0 (1.4) 
Firmware Version: v10G-2

> Does this reproduce on 1.3 Flame?

On 1.3 (Base) the voice part of the clip is heard more often (~3/5) than on the 1.4 build, but otherwise the issue is the same.

Device: Flame
Build ID: 20140520094859
Gaia: a73235d23685e9898f40647cebd83b3fcbfd0117
Gecko: b637b0677e15318dcce703f0358b397e09b018af
Version: 28.0 (1.3) 
Firmware Version: v10G-2

Comment 5

[Jason Smith [:jsmith]]

Ok - so that implies the severity of the bug got worse between 1.3 --> 1.4, so that makes this still a regression.

Comment 6

[Lionel Mauritson]

Going from the 1.3 base to the earliest 1.4 I have access to the severity increases dramatically and the voice becomes rarely heard.

Device: Flame
BuildID: 20140417000006
Gaia: 7591e9dc782ac2e97d63a96f9deb71c7b3588328
Gecko: e71ed4135461
Version: 31.0a1  
Firmware Version: v10G-2

Comment 7

[Bruce Sun [:brsun]]

Attachment: bug1017438_audio_tail_cut_off.patch

Even all the audio data have been consumed in AudioStream::DataCallback() by libcubeb, the audio back-end still needs time to output the audio. Because there is no APIs to get the exact mapping between the audio sound and the audio position in the stream, we have to guess a proper duration to wait before closing AudioStream.

On my dolphin device (with 1.4 gecko), |mAudioEndTime - GetMediaTime()| of 1k.amr is roughly 400ms after AudioStream::Drain(), and it sounds OK by waiting for such period.

On my flame device (with master mecko), |mAudioEndTime - GetMediaTime()| of 1k.amr is always 0ms after AudioStream::Drain(), so there is no improvement by simply waiting for such period. I guess |AudioStream::GetPositionInFramesUnlocked()| could be refined so that we could have a more conservative position value instead of a optimistic one.
 - http://dxr.mozilla.org/mozilla-central/source/content/media/AudioStream.cpp#784

Any comments will be appreciated.

Comment 8

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

I'll let Matthew or Paul answer this, it's more their area of expertise than mine.

Comment 9

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

Comment on attachment 8433268 [details] [diff] [review]
bug1017438_audio_tail_cut_off.patch

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

I'll let Matthew and/or Paul handle this.

Comment 10

[Matthew Gregan [:kinetik]]

Comment on attachment 8433268 [details] [diff] [review]
bug1017438_audio_tail_cut_off.patch

f- because the correct fix is making Drain() behave like it is expected to.

(In reply to Bruce Sun [:brsun] from comment #7)
> Created attachment 8433268 [details] [diff] [review]
> bug1017438_audio_tail_cut_off.patch
> 
> Even all the audio data have been consumed in AudioStream::DataCallback() by
> libcubeb, the audio back-end still needs time to output the audio. Because
> there is no APIs to get the exact mapping between the audio sound and the
> audio position in the stream, we have to guess a proper duration to wait
> before closing AudioStream.

We shouldn't need to guess.  It is signalled by AudioStream::StateCallback being called with CUBEB_STATE_DRAINED.  If that's happening too early, we should fix that directly.

> On my dolphin device (with 1.4 gecko), |mAudioEndTime - GetMediaTime()| of
> 1k.amr is roughly 400ms after AudioStream::Drain(), and it sounds OK by
> waiting for such period.

I'm not clear on which version of Android and Gecko are involved here.  For this and the Flame device, can you confirm which libcubeb backend is in use?  It'll either be cubeb_audiotrack or cubeb_opensl.  I would've expected both of them to be using cubeb_opensl, although it sounds like drain is behaving differently on each device.

Comment 11

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8433268 [details] [diff] [review]
bug1017438_audio_tail_cut_off.patch

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

::: content/media/MediaDecoderStateMachine.cpp
@@ +946,5 @@
>        }
> +      if (mState != DECODER_STATE_SEEKING && mState != DECODER_STATE_SHUTDOWN) {
> +        int64_t compensated_latency = mAudioEndTime - GetMediaTime();
> +        if (compensated_latency > 0) {
> +          Wait(compensated_latency);

Isn't that Wait() is already handled in http://dxr.mozilla.org/mozilla-central/source/content/media/MediaDecoderStateMachine.cpp#928?

Comment 12

[Bruce Sun [:brsun]]

(In reply to JW Wang [:jwwang] from comment #11)
> Isn't that Wait() is already handled in
> http://dxr.mozilla.org/mozilla-central/source/content/media/
> MediaDecoderStateMachine.cpp#928?

Not so exactly. The while loop leaves if two consecutive GetMediaTime() returns the same position. But getting the same position from GetMediaTime() doesn't mean all the audio data have been processed/output through the audio back-end.

Comment 13

[JW Wang [:jwwang] [:jw_wang]]

(In reply to Bruce Sun [:brsun] from comment #12)
> Not so exactly. The while loop leaves if two consecutive GetMediaTime()
> returns the same position. But getting the same position from GetMediaTime()
> doesn't mean all the audio data have been processed/output through the audio
> back-end.

Then it looks like a bug in that while loop for the intention of the while loop is to wait for the underlying audio engine to consume all data. We should fix the logic of the while loop.

Comment 14

[Bruce Sun [:brsun]]

(In reply to Matthew Gregan [:kinetik] from comment #10)
> Comment on attachment 8433268 [details] [diff] [review]
> bug1017438_audio_tail_cut_off.patch
> 
> f- because the correct fix is making Drain() behave like it is expected to.
> 
> (In reply to Bruce Sun [:brsun] from comment #7)
> > Created attachment 8433268 [details] [diff] [review]
> > bug1017438_audio_tail_cut_off.patch
> > 
> > Even all the audio data have been consumed in AudioStream::DataCallback() by
> > libcubeb, the audio back-end still needs time to output the audio. Because
> > there is no APIs to get the exact mapping between the audio sound and the
> > audio position in the stream, we have to guess a proper duration to wait
> > before closing AudioStream.
> 
> We shouldn't need to guess.  It is signalled by AudioStream::StateCallback
> being called with CUBEB_STATE_DRAINED.  If that's happening too early, we
> should fix that directly.
> 

The idea behind waiting |mAudioEndTime - GetMediaTime()| period is the assumption that cubeb_stream_get_position() can return the exact audio position with correct latency compensation.
So the latency before the last audio frame can be heard by users should be approximately equal to the difference between the timestamps of the delivered audio data and the retrieved playback position.

If we want to correct the timing of CUBEB_STATE_DRAINED, we might need to consider the latency of audio back-end as well. But I don't have any clear idea about how to achieve it. Any direction?

> > On my dolphin device (with 1.4 gecko), |mAudioEndTime - GetMediaTime()| of
> > 1k.amr is roughly 400ms after AudioStream::Drain(), and it sounds OK by
> > waiting for such period.
> 
> I'm not clear on which version of Android and Gecko are involved here.  For
> this and the Flame device, can you confirm which libcubeb backend is in use?
> It'll either be cubeb_audiotrack or cubeb_opensl.  I would've expected both
> of them to be using cubeb_opensl, although it sounds like drain is behaving
> differently on each device.

I will update this information later.

Comment 15

[Bruce Sun [:brsun]]

(In reply to Matthew Gregan [:kinetik] from comment #10)
> I'm not clear on which version of Android and Gecko are involved here.  For
> this and the Flame device, can you confirm which libcubeb backend is in use?
> It'll either be cubeb_audiotrack or cubeb_opensl.  I would've expected both
> of them to be using cubeb_opensl, although it sounds like drain is behaving
> differently on each device.

Both devices use cubeb_opensl.

Comment 16

[Bruce Sun [:brsun]]

(In reply to Bruce Sun [:brsun] from comment #7)
> On my flame device (with master mecko), |mAudioEndTime - GetMediaTime()| of
> 1k.amr is always 0ms after AudioStream::Drain(), so there is no improvement
> by simply waiting for such period. I guess
> |AudioStream::GetPositionInFramesUnlocked()| could be refined so that we
> could have a more conservative position value instead of a optimistic one.
>  -
> http://dxr.mozilla.org/mozilla-central/source/content/media/AudioStream.
> cpp#784

If I minus adjustedPosition with mLostFramesPast and mLostFramesLast just like what our logic is on master gecko before the modification 185393:758fb5c247c2, |mAudioEndTime - GetMediaTime()| of 1k.amr is roughly 700ms after AudioStream::Drain(), and it sounds OK by waiting for such period on flame device.

Comment 17

[Paul Adenot (:padenot)]

clearing, as Matthew answered.

Comment 18

[Paul Adenot (:padenot)]

Comment on attachment 8433268 [details] [diff] [review]
bug1017438_audio_tail_cut_off.patch

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

Same remark as Matthew.

Comment 19

[Bruce Sun [:brsun]]

By the way, the original AudioStream::GetPositionInFramesUnlocked() was too conservative and not monotonic increasing. But the current one might be a little bit too optimistic.
If we want to have a more precise position information from AudioStream::GetPositionInFramesUnlocked(), probably we can keep tracking the count of the written frames and the silent frames into a frame-count-based table when AudioStream::DataCallback() is called. Within AudioStream::GetPositionInFramesUnlocked(), we can use the position value from cubeb_stream_get_position() to look-up the table to have a more precise accumulated frames.

Well...but this issue could not improved by refining AudioStream::GetPositionInFramesUnlocked() if waiting for |mAudioEndTime - GetMediaTime()| period is not acceptable.

Comment 20

[Star Cheng [:scheng]]

AFAIK, If we invoke opensl_stream_stop(), the state of audio back-end is paused. It means that we can't consume any data in shared memory buffer of audio back-end. While we invoke opensl_stream_destroy(), the audio back-end will be stopped. Please see below following 2 functions:

[opensl_stream_stop]
In opensl_stream_stop(), set the SL_PLAYSTATE_PAUSED state through SetPlayState() to OpenSL. 

[opensl_stream_destroy]
In Audio back-end, AudioTrack continue invoking callback function to get more data from OpenSL ndk lib. And Opensl call the buffer callback function of Cubeb, which get data from AudioStream and enqueue to SL. These actions are going until the AudioTrack is stopped by Gecko [1]. 


Considering this issue : While in the draining mode, we will use AudioStream::Shutdown() to pause cube and SL. SL will notify AudioTrack with pause state. If the buffer of audio back-end is not empty, but it can not be consumed. And we can't get any information about the end of the decoded data in audio back-end. 


Hi, Matthew

Do you know how do we get the information about end of decoded data? If we can get the information in cubeb and we can set the CUBEB_STATE_DRAINED by AudioStream::StateCallback in good timing.



[1] opensl_stream_destroy() -> OpenSL Destroy() -> pAudioPlayer->mAudioTrack->stop() -> AudioTrack::stop()

Comment 21

[Matthew Gregan [:kinetik]]

(In reply to Star Cheng [:scheng] from comment #20)
> Considering this issue : While in the draining mode, we will use
> AudioStream::Shutdown() to pause cube and SL. SL will notify AudioTrack with
> pause state. If the buffer of audio back-end is not empty, but it can not be
> consumed. And we can't get any information about the end of the decoded data
> in audio back-end. 

The fix needs to be in cubeb_opensl.c, not at the AudioStream level.  Any OpenSL calls we need to make have to happen either when the AudioStream DataCallback signals the end of stream (to set up the drain delay), or in a triggered callback (to signal drain completion).

> Do you know how do we get the information about end of decoded data? If we
> can get the information in cubeb and we can set the CUBEB_STATE_DRAINED by
> AudioStream::StateCallback in good timing.

Not sure.  In opensl_stream_get_position, we query the mixer latency.  What value is that returning on these devices?  What does player->GetPosition() return when we hit the |if (!state.count)| drain logic in bufferqueue_callback (and how many msec of audio have we written at this point -- that is, what value do we expect it to be once our audio finishes playing back?)  Perhaps we can use SetMarkerPosition to receive a callback when the audio in the last buffer has actually been played?

Comment 22

[Jet Villegas (inactive)]

Setting assignee to Bruce who owns the patch here.

Comment 23

[Bruce Sun [:brsun]]

I'm trying to use SetMarkerPosition() to see if we can get CUBEB_STATE_DRAINED callback from libcubeb at the correct timing.

Comment 24

[JW Wang [:jwwang] [:jw_wang]]

http://hg.mozilla.org/mozilla-central/file/9e8e3e903484/content/media/MediaDecoderStateMachine.cpp#l1249
We should call GetAudioClock() which is more relevant since we are waiting for frames to be consumed by audio hardware.

http://hg.mozilla.org/mozilla-central/file/9e8e3e903484/content/media/MediaDecoderStateMachine.cpp#l1250
Datacallback interval from libcubed is about 25ms. We should wait for at least 25ms for the first time. Otherwise we just have oldPosition == position == 0 and exit the loop immediately for playback position of audio hardware hasn't advanced at all.

Comment 25

[JW Wang [:jwwang] [:jw_wang]]

Btw, audio latency should be the amount of time we should wait for the first frame to be played by audio hardware.

Comment 26

[Bruce Sun [:brsun]]

Attachment: bug1017438_audio_tail_cut_off.v2.patch

Use SLPlayItf::SetMarkerPosition() to get SL_PLAYEVENT_HEADATMARKER event so that CUBEB_STATE_DRAINED state callback can be triggered at the correct timing.

Comment 27

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8439144 [details] [diff] [review]
bug1017438_audio_tail_cut_off.v2.patch

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

::: media/libcubeb/src/cubeb_opensl.c
@@ +89,5 @@
>      void *buf = stm->queuebuf[stm->queuebuf_idx];
> +    long written = 0;
> +
> +    if (!stm->draining) {
> +      written = stm->data_callback(stm, stm->user_ptr, buf, stm->queuebuf_len / stm->framesize);

Check datacallback doesn't return more than asked. Otherwise memset below will blow.

@@ +90,5 @@
> +    long written = 0;
> +
> +    if (!stm->draining) {
> +      written = stm->data_callback(stm, stm->user_ptr, buf, stm->queuebuf_len / stm->framesize);
> +      if (written == CUBEB_ERROR || written < 0) {

Since CUBEB_ERROR is negative, it is OK to check |written < 0| only.

@@ +98,4 @@
>      }
>  
> +    // Keep sending silent data even in draining mode to prevent AudioTrack from
> +    // being stopped automatically by OpenSL/ES.

Padding silent frames (which is not sent by the client) must be taken into account in opensl_stream_get_position(), otherwise the client (AudioStream) will get incorrect position.

@@ +98,5 @@
>      }
>  
> +    // Keep sending silent data even in draining mode to prevent AudioTrack from
> +    // being stopped automatically by OpenSL/ES.
> +    memset(buf + written * stm->framesize, 0, stm->queuebuf_len - written * stm->framesize);

You will send nothing but silent frames when not draining, which is wrong.

Comment 28

[Bruce Sun [:brsun]]

Hi JW, thanks. It's great to have your feedback.

(In reply to JW Wang [:jwwang] from comment #27)
> Comment on attachment 8439144 [details] [diff] [review]
> bug1017438_audio_tail_cut_off.v2.patch
> 
> Review of attachment 8439144 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Check datacallback doesn't return more than asked. Otherwise memset below
> will blow.
> 

will do.

> @@ +90,5 @@
> > +    long written = 0;
> > +
> > +    if (!stm->draining) {
> > +      written = stm->data_callback(stm, stm->user_ptr, buf, stm->queuebuf_len / stm->framesize);
> > +      if (written == CUBEB_ERROR || written < 0) {
> 
> Since CUBEB_ERROR is negative, it is OK to check |written < 0| only.
> 

The intention to check |written < 0| here is just for correctly accumulating written counts.

Probably we have to decide how to behave when the return value from stm->data_callback() doesn't fall into 0 and stm->queuebuf_len:
 - Behavior 1: Stop playback. Then we have to check |written == CUBEB_ERROR| and |written < 0| and |written > stm->queuebuf_len| conditions before calling stop and returning.
 - Behavior 2: Continue playback. Then we don't have to modify the error checking and returning logic (only check |written == CUBEB_ERROR| is enough.) And then check |written < 0| and |written > stm->queuebuf_len| only for copying data.

Any advice?

> @@ +98,4 @@
> >      }
> >  
> > +    // Keep sending silent data even in draining mode to prevent AudioTrack from
> > +    // being stopped automatically by OpenSL/ES.
> 
> Padding silent frames (which is not sent by the client) must be taken into
> account in opensl_stream_get_position(), otherwise the client (AudioStream)
> will get incorrect position.
> 

Not sure whether we have to take this situation into account or not. This condition should only happen after SL_PLAYEVENT_HEADATMARKER has been reached (which only happens in draining mode), and then gecko stops playback immediately.
If this is not the case, maybe there are some more position bugs inside gecko.

> @@ +98,5 @@
> >      }
> >  
> > +    // Keep sending silent data even in draining mode to prevent AudioTrack from
> > +    // being stopped automatically by OpenSL/ES.
> > +    memset(buf + written * stm->framesize, 0, stm->queuebuf_len - written * stm->framesize);
> 
> You will send nothing but silent frames when not draining, which is wrong.

This will not happen. If |stm->queuebuf_len - written * stm->framesize| is not zero in non-draining mode, cubeb will change into draining mode immediately.

Comment 29

[Bruce Sun [:brsun]]

(In reply to Bruce Sun [:brsun] from comment #28)
> Probably we have to decide how to behave when the return value from
> stm->data_callback() doesn't fall into 0 and stm->queuebuf_len:
>                                              ^^^^^^^^^^^^^^^^^
should be |stm->queuebuf_len / stm->framesize|.

>  - Behavior 1: Stop playback. Then we have to check |written == CUBEB_ERROR|
> and |written < 0| and |written > stm->queuebuf_len| conditions before
>                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
should be |written * stm->framesize > stm->queuebuf_len|.

> calling stop and returning.

Comment 30

[JW Wang [:jwwang] [:jw_wang]]

(In reply to Bruce Sun [:brsun] from comment #28)
> The intention to check |written < 0| here is just for correctly accumulating
> written counts.
I mean it is OK to write |if (written < 0)| since CUBEB_ERROR is negative.

> Not sure whether we have to take this situation into account or not. This
> condition should only happen after SL_PLAYEVENT_HEADATMARKER has been
> reached (which only happens in draining mode), and then gecko stops playback
> immediately.
> If this is not the case, maybe there are some more position bugs inside
> gecko.
Since libcubeb is an open source project, don't make an assumption of client's behavior unless it is documented.


> This will not happen. If |stm->queuebuf_len - written * stm->framesize| is
> not zero in non-draining mode, cubeb will change into draining mode
> immediately.
Sorry, I was wrong. Send silent frames in draining mode is exactly your intention.

Comment 31

[Bruce Sun [:brsun]]

(In reply to JW Wang [:jwwang] from comment #30)
> (In reply to Bruce Sun [:brsun] from comment #28)
> > The intention to check |written < 0| here is just for correctly accumulating
> > written counts.
> I mean it is OK to write |if (written < 0)| since CUBEB_ERROR is negative.
> 

Understood. I just wondering whether it is good or not to merge the logic of checking predefined errors into the logic of checking index/range value.

> > Not sure whether we have to take this situation into account or not. This
> > condition should only happen after SL_PLAYEVENT_HEADATMARKER has been
> > reached (which only happens in draining mode), and then gecko stops playback
> > immediately.
> > If this is not the case, maybe there are some more position bugs inside
> > gecko.
> Since libcubeb is an open source project, don't make an assumption of
> client's behavior unless it is documented.
> 
> 

Because opensl_stream_get_position() uses the position value from AudioTrack with a compensated |mixer_latency| value, users don't have chance to get any position value bigger than |the_real_end_position - mixer_latency| in the original case. Since libcubeb doesn't have any API that can expose the exact |mixer_latency| value to users, I might say it is a little bit hard to use opensl_stream_get_position() for any accurate stuff near the end of media playback.

The modified behavior will be:
 - Original: Since CUBEB_STATE_DRAINED is called too early, opensl_stream_get_position() will keep increasing as long as audio data have not completely consumed by AudioTrack. During this period, the return value of opensl_stream_get_position() will not bigger than |the_real_end_position - mixer_latency|. After all data has been consumed by AudioTrack, OpenSL/ES will stop AudioTrack[1], and then AudioTrack will be flushed. After that we probably cannot get a meaningful value from opensl_stream_get_position().
 - In this patch: AudioTrack will not be stopped automatically by OpenSL/ES even all meaningful data have been consumed, and opensl_stream_get_position() will keep increasing even CUBEB_STATE_DRAINED has been called. By doing this, users of libcubeb have a chance to have a position value from opensl_stream_get_position() to reach |the_real_end_position|.

Kindly let me know if I delivered any incorrect information.
May I know what would be the proper behavior after CUBEB_STATE_DRAINED has been called?

[1] https://github.com/mozilla-b2g/platform_frameworks_wilhelm/blob/master/src/android/AudioPlayer_to_android.cpp#L1174

> > This will not happen. If |stm->queuebuf_len - written * stm->framesize| is
> > not zero in non-draining mode, cubeb will change into draining mode
> > immediately.
> Sorry, I was wrong. Send silent frames in draining mode is exactly your
> intention.

Comment 32

[Bruce Sun [:brsun]]

Thanks for JW's inspiration, I'll try to use |stm->written| to limit the maximum position value of opensl_stream_get_position().

Comment 33

[Bruce Sun [:brsun]]

Comment on attachment 8439144 [details] [diff] [review]
bug1017438_audio_tail_cut_off.v2.patch

Change |review?| to |feedback?| since I am going to provide another similar patch in the near future.

Comment 34

[Matthew Gregan [:kinetik]]

Comment on attachment 8439144 [details] [diff] [review]
bug1017438_audio_tail_cut_off.v2.patch

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

::: media/libcubeb/src/cubeb_opensl.c
@@ +57,5 @@
>    cubeb_state_callback state_callback;
>    void * user_ptr;
>  };
>  
> +static void play_callback(SLPlayItf caller, void * user_ptr, SLuint32 event)

New line after "void"

@@ +61,5 @@
> +static void play_callback(SLPlayItf caller, void * user_ptr, SLuint32 event)
> +{
> +  cubeb_stream * stm = user_ptr;
> +  switch (event) {
> +    case SL_PLAYEVENT_HEADATMARKER:

Did you confirm that this fires at the correct time?

@@ +62,5 @@
> +{
> +  cubeb_stream * stm = user_ptr;
> +  switch (event) {
> +    case SL_PLAYEVENT_HEADATMARKER:
> +      if (stm->draining) {

Since the marker is only registered when draining == 1, drain should never be false here, so use an assert and unident the rest of the code.

@@ +98,4 @@
>      }
>  
> +    // Keep sending silent data even in draining mode to prevent AudioTrack from
> +    // being stopped automatically by OpenSL/ES.

Can you explain why this is necessary?  Have you observed the AudioTrack stopping before we reach the end of the real audio data and thus never reaching the set position marker?

@@ +108,3 @@
>        stm->draining = 1;
> +      // Try to get SL_PLAYEVENT_HEADATMARKER event from slPlayCallback of
> +      // SLPlayItf to make sure all the data has been processed by AudioTrack.

Why "try"?

Also, remove "by AudioTrack", since that reveals assumptions about the implementation that aren't exposed via the API and could be wrong in the future/with different OpenSL implementations.

Comment 35

[Bruce Sun [:brsun]]

(In reply to Matthew Gregan [:kinetik] from comment #34)
> @@ +61,5 @@
> > +static void play_callback(SLPlayItf caller, void * user_ptr, SLuint32 event)
> > +{
> > +  cubeb_stream * stm = user_ptr;
> > +  switch (event) {
> > +    case SL_PLAYEVENT_HEADATMARKER:
> 
> Did you confirm that this fires at the correct time?
> 

This event is fired when the data are processed by the downstream component of AudioTrack:
 - http://osxr.org/android/source/frameworks/av/media/libmedia/AudioTrack.cpp#1227
It seems that |mixer_latency| might be still not considered well in this case thought.

> @@ +98,4 @@
> >      }
> >  
> > +    // Keep sending silent data even in draining mode to prevent AudioTrack from
> > +    // being stopped automatically by OpenSL/ES.
> 
> Can you explain why this is necessary?  Have you observed the AudioTrack
> stopping before we reach the end of the real audio data and thus never
> reaching the set position marker?
> 

Correct. The marker is used for the position of the consumer part of the shared buffer. However, AudioTrack will be stopped automatically when the producer part of the shared buffer becomes empty. If we set the last audio byte as the marker but we don't keep sending data to the shared buffer, EVENT_MARKER event will never be called due to AudioTrack will be stopped earlier when dealing with EVENT_MORE_DATA event.
 - https://github.com/mozilla-b2g/platform_frameworks_wilhelm/blob/master/src/android/AudioPlayer_to_android.cpp#L1174

> @@ +108,3 @@
> >        stm->draining = 1;
> > +      // Try to get SL_PLAYEVENT_HEADATMARKER event from slPlayCallback of
> > +      // SLPlayItf to make sure all the data has been processed by AudioTrack.
> 
> Why "try"?
> 

I'll refine the comment as "Use SL_PLAYEVENT_HEADATMARKER event from slPlayCallback..." and remove all "AudioTrack" words.

Comment 36

[Bruce Sun [:brsun]]

Attachment: bug1017438_audio_tail_cut_off.v3.patch

Modified based on comment 27, comment 32, comment 34.

Comment 37

[Matthew Gregan [:kinetik]]

Comment on attachment 8440643 [details] [diff] [review]
bug1017438_audio_tail_cut_off.v3.patch

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

Looks good, but r- because of the volatile/locking issue.

::: media/libcubeb/src/cubeb_opensl.c
@@ +48,5 @@
>    int queuebuf_idx;
>    long queuebuf_len;
>    long bytespersec;
>    long framesize;
> +  volatile long written;

You need to use a lock.  We also need one for draining now that it's accessed on more than one thread (via play_callback).

@@ +90,5 @@
> +    long written = 0;
> +
> +    if (!stm->draining) {
> +      written = stm->data_callback(stm, stm->user_ptr, buf, stm->queuebuf_len / stm->framesize);
> +      if (written == CUBEB_ERROR || written < 0 || written * stm->framesize > stm->queuebuf_len) {

written == CUBEB_ERROR || written < 0

Just make this:

    written < 0

...since it covers both cases.

Comment 38

[Bruce Sun [:brsun]]

Attachment: bug1017438_audio_tail_cut_off.v4.patch

Modified based on comment 37.

Comment 39

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8441177 [details] [diff] [review]
bug1017438_audio_tail_cut_off.v4.patch

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

::: media/libcubeb/src/cubeb_opensl.c
@@ +634,1 @@
>    }

You have to take into account the silent bytes sent to the audio engine while draining. Otherwise, as the client enter/leave draining mode several times, the silent bytes will add up and cause a problem in AV sync.

Comment 40

[Bruce Sun [:brsun]]

(In reply to JW Wang [:jwwang] from comment #39)
> Comment on attachment 8441177 [details] [diff] [review]
> bug1017438_audio_tail_cut_off.v4.patch
> 
> Review of attachment 8441177 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: media/libcubeb/src/cubeb_opensl.c
> @@ +634,1 @@
> >    }
> 
> You have to take into account the silent bytes sent to the audio engine
> while draining. Otherwise, as the client enter/leave draining mode several
> times, the silent bytes will add up and cause a problem in AV sync.

Is this, enter/leave draining mode several times, a valid use case of libcubub?

Comment 41

[JW Wang [:jwwang] [:jw_wang]]

I am not sure since it is not prohibited in the document. On the other hand, we shouldn't make an assumption of what a client should (not) do unless it is explicitly documented.

Comment 42

[Matthew Gregan [:kinetik]]

It's not (intended to be) supported by the cubeb API.  Once you signal a drain, you should not receive any further data callbacks and should expect a state callback signalling drain, at which time you are expected to destroy the stream.

Comment 43

[Bruce Sun [:brsun]]

(In reply to JW Wang [:jwwang] from comment #41)
> I am not sure since it is not prohibited in the document. On the other hand,
> we shouldn't make an assumption of what a client should (not) do unless it
> is explicitly documented.

From the comment of cubeb_data_callback, draining mode should be triggered only when end-of-stream occurs at the client side. This is already documented.
 - http://dxr.mozilla.org/mozilla-central/source/media/libcubeb/include/cubeb.h#153

Comment 44

[JW Wang [:jwwang] [:jw_wang]]

Thanks for the clarification. Since silent bytes only appear at the end of stream it should not cause any audible artifacts to the client which should be fine with the playback position goes slightly beyond the sent frames.

Comment 45

[JW Wang [:jwwang] [:jw_wang]]

Btw, does this symptom happen on Opensl backend only? Does Windows or Linux also suffer from such a very-short-file?

Comment 46

[Bruce Sun [:brsun]]

Attachment: bug1017438_audio_tail_cut_off.v4.merge_bug1008079.patch

Hi Matthew,

I've merged my patch with the latest master, but it seems we need some extra efforts to calculate the maximum input position in opensl_stream_get_position() after integrating the re-sampling mechanism. May I have your review again?

Comment 47

[Bruce Sun [:brsun]]

Update:
I am trying to clarify the following errors on |Android 2.3 Opt| TBPL:
 - TEST-UNEXPECTED-FAIL | /tests/content/html/content/test/test_audio_wakelock.html | application timed out after 330 seconds with no output
 - TEST-UNEXPECTED-FAIL | /tests/toolkit/content/tests/widgets/test_videocontrols_standalone.html | application timed out after 330 seconds with no output

Comment 48

[JW Wang [:jwwang] [:jw_wang]]

Can you post the TBPL link? We might be able find some clues in the log/error messages.

Comment 49

[Bruce Sun [:brsun]]

https://tbpl.mozilla.org/?tree=Try&rev=3a936d009486

Comment 50

[JW Wang [:jwwang] [:jw_wang]]

Nothing stands out to me...

It might be related to bug 1020227. Does test_audio_wakelock.html create AudioStream?

Comment 51

[Bruce Sun [:brsun]]

HTMLMediaElement creates AudioStream when it is about to start playback:
 - http://dxr.mozilla.org/mozilla-central/source/content/media/MediaDecoderStateMachine.cpp#1134

Comment 52

[JW Wang [:jwwang] [:jw_wang]]

http://hg.mozilla.org/mozilla-central/file/f78e532e8a10/media/libcubeb/src/cubeb_opensl.c#l562
Try to add some logs to see if it takes eternity to destroy the player object. If yes, you hit bug 1020227.

Comment 53

[James Zhang (Spreadtrum)]

Please help to land this WIP patch to verify.

Comment 54

[yang.zhao]

(In reply to Bruce Sun [:brsun] from comment #46)
> Created attachment 8442040 [details] [diff] [review]
> bug1017438_audio_tail_cut_off.v4.merge_bug1008079.patch
> 
> Hi Matthew,
> 
> I've merged my patch with the latest master, but it seems we need some extra
> efforts to calculate the maximum input position in
> opensl_stream_get_position() after integrating the re-sampling mechanism.
> May I have your review again?
Hi,Bruce
   I tried to apply either of the two patches to gecko on v1.4, both of them failed. Could you help to merge the patch in v1.4 ?Thank you very much!

Comment 55

[Bruce Sun [:brsun]]

Attachment: bug1017438_audio_tail_cut_off.v1_4.patch

Hi yang.zhao,
You can try this one for v1.4.

Comment 56

[yang.zhao]

I've tried the patch and it's ok for v1.4.James has landed on v1.4 by sprd_patch,our commit:f2b3d23ee9bacbe3b7fd05a92dd2f860140400fb

Comment 57

[James Zhang (Spreadtrum)]

Please land it.

Comment 58

[Bruce Sun [:brsun]]

> (*stm->play)->ClearMarkerPosition(stm->play);
It seems this line is the cause of Mochitest timeout.

Comment 59

[Bruce Sun [:brsun]]

Attachment: bug1017438_audio_tail_cut_off.checkin-needed.master.patch

The result of TBPL seems ok:
 - https://tbpl.mozilla.org/?tree=Try&rev=aaa23c64d424

Comment 60

[Bruce Sun [:brsun]]

Attachment: bug1017438_audio_tail_cut_off.checkin-needed.v1_4.patch

The result of TBPL seems ok:
 - https://tbpl.mozilla.org/?tree=Try&rev=cfe8b34ce2b9

Comment 61

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/17e249385be6

Comment 62

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/17e249385be6

Comment 63

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g30_v1_4/rev/2f1aeb3d0083

Note that there was a recent policy change such that 1.4 blockers don't have auto-approval for uplift to 2.0 anymore. You'll need to request approval-mozilla-aurora for it to be considered. Also note that AFAICT, you'll need another branch patch for v2.0 uplift as neither the trunk patch nor the 1.4 patch apply cleanly.

Comment 64

[Bruce Sun [:brsun]]

Attachment: bug1017438_audio_tail_cut_off.checkin-needed.aurora.patch

Approval Request Comment
[Feature/regressing bug #]: Not a regressing. This is just an improvement of current playback mechanism.
[User impact if declined]: The tail part of each audio file isn't output before stopping the playback.
[Describe test coverage new/current, TBPL]: https://tbpl.mozilla.org/?tree=Try&rev=b5ca5951ae27
[Risks and why]: Low. We just leverage the underlying event SL_PLAYEVENT_HEADATMARKER to make CUBEB_STATE_DRAINED callback at a more precise timing.
[String/UUID change made/needed]: No strings or UUIDs are changed.

Comment 65

[Lawrence Mandel [:lmandel] (use needinfo)]

Comment on attachment 8447862 [details] [diff] [review]
bug1017438_audio_tail_cut_off.checkin-needed.aurora.patch

Aurora (2.0) approval granted.

Comment 66

[Bruce Sun [:brsun]]

(In reply to Lawrence Mandel [:lmandel] from comment #65)
> Comment on attachment 8447862 [details] [diff] [review]
> bug1017438_audio_tail_cut_off.checkin-needed.aurora.patch
> 
> Aurora (2.0) approval granted.

Set checkin-needed keyword for this patch: attachment 8447862 [details] [diff] [review].

Comment 67

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/4b5aae0fe6a1

Comment 68

[Alissa（leave from Mozilla）]

Attachment: verifyflame.3gp

This issue has been successfully verified on Flame 2.1, 2.0
See attachment:verifyflame.3gp
Reproducing rate: 0/5

Flame 2.1 build:
Gaia-Rev        38e17b0219cbc50a4ad6f51101898f89e513a552
Gecko-Rev       https://hg.mozilla.org/releases/mozilla-b2g34_v2_1/rev/8b92c4b8f59a
Build-ID        20141205001201
Version         34.0

 Flame 2.0 new build:
Gaia-Rev        856863962362030174bae4e03d59c3ebbc182473
Gecko-Rev       https://hg.mozilla.org/releases/mozilla-b2g32_v2_0/rev/e40fe21e37f1
Build-ID        20141208000206
Version         32.0
-------------
Hi,peipei
The recording sounds normal,you can check attachment agian,if there is any problem,IN me.

Comment 69

[Peipei Cheng (needinfo if you need my action)]

(In reply to Alissa from comment #68)
> Created attachment 8533503 [details]
> verifyflame.3gp
> 
> This issue has been successfully verified on Flame 2.1, 2.0
> See attachment:verifyflame.3gp
> Reproducing rate: 0/5
> 
> Flame 2.1 build:
> Gaia-Rev        38e17b0219cbc50a4ad6f51101898f89e513a552
> Gecko-Rev      
> https://hg.mozilla.org/releases/mozilla-b2g34_v2_1/rev/8b92c4b8f59a
> Build-ID        20141205001201
> Version         34.0
> 
>  Flame 2.0 new build:
> Gaia-Rev        856863962362030174bae4e03d59c3ebbc182473
> Gecko-Rev      
> https://hg.mozilla.org/releases/mozilla-b2g32_v2_0/rev/e40fe21e37f1
> Build-ID        20141208000206
> Version         32.0
> -------------
> Hi,peipei
> The recording sounds normal,you can check attachment agian,if there is any
> problem,IN me.

Yes, it looks good. Thank you!