1165963 - [Video][Audio Sync] Audio is not in sync for video playback.

Status: VERIFIED FIXED

(Firefox OS Graveyard :: Gaia::Video, defect)

Description

[Martin Shuman [:Marty]]

Attachment: logcat-Audio-Sync.txt

Description:
When viewing a view, the audio noticeably lags behind the video feed, out of sync.

This occurs in both Video, Gallery, Camera Preview, and watching YouTube videos in Browser.

Repro Steps:
1) Update a Flame to 20150518010206
2) Open the browser and navigate to YouTube
3) Watch a video and watch for audio synchronization

Actual:
Audio is not synchronized, lags behind the video.

Expected:
Audio is synchronized with the video.

Environmental Variables:
Device: Flame 3.0 (Full Flash)
Build ID: 20150518010206
Gaia: afea16de7a76c3b6d15c35fb4c37bac71c8ddc6a
Gecko: 35918b0441b4
Gonk: 040bb1e9ac8a5b6dd756fdd696aa37a8868b5c67
Version: 41.0a1 (3.0)
Firmware Version: v18D-1
User Agent: Mozilla/5.0 (Mobile; rv:41.0) Gecko/41.0 Firefox/41.0

This issue occurs with 512MB and 319MB memory.

Repro frequency: 8/8
See attached: Logcat

Comment 1

[Martin Shuman [:Marty]]

This issue does NOT occur on Flame  builds.
Audio plays in sync with the video.

Environmental Variables:
Device: Flame 2.2 (Full Flash)
Build ID: 20150517162505
Gaia: f73891b8fcc5f34de81868640754f7cc331fa709
Gecko: 8785a53b8d6e
Gonk: bd9cb3af2a0354577a6903917bc826489050b40d
Version: 37.0 (2.2)
Firmware Version: v18D-1
User Agent: Mozilla/5.0 (Mobile; rv:37.0) Gecko/37.0 Firefox/37.0

Comment 2

[Peter Bylenga [:PBylenga]]

[Blocking Requested - why for this release]:
Functional regression of a core feature.

Requesting a window.

Comment 3

[John Thomas [:Johnt]]

Mozilla inbound Regression Window
Issue appears to occur due to changes made in bug 1104643

Last Working 
Environmental Variables:
Device: Flame 3.0
Build ID: 20150510231338
Gaia: 6089234ace8b294a8feef064387604bae16254e3
Gecko: f39f5779392d
Version: 40.0a1 (3.0)
Firmware Version: v18D-1
User Agent: Mozilla/5.0 (Mobile; rv:40.0) Gecko/40.0 Firefox/40.0

First Broken 
Environmental Variables
BuildID: 20150511012931
Gaia: 6089234ace8b294a8feef064387604bae16254e3
Gecko: d5d2f6e45d70
Version: 40.0a1 (3.0)
Firmware Version: v18D-1
User Agent: Mozilla/5.0 (Mobile; rv:40.0) Gecko/40.0 Firefox/40.0


Last Working gaia / First Broken gecko - 
Gaia: 6089234ace8b294a8feef064387604bae16254e3
Gecko: d5d2f6e45d70

First Broken gaia / Last Working gecko -
Gaia: 6089234ace8b294a8feef064387604bae16254e3 
Gecko: f39f5779392d


Mozilla Inbound Pushlog: 
http://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=f39f5779392d&tochange=d5d2f6e45d70

Comment 4

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

Benjamin, can you take a look at this please? This might have been caused by the landing for bug 1104643.

We might need this backed out.

Comment 5

[Benjamin Chen [:bechen]]

Attachment: bug-1104643.v05.patch

Comment 6

[Benjamin Chen [:bechen]]

Comment on attachment 8611144 [details] [diff] [review]
bug-1104643.v05.patch

Address bug 1104643 comment 25, 26.

patch v05: When we detect an "over compensation" ( |msec < stm->lastCompensativePosition| ), we stop the compensation logic and return the lastCompensativePosition to prevent the backward audio_clock.

Comment 7

[Paul Adenot (:padenot)]

Comment on attachment 8611144 [details] [diff] [review]
bug-1104643.v05.patch

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

r+ if it's fixing your issue, as it makes sense, but I'd like to know why this happens, do you have a log of times before and after?

Basically, I don't want us to paper over an issue that we don't fully understand.

