1085356 - Mac audio problems when changing output devices (regression)

Status: RESOLVED FIXED

(Core :: WebRTC, defect)

Description

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

[Tracking Requested - why for this release]:
Very important for using macs with webrtc - 1 second echo if the user plugs/unplugs headsets during a call.

Regression from bug 848954 - we seem to have lost the "reset output if the audio output is changed by the OS" (i.e. user selected or plug/unplug headset) on mac.

Also verify (and add logs back) for the panning support for macbookpros

Comment 1

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

Attachment: reset audio output on Mac if output device changes

Comment 2

[Paul Adenot (:padenot)]

Attachment: Fall back temporarily to a SystemClockDriver on device change

This is crazy, so make sure too read the commit message and all the comments I've put in. It works, though.

There are still a lot of printfs and it needs cleanup (so most of this is disabled on other platforms, etc.).

Comment 3

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

Comment on attachment 8509487 [details] [diff] [review]
Fall back temporarily to a SystemClockDriver on device change

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

Not as ugly as I feared, outside of the "gets called back somtimes" part, which we can't control.  Too bad they don't specify a clean state transition for this.

::: content/media/GraphDriver.cpp
@@ +79,5 @@
>  }
>  
>  void GraphDriver::SwitchAtNextIteration(GraphDriver* aNextDriver)
>  {
> +  // This is the situation where `mPreviousDriver` is an AudioCallbackDriver

"This handles the" ...

@@ +80,5 @@
>  
>  void GraphDriver::SwitchAtNextIteration(GraphDriver* aNextDriver)
>  {
> +  // This is the situation where `mPreviousDriver` is an AudioCallbackDriver
> +  // that is switching device, and the graph has found the current driver is not

devices

@@ +1010,5 @@
>  void
>  AudioCallbackDriver::DeviceChangedCallback() {
>    MonitorAutoLock mon(mGraphImpl->GetMonitor());
>    PanOutputIfNeeded(mMicrophoneActive);
> +  // On OSX, changing the output device causes the audio thread to no call the

s/no/not/

::: content/media/GraphDriver.h
@@ +473,5 @@
> +  /* Self-reference that keep this driver alive when switching output audio
> +   * device and making the graph running temporarily off a SystemClockDriver.  */
> +  SelfReference<AudioCallbackDriver> mSelfReference;
> +  /* While switching devices, we keep track of the number of callback received,
> +   * since OSX seem to still call us _sometimes_. */

seems

::: content/media/webaudio/AudioNode.h
@@ +16,5 @@
>  #include "MediaStreamGraph.h"
>  #include "WebAudioUtils.h"
>  #include "mozilla/MemoryReporting.h"
>  #include "nsWeakReference.h"
> +#include "SelfRef.h"

SelfRef.h is missing

Comment 4

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

For an upliftable patch: I'd also be ok with just switching to a internally-clocked driver and opening a new callback driver, and have it SwitchOnNextIteration when the new driver sees a callback.  While fundamentally the same, it may remove the need for some of the additional if() clauses.  If this doesn't help, then I'm not sure what out options are other than uplifting the entire patch.  If so, then we ask to.

Comment 5

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

Try was green other than 10.8 which never ran (not enough 10.8 test machines); I cancelled them after 12 hours waiting.  I'd say we good to review; I may proactively review the patch from the try

Comment 6

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

Attachment: Fall back temporarily to a SystemClockDriver on device change (from latest Try)

Comment 7

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

Comment on attachment 8511301 [details] [diff] [review]
Fall back temporarily to a SystemClockDriver on device change (from latest Try)

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

r+ with nits and addition of DISALLOW copy/assign

::: content/media/GraphDriver.cpp
@@ +786,5 @@
>    mDriver->mInCallback = false;
>  }
>  
> +#ifdef XP_MACOSX
> +long

bool

@@ +1035,5 @@
> +  mSelfReference.Take(this);
> +  mCallbackReceivedWhileSwitching = 0;
> +  mNextDriver = new SystemClockDriver(GraphImpl());
> +  mNextDriver->SetGraphTime(this, mIterationStart, mIterationEnd,
> +                             mStateComputedTime, mNextStateComputedTime);

indent is off (nit)

::: content/media/GraphDriver.h
@@ +482,5 @@
>     * the graph's monitor. */
>    bool mMicrophoneActive;
> +
> +#ifdef XP_MACOSX
> +  long OSXDeviceSwitchingWorkaround();

bool, maybe a 1-liner comment

@@ +486,5 @@
> +  long OSXDeviceSwitchingWorkaround();
> +  /* Self-reference that keep this driver alive when switching output audio
> +   * device and making the graph running temporarily off a SystemClockDriver.  */
> +  SelfReference<AudioCallbackDriver> mSelfReference;
> +  /* While switching devices, we keep track of the number of callback received,

callbacks

@@ +487,5 @@
> +  /* Self-reference that keep this driver alive when switching output audio
> +   * device and making the graph running temporarily off a SystemClockDriver.  */
> +  SelfReference<AudioCallbackDriver> mSelfReference;
> +  /* While switching devices, we keep track of the number of callback received,
> +   * since OSX seem to still call us _sometimes_. */

seems

::: content/media/SelfRef.h
@@ +35,5 @@
> +
> +  operator bool() const { return mHeld; }
> +
> +private:
> +  bool mHeld;

I suspect we need to disallow Copy/etc here, since a Copy wouldn't grab an AddRef

Comment 8

[Paul Adenot (:padenot)]

Attachment: Better handling of OSX audio output devices switching when SourceMediaStream are present in the MSG. r=

On OSX, when the audio output device changes, the OS will call the audio
callbacks in weird patterns, if at all, during a period of ~1s. If
real-time SourceMediaStreams are present in the MediaStreamGraph, this means
buffering will occur, and the overall latency between the MediaStreamGraph
insertion time, and the actual output time will grow.

To fix this, we detect when the output device changes, and we switch temporarily
to a SystemClockDriver, that will pull from the SourceMediaStream, and simply
discard all input data. Then, when we get audio callbacks called reliably
(basically, when OSX is done switching to the other output), we switch back to
the previous AudioCallbackDriver.

We keep the previous AudioCallbackDriver alive using a self-reference. If an
AudioCallbackDriver has a self-reference, that means it's in a state when a
device is switching, so it's not linked to an MSG per se.

Comment 9

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

https://hg.mozilla.org/integration/mozilla-inbound/rev/7c59e2ab04e2

Comment 10

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/7c59e2ab04e2

Comment 11

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

Attachment: WIP patch to forget buffered data from before output change callback

Comment 12

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

Note: very WIP, doesn't actually work (throws underflows); the min(ticks, 30ms) was a hack to see if leaving more in the buffer would avoid the underruns (it doesn't).  Likely I'm not handling some subtlety of FlushAllBut()... Perhaps something involving the blocked time?  (but MSG's time didn't move forward while we weren't getting called back.  On the other hand, we don't know exactly how many callbacks were missed, and thus how much data we *should* be removing.)

Comment 13

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

Comment on attachment 8513270 [details] [diff] [review]
WIP patch to forget buffered data from before output change callback

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

::: dom/media/MediaSegment.h
@@ +185,5 @@
> +    if (mChunks.IsEmpty()) {
> +      return;
> +    }
> +    if (mChunks[0].IsNull()) {
> +      TrackTicks extraToForget = (mDuration - mChunks[0].GetDuration()) - aRemaining;

You seem to assume that the leading Null chunk is exactly the content that has been consumed already via ForgetUpTo. That's not necessarily the case; part of the leading null data might be null because something wanted to generate silence efficiently, and this hasn't been consumed yet.

Instead of FlushAllBut you should probably just call RemoveLeading with the amount of data you want to remove. I'm not sure how to calculate how much that is, and I suspect you aren't either? :-( Maybe you can convert the graph currenttime to the stream time, and remove "track duration minus stream time minus aRemaining"?

Comment 14

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

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #13)
> Comment on attachment 8513270 [details] [diff] [review]
> You seem to assume that the leading Null chunk is exactly the content that
> has been consumed already via ForgetUpTo. That's not necessarily the case;
> part of the leading null data might be null because something wanted to
> generate silence efficiently, and this hasn't been consumed yet.

Ah, yes.   Hmmm.  It's quite unfortunate that a segment or StreamBuffer doesn't know internally how much data it has (what it's position in the mDuration timeline it is).

> Instead of FlushAllBut you should probably just call RemoveLeading with the
> amount of data you want to remove. I'm not sure how to calculate how much
> that is, and I suspect you aren't either? :-( Maybe you can convert the
> graph currenttime to the stream time, and remove "track duration minus
> stream time minus aRemaining"?

Perhaps.  I'm concerned however that what you are talking about here, while wrong in some edge cases, isn't the reason it totally fails when I use it as-is -- there's more hidden state somewhere that needs to be rolled back to "undo" the extra AppendToTracks that happened while we were frozen.


There's one other long-term solution: we're still missing an adaptive resampler at realtime inputs to MSG.  An adaptive resampler could deal with the buildup gradually - you'd have an up-to 1 sec delay after output changes, but it would bleed away over N seconds.  That isn't doable immediately, and not upliftable (and certainly not to beta).

Comment 15

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

Attachment: Fix Mac output changes on older/different macs

works (on 10.7.5 - will check 10.9 and 10.6)

Comment 16

[Paul Adenot (:padenot)]

Comment on attachment 8513508 [details] [diff] [review]
Fix Mac output changes on older/different macs

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

::: dom/media/MediaStreamGraphImpl.h
@@ +610,5 @@
>     */
>    bool mPostedRunInStableStateEvent;
>  
> +  bool mFlushSourcesNow;
> +  bool mFlushSourcesOnNextIteration;

Comments on those two?

::: dom/media/TrackUnionStream.cpp
@@ +307,5 @@
>          map->mEndOfLastInputIntervalInInputStream = inputEnd;
>          map->mEndOfLastInputIntervalInOutputStream = outputEnd;
> +
> +        if (GraphImpl()->mFlushSourcesNow) {
> +          TrackTicks flushto  = inputEndTicks;

nit: s/  / /

Comment 17

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

https://hg.mozilla.org/integration/mozilla-inbound/rev/8ccb2bf14892

Comment 18

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/8ccb2bf14892

Comment 19

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

FYI, I've tested this on:
MacBookPro 2013 13" 10.9.4
MacbookPro 2011 15" 10.7.5 (longest delay)
MacbookPro 2011 13" 10.6

Good on all of them

Note: usually/always this happens on earbud (analog) plugin.  Also known to happen on 10.8(?) when switching to external speakers during a call.  USB headsets seem to not cause it, or cause it much more rarely.

Comment 20

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

verified on all above on m-c Nightlies

Comment 21

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

Comment on attachment 8511379 [details] [diff] [review]
Better handling of OSX audio output devices switching when SourceMediaStream are present in the MSG. r=

Approval Request Comment
[Feature/regressing bug #]: bug 848954 (MSG refactor)
This functionality was accidentally lost during the refactor

[User impact if declined]: Macs (especially laptops) will get long added delay to audio when plugging/unplugging headsets (especially analog) or switching to/from external speakers.  The amount varies by Mac and by OS version, but can range from 100's of ms to 1 second. Multiple switches will accumulate more delay as well.  Note that these delays may impact non-webrtc uses of the MediaStreamGraph as well, since the graph stalls at this time.  Webaudio itself might simply thus pause, but this may throw it out of sync with other things occuring (games, etc).

[Describe test coverage new/current, TBPL]: Not testable in automation.  Manually tested in m-c nightly on 3 different models of MacBookPro on 3 different OS versions.  Will try to add 10.8 and Yosemite before uplift.

[Risks and why]: Moderate to moderate-low risk.  Changes are larger than I'd have liked, but reasonably straightforward.  The flush part in the second patch was less obvious, but has little risk from a security or crash perspective - the only complexity there was figuring out the right calculation to remove the accumulated data.  Almost certainly this will not do anything worse than happens today, and even if the fix is incomplete in some hardware/scenario it's likely to do no harm.  Highest risk would be some timing/reference flub in changing drivers, but we do that in normal operation anyways.

[String/UUID change made/needed]: none

Comment 22

[Lawrence Mandel [:lmandel] (use needinfo)]

Comment on attachment 8511379 [details] [diff] [review]
Better handling of OSX audio output devices switching when SourceMediaStream are present in the MSG. r=

I reviewed this change with Randell. The user impact is noticeable enough to warrant taking this moderate risk patch on Beta. Let's take this in Beta 6, which will give us 3 additional Beta builds to deal with any fallout. Beta+

Aurora+

Comment 23

[John Ford [:jhford] CET/CEST Berlin Time]

Attachment: latency-log

I was talking to Randell over IRC and it looks like this issue might still be present on 10.10 with my hardware.

My laptop is "MacBook Pro (Retina, 15-inch, Early 2013)" running OS X 10.10.  My headphones are TRS Bose QC15 (no mic, analogue).  I tested with both Nightly and debug Nightly.  The Nightly build was 2-11-14, the debug build was built from https://hg.mozilla.org/mozilla-central/rev/0b81c10a9074.

My experience was that the Audio had no perceptible latency until I had plugged and unplugged the headphones.  With non-debug Nightly, it took about 4-5 plug/unplug attempts to get to a latency of about 1s between when when I tapped the mic and when I heard the tap.  With debug, I got to 1s with 1-2 rotations of this plugging and unplugging.

The increase in latency seemed to be more dramatic for removing than it was for inserting.

Comment 24

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

I re-verified on 10.9.4 just to be sure I hadn't missed something with higher numbers of insertions/removals.  10+ cycles of insertion and removal (20+ output changes), and no change at all in output delay (using analog earbud headset).  Before the patches delay increased by 0.3-0.5 seconds per plug or unplug.  So we may have some more 10.10 work to do, but there's still a huge improvement to earlier revs.

Comment 25

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

https://hg.mozilla.org/releases/mozilla-aurora/rev/239b6be45a29
https://hg.mozilla.org/releases/mozilla-aurora/rev/1ee1732b4485

https://hg.mozilla.org/releases/mozilla-beta/rev/80b1fc2042df
https://hg.mozilla.org/releases/mozilla-beta/rev/ddc951a77894

For less confusion, I'll file a bug for investigating/fixing Yosemite

Comment 26

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

Merge bustage fix (missing include)
https://hg.mozilla.org/releases/mozilla-beta/rev/f6a4136fe0af

Comment 27

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

Note: from the logs from jhford, the issue with Yosemite appears to be that we're never notified of output changes (and so can't react).