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

VERIFIED FIXED in Firefox 27

Status

()

defect
--
major
VERIFIED FIXED
6 years ago
5 years ago

People

(Reporter: jesup, Assigned: jesup)

Tracking

(Blocks 2 bugs)

unspecified
mozilla31
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(blocking-b2g:-, firefox26 wontfix, firefox27 fixed, firefox28 fixed, firefox31 fixed)

Details

(Whiteboard: [ft:webrtc][ft:webrtc][qa-][s=fx32, c=webrtc])

Attachments

(9 attachments, 7 obsolete attachments)

7.59 KB, patch
padenot
: review-
Details | Diff | Splinter Review
10.43 KB, patch
roc
: review+
Details | Diff | Splinter Review
9.80 KB, patch
Details | Diff | Splinter Review
3.33 KB, patch
Details | Diff | Splinter Review
2.44 KB, patch
Details | Diff | Splinter Review
23.76 KB, patch
roc
: review+
Details | Diff | Splinter Review
15.91 KB, patch
roc
: review+
Details | Diff | Splinter Review
10.26 KB, patch
Details | Diff | Splinter Review
27.49 KB, patch
padenot
: review+
Details | Diff | Splinter Review
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.
Posted patch audio_latencySplinter Review
Attachment #808214 - Flags: review?(paul)
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
Attachment #808214 - Flags: review?(roc)
Summary: Mac audio playout latency with internal mic/speakers in use is too high → AudioStream playout latency is too high, esp on Mac with internal mic/speakers
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.
Attachment #808214 - Flags: review?(roc)
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).
Attachment #808214 - Flags: review?(paul) → review-
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/
Assignee: nobody → paul
(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).
Attachment #808491 - Attachment is obsolete: true
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.
Attachment #818431 - Flags: review?(roc)
Attachment #810663 - Attachment is obsolete: true
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?
Attachment #818431 - Flags: review?(roc) → review-
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.
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.
Null chunks arriving here might not be at the beginning of the stream. We can't just drop them.
Plus this bug for v1.3 since it block the committed webRTC feature for audio P2P
blocking-b2g: --- → 1.3+
Whiteboard: [webrtc][webrtc-uplift] → [webrtc][webrtc-uplift][ft:webrtc][ft:webrtc]
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.
blocking-b2g: 1.3+ → 1.3?
Flags: needinfo?(paul)
No longer blocks: 923363
Attachment #818431 - Attachment is obsolete: true
Flags: needinfo?(paul)
https://hg.mozilla.org/mozilla-central/rev/37153a22e87a
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Duplicate of this bug: 921365
Updating the target milestone to Firefox 28 since that is when this landed.
Target Milestone: mozilla27 → mozilla28
(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.
blocking-b2g: 1.3? → -
Duplicate of this bug: 937505
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.
Attachment #8333556 - Flags: approval-mozilla-beta?
Flags: needinfo?(paul)
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.
Attachment #8333556 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Flags: needinfo?(paul)
Whiteboard: [webrtc][webrtc-uplift][ft:webrtc][ft:webrtc] → [webrtc][ft:webrtc][ft:webrtc]
Paul, please verify this is fixed in the latest Firefox 27 and 28 builds when you get back from holidays in January.
Flags: needinfo?(paul.silaghi)
Keywords: verifyme
(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 ?
Flags: needinfo?(paul.silaghi)
(In reply to Paul Silaghi, QA [:pauly] from comment #27)

Marc, is this something you can organize with QA resources in Mountain View?
Flags: needinfo?(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?
Flags: needinfo?(mschifer)
Randell, can you answer comment 29?
Flags: needinfo?(rjesup)
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).
Status: RESOLVED → REOPENED
Flags: needinfo?(rjesup)
Resolution: FIXED → ---
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).
Blocks: 970426
doesn't deal with prefill separately - contracts to the request size on first call
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.
Attachment #8403542 - Flags: review?(roc)
Assignee: paul → rjesup
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
Attachment #8403542 - Flags: review?(roc)
Wouldn't Paul be a better reviewer here anyway?
works.  One issue left to resolve - the raw ptr in AudioInitTask
Attachment #8403542 - Attachment is obsolete: true
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
Attachment #8404267 - Flags: feedback?(roc)
Attachment #8404267 - Flags: feedback?(paul)
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 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?
Attachment #8404267 - Flags: feedback?(roc) → feedback+
interdiffs to remove threadname stuff and make AudioStream be refcounted
Attachment #8404267 - Attachment is obsolete: true
Attachment #8404267 - Flags: feedback?(paul)
Attachment #8404375 - Flags: review?(roc)
Attachment #8404375 - Attachment is obsolete: true
Attachment #8404375 - Flags: review?(roc)
Attachment #8404437 - Flags: review?(roc)
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.
Attachment #8404437 - Attachment is obsolete: true
Attachment #8404493 - Flags: review?(roc)
I'll also address kinetik's nits
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.
Attachment #8405112 - Flags: review?(roc)
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
Attachment #8405112 - Flags: review?(roc) → review+
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
Updated patch queue and Try (more logging on what is failing and Shutdown/etc)
https://tbpl.mozilla.org/?tree=Try&rev=a87be2a9ebd7
Fixed a AudioStream::Shutdown() vs wasapi deadlock; updated queue, pushed new try:  https://tbpl.mozilla.org/?tree=Try&rev=4e62811076a3
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.
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.
Flags: needinfo?(kinetik)
Clearing needinfo; discussed on IRC.
Flags: needinfo?(kinetik)
Rollup of the two previously r+'d patches and the interdiff patch for shutdown/wasapi issues.
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.
Attachment #8406162 - Flags: review?(paul)
Blocks: 921622
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.
Attachment #8406164 - Flags: review+
Blocks: 996162
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).
Attachment #8406162 - Flags: review?(paul)
https://hg.mozilla.org/mozilla-central/rev/40260af420a7
Status: REOPENED → RESOLVED
Closed: 6 years ago5 years ago
Resolution: --- → FIXED
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.
Attachment #8333556 - Flags: approval-mozilla-beta+
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.
Paul, can you please verify this is fixed? Thanks.
QA Contact: paul.silaghi
(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
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.
Thanks Paul.
Marking qa- based on comment 68.
Keywords: verifyme
Whiteboard: [webrtc][ft:webrtc][ft:webrtc] → [webrtc][ft:webrtc][ft:webrtc][qa-]
Status: RESOLVED → VERIFIED
Blocks: 997286
Depends on: 996487
No longer depends on: 996487
Marking requirements for these changes as dependencies, separating them from issues depending on these changes.
No longer blocks: 997286
Depends on: 997286, 996487
Whiteboard: [webrtc][ft:webrtc][ft:webrtc][qa-] → [webrtc][ft:webrtc][ft:webrtc][qa-][s=fx32]
Whiteboard: [webrtc][ft:webrtc][ft:webrtc][qa-][s=fx32] → [ft:webrtc][ft:webrtc][qa-][s=fx32, c=webrtc]
You need to log in before you can comment on or make changes to this bug.