525401 - Prolonged delay resuming video playback after pausing with some videos

Status: RESOLVED FIXED

(Core :: Audio/Video, defect)

Description

[Matthew Gregan [:kinetik]]

I have a somewhat badly constructed (produced by test video in which many of the "frames" do not have audio data associated with them that has revealed a couple of problems:

1. There can be drift between the audio clock and the wall clock.  The loop in PlayFrame() that waits for the current frame time to pass can alternate between using the wall clock and the audio clock in cases where some frames don't have audio data attached.

2. There's a problem resetting the wall clock/pause duration times when resuming from pause that causes a permanent drift and large amount of frame skipping the first time we enter PlayFrame() with a audioless frame.

No URL for the test video because the online copy has since been reencoded by the owner.

This problem *may* explain the issues seen in bug 520100, and possibly also in bug 498564.

I have a patch but it needs cleaning up and testing before I post it.

Comment 1

[Rich Walsh]

That certainly is a problematic little bit of code.  I look forward to seeing (and testing) your patch.

Comment 2

[Matthew Gregan [:kinetik]]

It's definitely not related to bug 520100, but I have a theory about that one now.

Comment 3

[Matthew Gregan [:kinetik]]

Attachment: potential fix

This is the approach I've taken for the fix.  This patch isn't quite right, as I'm seeing a test failure (timeout) for one file in test_playback.html.

Comment 4

[Matthew Gregan [:kinetik]]

test_playback.html times out on bug520493.ogg because the ended event never fires.  This is caused by the new PausePlayback() call I added to the QueueDecodedFrames wait loop.

When the audio stream is paused at this point, the audio playback thread is destroyed.  There's still 7330 bytes of audio buffered in sydneyaudio to play, so when we eventually make it to COMPLETED state, sa_stream_drain hangs waiting for the audio thread to play back the remaining buffered audio, which never happens.

sa_stream_drain should return an error if the caller tries to drain the stream when the audio backend is paused.

Comment 6

[Matthew Gregan [:kinetik]]

Bug 526411 comment 50 points to a public testcase for this problem.

Comment 7

[Matthew Gregan [:kinetik]]

Attachment: patch part 1 v0

Make sa_stream_drain return an error if the stream is not playing when drain is called.

Comment 8

[Matthew Gregan [:kinetik]]

Attachment: patch part 2 v0

Don't clobber the system clock when resuming from pause.  Pause playback when waiting on the decode thread to avoid desynching the audio and system clocks.  Also removes some (now) bogus code from PausePlayback that could cause problems.

Comment 9

[Matthew Gregan [:kinetik]]

Attachment: patch part 3 v0

Periodically resync the system clock against the audio clock at a time when we're trusting the audio clock.  This reduces the drift between clocks fairly significantly so that poorly muxed files (such as those where half of the "frames" don't have audio attached) play back smoothly.  Without this change, these poorly muxed files suffer from frame dropping due to clock drift.

This change is kinda gross, but a cleaner fix requires more work done in libsydneyaudio, which I'm saving for a later date.  The current plan here is to have the sound backend report the current playback position via callbacks and use that data interpolated with the system clock to provide a continuously updating master clock on all platforms.

Comment 10

[Matthew Gregan [:kinetik]]

http://hg.mozilla.org/mozilla-central/rev/b876c36242dc
http://hg.mozilla.org/mozilla-central/rev/9b33c91c851d
http://hg.mozilla.org/mozilla-central/rev/d7a32460bb32

Comment 11

[Matthew Gregan [:kinetik]]

test_bug468190.html went orange on Windows and test_ended2.html went orange on Linux.  This made it through tryserver and local tests on multiple platforms.  I've backed the patches out for now.

http://hg.mozilla.org/mozilla-central/rev/5988d1cd74ff
http://hg.mozilla.org/mozilla-central/rev/0d981e2a7a25
http://hg.mozilla.org/mozilla-central/rev/1f8d93376db0

