520100 - Audio/video sync lost after seeking into non-buffered ranges (sometimes)

Status: RESOLVED FIXED

(Core :: Audio/Video, defect)

Description

[Matthew Gregan [:kinetik]]

1. Wait for video to buffer a small amount little
2. Begin playback
3. Seek to near end (e.g. 7/8ths), outside of buffered range
4. Playback resumes briefly (plays a few frames of video/audio)
5. Pauses to buffer
6. Resumes playback and is out of sync

With the bug URL, it often ends up that the bip and bop noise are swapped, so it can be slightly deceptive--you need to make sure the noise matches the onomatopoeic text.

Also reproduced with http://tinyvid.tv/show/2r1d4f8jhhct

Comment 1

[Matthew Gregan [:kinetik]]

Reproduced in a build from http://hg.mozilla.org/mozilla-central/rev/bad2d2351f7f

Comment 2

[Matthew Gregan [:kinetik]]

Reproduced in a build from July 1st (http://hg.mozilla.org/mozilla-central/rev/d54a92a63aa7), so this looks like a plain bug rather than a regression.

Also reproduced in a build from mid-May, not long after initial A/V sync support landed: ftp://ftp.mozilla.org/pub/firefox/nightly/2009/05/2009-05-21-03-mozilla-central/

Comment 3

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

I could not reproduce this in last night's Windows nightly (on Windows 7), so this may be Mac only.

Comment 4

[Matthew Gregan [:kinetik]]

I think what's happening here is that the audio clock is running ahead during some cases of the play/pause/seek/resume state changes.  Once we stop feeding the audio buffer, if we take longer to call mAudioStream->Pause() than the length of buffer audio, the audio clock can run forward during XRUN processing.

In sydney_audio_mac.c#audio_callback, bytes_played is calculated as time_stamp->mSampleTime * bytes_per_frame, but we may not have that much data actually buffered--if an XRUN occurs, the rest of the OS buffer is memset to 0.  These silent samples are accounted for by the bytes_played calculation despite not being real samples, allowing the audio clock to run ahead of where it should be.

Changing bytes_played to the sum of the actual samples written (excluding the silent XRUN samples) looks like the correct fix, and seems to solve this problem.  I'll test a little more before I post a patch.

This may explain why the problem wasn't visible on other platforms.  On Linux/ALSA, the audio clock stops ticking if an XRUN occurs.  I'm not sure how Win32 behaves in this situation and will need to verify that.

Comment 5

[Matthew Gregan [:kinetik]]

Attachment: patch v0

This seems to fix the problem.  I can see these symptoms occurring with observable loss of a/v sync, and I can't reproduce that case with the patch applied.  Not for review because I need to verify that bytes_played is reset in all of the necessary places.

Markus, you were pretty fast at reproducing this originally.  If you have a chance, could you try reproducing with this patch applied?

Comment 6

[Matthew Gregan [:kinetik]]

It looks like this patch will fix bug 520101, too.

Comment 7

[Rich Walsh]

Your patch puts the audio clock permanently out of sync with real time.  It also makes satisfactory playback performance dependent on the ratio of the input & output block sizes.

The data fed to the hardware by the callback (i.e. output) is expected to take a finite length of time to consume.  However, because you're adding it to bytes_played before the fact, it appears to be consumed instantaneously.  The value returned by sa_stream_get_position() will always be running ahead by the size of the callback's first write.

Whether this has any perceptible effect depends on the number of bytes delivered with each call to sa_stream_write()(i.e. input).  Last time I looked, the OGG decoder sent 4k or 8k blocks.  If the Mac callback only consumes a small fraction of the input block per invocation, then the time difference will also be small & performance will be good.  As the ratio of input to output diminishes, the upstream components will "think" they're running behind and may start dropping frames.  When the ratio reaches 1, it just gives up & stops playing.

While the explanation of the problems may be long-winded, the solution isn't: save the number of bytes written and add it to bytes_played on the next invocation of the callback.

Comment 8

[Matthew Gregan [:kinetik]]

The patch isn't complete yet, which is why I haven't asked for review.

As I've been looking into this more, I think the correct solution is to subtract the number of silent samples from the position computed from the callback timestamp.  This has the advantage of accounting for playback latency correctly (which counting the bytes written ourselves can't ever do), and keeps the behaviour close to what we had before.  I still need to verify the timestamp is sane after hotplugging a sound device (bug 520101) and do some more testing, though.

Comment 9

[Matthew Gregan [:kinetik]]

Accounting for silence written in the callback seems to solve the problem in this bug, but it doesn't solve bug 520101, and it also doesn't solve any problems in the case where the callback is called late but mSampleTime keeps advancing as if we'd written samples.

Comment 10

[Yury Delendik (:yury)]

The bug 598812 (c15) has an example that demonstrate this issue and might be a test.

Comment 11

[Yury Delendik (:yury)]

Attachment: Fixes libsyndey for MacOS: counts amount of missed audio sample bytes

Comment 12

[Matthew Gregan [:kinetik]]

+  int64_t           bytes_lost;

bytes_lost doesn't seem like the right name for this.  There has been no user audio data lost.  In fact, the opposite problem has occurred--sydneyaudio has inserted extra audio data to handle an underrun, so the audio clocks has advanced beyond what the library user might expect.

+  *pos = s->total_bytes_played + s->bytes_played - s->bytes_lost;

+  s->total_bytes_played += s->bytes_played - s->bytes_lost;

It seems like it's possible for bytes_lost to be larger than bytes_played, so these need underflow checks.

Comment 13

[Yury Delendik (:yury)]

Attachment: Fixes libsyndey for MacOS: counts amount of missed audio sample bytes (version 2)

Changed "bytes_lost" to "bytes_underrun_inserted" and fixed the (s->bytes_played - s->bytes_lost) underflow possibility.

Comment 14

[Matthew Gregan [:kinetik]]

+  if(bytes_played_wo_underrun > 0) {

Fix spacing, should be |if (bytes|.  Same in the other instance of this.

+  /*
+   * There was inserted the extra audio data (s->bytes_underrun_inserted bytes)
+   * to hanle underruns. Adjusting the audio clock to reflect the actual data
+   * played. Also, avoiding the case where s->bytes_underrun_inserted is larger 
+   * than s->bytes_played.
+   */

I think you can leave this comment out entirely, it's pretty obvious from the variable names now.

+  if(bytes_played_wo_underrun > 0) {
+    *pos = s->total_bytes_played + bytes_played_wo_underrun;
+  } else {
+    *pos = s->total_bytes_played;
+  }

This can just be:

*pos = s->total_bytes_played;
if (bytes_played_wo_underrun > 0) {
  *pos += bytes_played_wo_underrun;
}

Thanks!

Comment 15

[Yury Delendik (:yury)]

Attachment: Fixes libsyndey for MacOS: counts amount of missed audio sample bytes (version 3)

Comment 16

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

Landed: http://hg.mozilla.org/mozilla-central/rev/906231add940
Thanks for the patch!