919215 - AudioStream playout latency is too high, esp on Mac with internal mic/speakers

Status: VERIFIED FIXED

(Core :: Audio/Video, defect)

Description

[Randell Jesup [:jesup] (needinfo me)]

Note: this likely applies to ALL platforms, but may be (much) worse on some depending on the audio backend to cubeb and the OS.

Basically, the audio backend takes time to start, and while we're waiting data from MediaStreams buffers.  Once data callbacks start, the data buffered in the BufferedAudioStream is effectively "stuck: delay you won't get rid of.

One possible fix is to dump any buffered data beyond a base amount on the first data callback; this appears to work in practice (with limited testing).  If we need to buffer for some sources like streaming media, we could add API info that will let MediaStreamGraph block non-realtime streams while not blocking realtime streams.  (Note: the source mediastream here in testing was a getUserMedia stream, so it was already using a TrackUnion)

I'd consider asking for uplift of this bug to 26, especially if we can use the "simple" fix.

Comment 1

[Randell Jesup [:jesup] (needinfo me)]

Attachment: audio_latency

Comment 2

[Randell Jesup [:jesup] (needinfo me)]

Comment on attachment 808214 [details] [diff] [review]
audio_latency

r? to roc on if this is a good/acceptable idea as-is or if we need to change the API

Comment 3

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Comment on attachment 808214 [details] [diff] [review]
audio_latency

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

Paul or Matthew would be a better reviewer for this.

Comment 4

[Paul Adenot (:padenot)]

Comment on attachment 808214 [details] [diff] [review]
audio_latency

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

I have a better idea (in the sense that it won't cut the beginning of a media, and it does not add a magic value): when we allocate the stream [1], and then, in AudioStream::Init, if there is the LowLatency flag (from [2]), we |cubeb_stream_start()| right away, filling the buffers with silence until we have stuff written to mBuffer. I had some instrumentation to measure the stream allocation duration, and that showed that it really depends on the platform, so we really can't make assumptions.

Hopefully I'll have a patch ready for you to test when you wake up.

[1]: http://mxr.mozilla.org/mozilla-central/source/content/media/MediaStreamGraph.cpp#764
[2]: from a patches in bug 907817

::: content/media/AudioStream.cpp
@@ +872,5 @@
> +    mHasRun = true;
> +    while (2 * aFrames <= BytesToFrames(mBuffer.Length())) {
> +      GetUnprocessed(output, aFrames);
> +    }
> +  }

This would kind of work for what we want to do here, but it would also skip the beginning of a media played in a regular HTMLMediaElement, so we can't take it.

Also, keep in mind that aFrames is not a constant (we can't make any assumptions about it AT ALL: it can vary from thousands of bytes to a single frame in edge cases).

Comment 5

[Paul Adenot (:padenot)]

Attachment: Start the cubeb stream right away when low latency is requested, and let it underrun. r=

This gives better results on my PulseAudio/Linux machine. I haven't tested on my
Macbook yet, and I can't remember if the AudioUnit backend is slow to start.

This patch does two things:
- Stop writing silence to the stream, so it underruns and we get silence
anyways. This is probably not good enough.
- Start the stream right away when low latency is requested, so we don't have a
big initial delay.

If it does not compile, you might want to grab the queue at [1].

[1]: http://hg.mozilla.org/users/paul_paul.cx/patches-webrtc/

Comment 6

[Randell Jesup [:jesup] (needinfo me)]

(In reply to Paul Adenot (:padenot) from comment #4)

> ::: content/media/AudioStream.cpp
> @@ +872,5 @@
> > +    mHasRun = true;
> > +    while (2 * aFrames <= BytesToFrames(mBuffer.Length())) {
> > +      GetUnprocessed(output, aFrames);
> > +    }
> > +  }
> 
> This would kind of work for what we want to do here, but it would also skip
> the beginning of a media played in a regular HTMLMediaElement, so we can't
> take it.

As I suspected.

> Also, keep in mind that aFrames is not a constant (we can't make any
> assumptions about it AT ALL: it can vary from thousands of bytes to a single
> frame in edge cases).

Right.  It was expediency due to not bothering to add a "drop data" call to the buffer class.  And I suspected this patch wasn't the right end solution, so I didn't want to spend a lot of time to change APIs; I wanted mostly to verify if it solved he problem (which it did).

Comment 7

[Paul Adenot (:padenot)]

Attachment: Start the cubeb stream right away when low latency is requested, and let it underrun. r=

Comment 8

[Paul Adenot (:padenot)]

Attachment: Start the cubeb stream right away when low latency is requested, and let it underrun. r=

This gives us a nice latency optimization as well.

The idea is that we let the AudioStream underrun (but this is safe, because
DataCallback takes care of putting silence in the buffer).

Then, when we get our first bit of non-silent data, we start putting real data
at the _end_ of the callback buffer, so we don't have a little bit of silence.

It does feel like a hack, but it definitly improves the situation.

Comment 9

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Comment on attachment 818431 [details] [diff] [review]
Start the cubeb stream right away when low latency is requested, and let it underrun. r=

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

::: content/media/AudioSegment.cpp
@@ -154,5 @@
>        } else {
>          // Assumes that a bit pattern of zeroes == 0.0f
>          memset(buf.Elements(), 0, buf.Length()*sizeof(AudioDataValue));
>        }
> -      aOutput->Write(buf.Elements(), int32_t(duration));