This'll be a good candidate for the Sword +5 Against Orange.

Comment 12

[Matthew Gregan [:kinetik]]

Linux fail log:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1267222797.1267225224.16574.gz

Windows fail log:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1267220890.1267223880.12619.gz

Comment 13

[Matthew Gregan [:kinetik]]

It looks like this could be caused by the PausePlayback() call I added in patch #2 when we're about to start buffer-waiting.

Comment 14

[Matthew Gregan [:kinetik]]

The Start/StopPlayback clock handling for videos with no audio is totally broken with this patch.  New patch coming shortly.

Comment 15

[Matthew Gregan [:kinetik]]

Looks like the fix for that solved failures in test_bug468190 on the Windows tryserver but not test_ended2 on the Linux builds.

Comment 16

[Matthew Gregan [:kinetik]]

It doesn't actually fix it, must have been a spurious pass.  Still investigating.

Comment 17

[Matthew Gregan [:kinetik]]

There's a race in QueueDecodedFrames that seems to be the cause of this (and probably the random orange in the same tests we've seen before this patch made it so obvious).

The problem is here:
http://mxr.mozilla.org/mozilla-central/source/content/media/ogg/nsOggDecoder.cpp#1158

We queue the update event before we add the frame we're notifying about.  This means that the main thread update can run before the frame is actually added, and thus see a different state to the one we're trying to signal.

Changing the ordering of the frame push and event firing isn't sufficient to solve this, as it's also possible to fire the event and then immediately revert to the previous state, which means the main thread never sees the state that we were attempting to notify it about.  The fix for this is to specify the state we're notifying about as part of the event.  I tried this during an earlier tryserver build but missed the push vs update race in QueueDecodedFrames, so my changes effectively ensured that the wrong state would *always* be reported in the racing case.

I've pushed two runs of the new patch to tryserver and both passed the relevant tests.

Comment 18

[Matthew Gregan [:kinetik]]

Attachment: patch part 2 v1

Revised part 2 to fix start/stop with videos that have no sound.  The last frame number is reset in StopPlayback so it's necessary to reset the system clock too.

Comment 19

[Matthew Gregan [:kinetik]]

Attachment: patch part 4 v0

Make ready state transitions initiated by the decode thread more reliable by including the new state in the event.  Fixes an ABA problem where we could play through without ever moving beyond HAVE_CURRENT_DATA.

This fixes a race where we would fire UpdateReadyStateForData to signal that we've got frames queued (i.e. we can move beyond HAVE_CURRENT_DATA) but by the time the main thread processed the event we've thrown the queue frames away (e.g. due to frame skipping).  The patch ensures that we handle the event based on the state at the time it was raised.  In the case described above we'll immediately revert to HAVE_CURRENT_DATA because another event will be queued that signals we've emptied the frame queue.

I believe the new behaviour makes sense because being able to play through an entire file without ever moving beyond HAVE_CURRENT_DATA should be impossible.

Comment 20

[Matthew Gregan [:kinetik]]

Part 4 probably fixes the random orange in bugs 492894 and 498955.

Comment 21

[cajbir (:cajbir)]

Comment on attachment 432469 [details] [diff] [review]
patch part 4 v0

>+  // entered.  Main thread only.
>+  void NextFrameUnavailableBuffering();
>+  void NextFrameAvailable();
>+  void NextFrameUnavailable();

In the implementation for these please assert that they are called only on the main thread.

r+ with that.

Comment 22

[Matthew Gregan [:kinetik]]

Attachment: patch part 4 v1

Add main thread assertions.  Review carried forward.

Comment 23

[Matthew Gregan [:kinetik]]

http://hg.mozilla.org/mozilla-central/rev/7f988284253e
http://hg.mozilla.org/mozilla-central/rev/d7b6a97efd06
http://hg.mozilla.org/mozilla-central/rev/d856fe629ad2
http://hg.mozilla.org/mozilla-central/rev/052a1c415457