::: media/libcubeb/src/cubeb_opensl.c
@@ +734,5 @@
>  
>    if (msec > mixer_latency) {
> +    int64_t unadjusted_position;
> +    if (stm->lastCompensativePosition > msec + compensation_msec) {
> +      // Over compensation, use lastCompensativePosition.

Would that be caused by a system clock skew or something?

Comment 8

[Benjamin Chen [:bechen]]

(In reply to Benjamin Chen [:bechen] from comment #6)
> Comment on attachment 8611144 [details] [diff] [review]
> bug-1104643.v05.patch
> 
> Address bug 1104643 comment 25, 26.
> 
> patch v05: When we detect an "over compensation" ( |msec <
> stm->lastCompensativePosition| ), we stop the compensation logic and return
> the lastCompensativePosition to prevent the backward audio_clock.

This description of the v05 patch might not 100% correctly.

Every time if the |msec| is updated from audio back end (stm->lastPosition != msec), we reset the compensation anchor from |msec|.
Then if we found over compensation, we still keep computing the |compensation_msec| until it reaches |stm->lastCompensativePosition| in order to keep the audio clock monotonic.

(In reply to Paul Adenot (:padenot) from comment #7)
> Comment on attachment 8611144 [details] [diff] [review]
> bug-1104643.v05.patch
> 
> Review of attachment 8611144 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> r+ if it's fixing your issue, as it makes sense, but I'd like to know why
> this happens, do you have a log of times before and after?
> 
> Basically, I don't want us to paper over an issue that we don't fully
> understand.
> 
> ::: media/libcubeb/src/cubeb_opensl.c
> @@ +734,5 @@
> >  
> >    if (msec > mixer_latency) {
> > +    int64_t unadjusted_position;
> > +    if (stm->lastCompensativePosition > msec + compensation_msec) {
> > +      // Over compensation, use lastCompensativePosition.
> 
> Would that be caused by a system clock skew or something?

The over compensation sometimes happened because the audio back end is not stable enough.
For example: if the audio back end forward the audio clock 20ms each time. Ideally the callback period is 20ms. Once it delay from 20ms to 30ms, the over compensation appears after the "delayed update" until the next update.

Comment 9

[Benjamin Chen [:bechen]]

Attachment: bug-1104643.v05.patch

r=padenot
try server: https://treeherder.mozilla.org/#/jobs?repo=try&revision=ff0cba6ad432

Comment 10

[Pulsebot]

https://hg.mozilla.org/integration/b2g-inbound/rev/265506e5d2ca

Comment 11

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/265506e5d2ca

Comment 12

[zouyi(Leave from Mozilla)]

Attachment: verify_master.MP4

This bug has been verified as "pass" on latest build of Flame v3.0&Nexus5 v3.0.
See attachments: verify_master.MP4
STR:
1) Update a Flame to 20150518010206
2) Open the browser and navigate to YouTube
3) Watch a video and watch for audio synchronization

Reproduce rate: 0/5
Device: Flame 3.0 build(Pass)
Build ID               20150607160204
Gaia Revision          1d62b32408567f9f7cf1c71c1e5a0c6593be757b
Gaia Date              2015-06-05 17:55:07
Gecko Revision         https://hg.mozilla.org/mozilla-central/rev/7d4ab4a9febd
Gecko Version          41.0a1
Device Name            flame
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.cltbld.20150607.193246
Firmware Date          Sun Jun  7 19:32:58 EDT 2015
Bootloader             L1TC000118D0

Device: Nexus5 3.0 build(Pass)
Build ID               20150607160204
Gaia Revision          1d62b32408567f9f7cf1c71c1e5a0c6593be757b
Gaia Date              2015-06-05 17:55:07
Gecko Revision         https://hg.mozilla.org/mozilla-central/rev/7d4ab4a9febd
Gecko Version          41.0a1
Device Name            hammerhead
Firmware(Release)      5.1
Firmware(Incremental)  eng.cltbld.20150607.193647
Firmware Date          Sun Jun  7 19:37:06 EDT 2015
Bootloader             HHZ12f

Comment 13

[Martin Shuman [:Marty]]

This issue is verified fixed on the latest Flame build.
Audio is synchronized with the video.

Environmental Variables:
Device: Flame 3.0
Build ID: 20150608010204
Gaia: 1d62b32408567f9f7cf1c71c1e5a0c6593be757b
Gecko: 7d4ab4a9febd
Gonk: 040bb1e9ac8a5b6dd756fdd696aa37a8868b5c67
Version: 41.0a1 (3.0)
Firmware Version: v18D-1
User Agent: Mozilla/5.0 (Mobile; rv:41.0) Gecko/41.0 Firefox/41.0