I don't understand this change. This changes behavior for high-latency streams as well as low-latency. Why are you just dropping null buffers, anyway? They should produce silence. Also what's the point of zeroing the buffer now?

Comment 10

[Randell Jesup [:jesup] (needinfo me)]

Comment on attachment 818431 [details] [diff] [review]
Start the cubeb stream right away when low latency is requested, and let it underrun. r=

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

::: content/media/AudioSegment.cpp
@@ -154,5 @@
>        } else {
>          // Assumes that a bit pattern of zeroes == 0.0f
>          memset(buf.Elements(), 0, buf.Length()*sizeof(AudioDataValue));
>        }
> -      aOutput->Write(buf.Elements(), int32_t(duration));

I believe the reason for moving the Write() is to let AudioStream::DataCallback() handle underruns (if any).

I agree the memset() is now spurious.

Comment 11

[Paul Adenot (:padenot)]

Ha, yes, indeed, this memset is useless, now. Also, if we are here, we are using a low-latency stream, since when calling the AudioStream ctor in the MSG, we pass in the low-latency flag.

Comment 12

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Null chunks arriving here might not be at the beginning of the stream. We can't just drop them.

Comment 13

[Ivan Tsay (:ITsay)]

Plus this bug for v1.3 since it block the committed webRTC feature for audio P2P

Comment 14

[Randell Jesup [:jesup] (needinfo me)]

I don't think this blocks 1.3/B2G unless someone proves it applies there; we can no proof it causes any user-visible problems on anything except Mac.

Paul - what's the status on landing this?  I'd like to get it landed and at least uplifted to Aurora if we can.

Comment 15

[Paul Adenot (:padenot)]

Attachment: Start the cubeb stream right away when low latency is requested, and let it underrun. r=

This should be safer.

Comment 16

[Paul Adenot (:padenot)]

pushed to try: https://tbpl.mozilla.org/?tree=Try&rev=b6c0f01cc505

Comment 17

[Paul Adenot (:padenot)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/37153a22e87a

Comment 18

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/37153a22e87a

Comment 20

[Maire Reavy [:mreavy]]

Updating the target milestone to Firefox 28 since that is when this landed.

Comment 21

[Jason Smith [:jsmith]]

(In reply to Randell Jesup [:jesup] from comment #14)
> I don't think this blocks 1.3/B2G unless someone proves it applies there; we
> can no proof it causes any user-visible problems on anything except Mac.
> 
> Paul - what's the status on landing this?  I'd like to get it landed and at
> least uplifted to Aurora if we can.

Okay, sounds good. Moving to blocking- then.

Comment 23

[Randell Jesup [:jesup] (needinfo me)]

Comment on attachment 8333556 [details] [diff] [review]
Start the cubeb stream right away when low latency is requested, and let it underrun. r=

[Approval Request Comment]
Bug caused by (feature/regressing bug #): n/a

Note: I had suggested in comment 14 that we wanted it landed and uplifted to Aurora (then 27) asap, so now I'm requesting Beta(27) uplift.

User impact if declined: Macs (and some other platforms maybe) can get horrible output delay especially when using built-in speakers/mic (1/2 second or more)

Testing completed (on m-c, etc.): On m-c and aurora (28).  Baked for over a month with no regressions.

Risk to taking this patch (and alternatives if risky): Low, and most risk would be of audio glitches

String or IDL/UUID changes made by this patch: none

Needinfo-ing to padenot to verify my comments above.

Comment 24

[Lukas Blakk [:lsblakk] use ?needinfo]

Comment on attachment 8333556 [details] [diff] [review]
Start the cubeb stream right away when low latency is requested, and let it underrun. r=

since we have extra time on beta with FF27 we can take this now, still early enough to get more feedback before release.

Comment 25

[Randell Jesup [:jesup] (needinfo me)]

https://hg.mozilla.org/releases/mozilla-beta/rev/2d1a46b92459

Comment 26

[u279076]

Paul, please verify this is fixed in the latest Firefox 27 and 28 builds when you get back from holidays in January.

Comment 27

[Paul Silaghi, QA [:pauly]]

(In reply to Randell Jesup [:jesup] from comment #23)
> User impact if declined: Macs (and some other platforms maybe) can get
> horrible output delay especially when using built-in speakers/mic (1/2
> second or more)
Our miniMacs don't have built-in mics AFAICT. I've tried to use only the internal speakers with external mics, but I couldn't reproduce the problem on some builds before the fix. This would be probably best to try on 2 iMacs.
Any suggestions ?

Comment 28

[u279076]

(In reply to Paul Silaghi, QA [:pauly] from comment #27)

Marc, is this something you can organize with QA resources in Mountain View?

Comment 29

[Marc Schifer [mschifer]]

If we can use Mac Books for this I can help out. Not sure we have enough iMacs around the office here otherwise. Do we have a good set of steps to reproduce?

Comment 30

[u279076]

Randell, can you answer comment 29?

Comment 31

[Randell Jesup [:jesup] (needinfo me)]

Sorry for the delay.  You need a mac where the audio drivers take a while to start.  I know this happens on my MacBook Pro 2011 with OSX 10.7.  No idea when/how often/where else it happens, you have to try and see.  I suspect this can happen on other OSes in theory, and might be happening in smaller amounts on Win7 (again depending on audio drivers, which are more variable on Windows).

Downside: I was just trying this, and while it appears to be better, the base problem does not appear to be solved.  This patch moves low-latency opens of cubeb earlier, but that doesn't guarantee enough time for cubeb to open and start making callbacks.  On my mac it can take up to 500ms (or more).

Comment 32

[Paul Adenot (:padenot)]

A possible solution that would work would be to drop the samples on the the floor when AudioStream::Write()ing until we received our _second_ callback (because there is some prefill logic: when the stream is started, the callback is called manually).

Comment 33

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Drop any extra queued audio data on low-latency startup

doesn't deal with prefill separately - contracts to the request size on first call

Comment 34

[Randell Jesup [:jesup] (needinfo me)]

Comment on attachment 8403542 [details] [diff] [review]
Drop any extra queued audio data on low-latency startup

This should work (even if it's not optimal); I'd like more details on any preload/initial-buffer-filling if we want to try to address that.

Comment 35

[Randell Jesup [:jesup] (needinfo me)]

Comment on attachment 8403542 [details] [diff] [review]
Drop any extra queued audio data on low-latency startup

Pulling r? for the moment until I do some more testing and add some logging

Comment 36

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Wouldn't Paul be a better reviewer here anyway?

Comment 37

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Drop queued audio data on low-latency startup, make AudioStream::Init() async

works.  One issue left to resolve - the raw ptr in AudioInitTask

Comment 38

[Randell Jesup [:jesup] (needinfo me)]

Comment on attachment 8404267 [details] [diff] [review]
Drop queued audio data on low-latency startup, make AudioStream::Init() async

f? to roc & padenot - only reason I'm not asking review is I still need to resolve the pointer to the AudioStream in the task I spawn; right now it's raw and unlocked.  making AudioStream refcounted would work but be more invasive.  There are some other possibilities; I'm open to suggestion/preference.  Also, we could make the task persistent if we think it helps, though that complicates the cleanup code.

The task is mildly patterned on CryptoTask

Comment 39

[Randell Jesup [:jesup] (needinfo me)]

Explanation: Turns out on Mac (at least my Macbook Pro 2011 10.7) starting cubeb for internal audio can take 300-850ms typically; and I sometimes would see up to 8.5 seconds.  Right now, it stalls MSG until the cubeb stream starts, which is very, very bad and leaves us with an N ms permanent delay in MSG.

Comment 40

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Comment on attachment 8404267 [details] [diff] [review]
Drop queued audio data on low-latency startup, make AudioStream::Init() async

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

::: content/media/AudioStream.h
@@ +421,5 @@
> +    , mParams(aParams)
> +  {}
> +
> +  template <size_t LEN>
> +  nsresult Dispatch(const char (&taskThreadName)[LEN])

Get rid of this name stuff

@@ +444,5 @@
> +    }
> +    return rv;
> +  }
> +
> +  AudioStream *mAudioStream; // FIX! ownership/lifetime

Can't we just make this a strong reference?

Comment 41

[Randell Jesup [:jesup] (needinfo me)]

Attachment: interdiffs from WIP to make AudioStream refcounted

interdiffs to remove threadname stuff and make AudioStream be refcounted

Comment 42

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Drop queued audio data on low-latency startup, make AudioStream::Init() async

Comment 43

[Randell Jesup [:jesup] (needinfo me)]

Attachment: interdiffs for <video> playback race fix

Comment 44

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Drop queued audio data on low-latency startup, make AudioStream::Init() async

Comment 45

[Matthew Gregan [:kinetik]]

Comment on attachment 8404437 [details] [diff] [review]
Drop queued audio data on low-latency startup, make AudioStream::Init() async

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

::: content/media/AudioStream.h
@@ +9,5 @@
>  #include "AudioSampleFormat.h"
>  #include "AudioChannelCommon.h"
>  #include "nsAutoPtr.h"
>  #include "nsAutoRef.h"
> +#include "nsAutoRef.h"

Double include (and the additions in this patch don't use nsAutoRef anyway...)

@@ +208,2 @@
>    AudioStream();
> +  virtual ~AudioStream();

Make this private to encourage Release() rather than buggy delete calls.

Comment 46

[Randell Jesup [:jesup] (needinfo me)]

Attachment: interdiff for init thread shutdown

Comment 47

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Drop queued audio data on low-latency startup, make AudioStream::Init() async

Comment 48

[Randell Jesup [:jesup] (needinfo me)]

I'll also address kinetik's nits

Comment 49

[Randell Jesup [:jesup] (needinfo me)]

Attachment: open_delay_interdiff

Looking pretty green so far at https://tbpl.mozilla.org/?tree=Try&rev=874be59ef366  

This makes Drain() not assert if the stream has hit an error (such as failing to init in the crashtest that tries to start 200 streams in no time), and fixes a missing state test in Pause(), plus adds a bunch of logs and makes streaming opens synchronous again (to minimize timing changes that upset the tests).

For the synchronous stuff, I moved all the cubeb open code into a method on AudioStream (which makes more sense anyways), so I can call it synchronously or from the init thread.

Comment 50

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Comment on attachment 8405112 [details] [diff] [review]
open_delay_interdiff

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

::: content/media/MediaDecoderStateMachine.cpp
@@ +781,4 @@
>  
> +  {
> +    // AudioStream initialization can block for extended periods in unusual
> +    // circumstances, so we take care to drop the decoder monitor while

say "not hold" rather than "drop" since you're not actually dropping it

Comment 51

[Randell Jesup [:jesup] (needinfo me)]

Remaining problems seem to all be Win7/Win8 (wasapi).  Adding kinetik to CC list.  We have at least one crash in wasapi's refill_with_resampling(). ('out' isn't accessible it appears).

Made a few improvements to theoretical holes in Shutdown/Pause() (no real affect on the results).  A bit of cleanup in error cases.

patch queue published here:
http://hg.mozilla.org/users/rjesup_wgate.com/audiostream_open

Try with earlier version with logging turned on:
https://tbpl.mozilla.org/?tree=Try&rev=03c8799a0ad7

Note: I can reproduce (at least some of) these errors locally, and catch them in an attached VS (modulo the mochitest timeout killing us).  I run it against dom/media/tests/mochitests/ (aka M3)

Old try without logging:
https://tbpl.mozilla.org/?tree=Try&rev=874be59ef366

Comment 52

[Randell Jesup [:jesup] (needinfo me)]

Updated patch queue and Try (more logging on what is failing and Shutdown/etc)
https://tbpl.mozilla.org/?tree=Try&rev=a87be2a9ebd7

Comment 53

[Randell Jesup [:jesup] (needinfo me)]

Fixed a AudioStream::Shutdown() vs wasapi deadlock; updated queue, pushed new try:  https://tbpl.mozilla.org/?tree=Try&rev=4e62811076a3

Comment 54

[Randell Jesup [:jesup] (needinfo me)]

Ok, the try was a big improvement for M3 (probably due to the extra code to cleanup/lock Pause and Shutdown), and M3 is now clean.  We are getting quite a few known M1 oranges from media and webaudio tests; this might be related to the logging (unlikely but possible, however a bunch of the oranges are on Opt builds with no debugging) or to timing changes due to the patches.

We also have a few instances of failure-to-exit-at-shutdown (which likely matches a known orange); the stacks appear to show cubeb/wasapi is in shutdown (*_destroy() called) and is waiting for something; there are 3 wasapi render threads waiting on something.  My guess is there's a deadlock there occasionally.

Comment 55

[Randell Jesup [:jesup] (needinfo me)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=37701685&tree=Try&full=1#error0
is another wasapi deadlock.  wasapi_destroy_stream is waiting after signaling shutdown; there are 5 streams in the render loop idle.

Comment 56

[Matthew Gregan [:kinetik]]

Clearing needinfo; discussed on IRC.

Comment 57

[Randell Jesup [:jesup] (needinfo me)]

Attachment: interdiffs for dealing with shutdown locking issues and cubeb/wasapi thread requirements

Comment 58

[Randell Jesup [:jesup] (needinfo me)]

Attachment: audiostream_all

Rollup of the two previously r+'d patches and the interdiff patch for shutdown/wasapi issues.

Comment 59

[Randell Jesup [:jesup] (needinfo me)]

Comment on attachment 8406162 [details] [diff] [review]
interdiffs for dealing with shutdown locking issues and cubeb/wasapi thread requirements

The previous two parts were r+d by roc already.  I attached a rollup patch to show what will be pushed and for context.

Comment 60

[Paul Adenot (:padenot)]

Comment on attachment 8406164 [details] [diff] [review]
audiostream_all

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

::: content/media/AudioStream.cpp
@@ +702,5 @@
> +    MOZ_ASSERT(mState != STARTED && mState != RUNNING); // paranoia
> +    mState = SHUTDOWN;
> +  }
> +  // Must not try to shut down cubeb from within the lock!  wasapi may still
> +  // call our callback after Pause()/stop()!?!

We need a bug number for this, and put it there. This is clearly a bug.

@@ +902,5 @@
>    uint32_t underrunFrames = 0;
>    uint32_t servicedFrames = 0;
>    int64_t insertTime;
>  
> +  // NOTE: wasapi (others?) can call us back *after* stop()/Shutdown() (mState == SHUTDOWN)

Same.

Comment 61

[Randell Jesup [:jesup] (needinfo me)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/40260af420a7

Comment 62

[Paul Adenot (:padenot)]

Comment on attachment 8406162 [details] [diff] [review]
interdiffs for dealing with shutdown locking issues and cubeb/wasapi thread requirements

(I r+ed the whole patch, cancelling the r? on the interdiff).

Comment 63

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/40260af420a7

Comment 64

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 8333556 [details] [diff] [review]
Start the cubeb stream right away when low latency is requested, and let it underrun. r=

Per discussion with jesup on IRC, I'm removing the old approval on this so it doesn't appear on my "patches needing uplift" bug queries.

Comment 65

[Ryan VanderMeulen [:RyanVM]]

For future archeological purposes, note that the "fixed" status for Fx27/Fx28 is only in reference to attachment 8333556 [details] [diff] [review], not the later patch that landed for Fx31 in comment 61.

Comment 66

[u279076]

Paul, can you please verify this is fixed? Thanks.

Comment 67

[Paul Silaghi, QA [:pauly]]

(In reply to Anthony Hughes, QA Mentor (:ashughes) from comment #66)
> Paul, can you please verify this is fixed? Thanks.
I'm not sure I can. See comment 27

Comment 68

[Paul Adenot (:padenot)]

Paul, Anthony, this is only affecting _some_ macs, and if you don't have the exact right model, it's impossible to repro.

Jesup has verified that it fixes it for him (he has an affected mac), no need to do more here, I think.

Comment 69

[Paul Silaghi, QA [:pauly]]

Thanks Paul.
Marking qa- based on comment 68.

Comment 70

[Karl Tomlinson (:karlt)]

Marking requirements for these changes as dependencies, separating them from issues depending on these changes.