Closed Bug 1586370 Opened 5 years ago Closed 4 years ago

Muting/Unmuting bluetooth headset on OSX results in 2s video delay

Categories

(Core :: WebRTC: Audio/Video, defect, P2)

defect

Tracking

()

RESOLVED FIXED
mozilla73
Tracking Status
firefox73 --- fixed

People

(Reporter: drno, Assigned: pehrsons)

References

(Regressed 1 open bug)

Details

Attachments

(29 files, 1 obsolete file)

47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review

Setup:

  • connect a bluetooth (I used Bose QC35, but work with AirPods as well) headset to a MBP
  • join an whereby room in one window
  • join the same room in another window
  • mute the mic in both windows via the whereby button
  • wait for a few seconds to switch from the bluetooth headset profile to the high fidelity playback profile

What happens:

  • the remote video is now delayed by ~1-2 seconds for some time

  • after something like 30s - 1m all four videos are in sync again

  • when you turn on the mic in of the windows bluetooth switches back to headset profile

  • now you can observe the same delay in video rendering, but the audio has no delay

  • again audio and video will be in syn again after an extended amount of time

Summary: Muting/Unmuting bluetooth headset on OSX results in 2s delay → Muting/Unmuting bluetooth headset on OSX results in 2s video delay

I've been trying to reason about this and it seems likely the following is happening:

  • Audiocallbacks are coming, continuous audio data is sent over the peerconnection
  • Mic gets muted & unmuted, because it's bluetooth it takes a few seconds
    • during this time there are no audio callbacks (on at least mac and windows) so no audio bits are sent over the peerconnection
    • there are however video frames flowing
    • the remote, receiving, end likely treats this as jitter, growing the video jitter buffer to compensate when audio comes in again
  • When audio flows again, it starts being sent over the peerconnection again too
  • The remote, receiving, end sees audio packets finally coming in and thinks they're a continuation of the pre-muted audio. It doesn't understand that there was a seconds-long gap in the audio stream.
  • Now the video jitter buffer is extra long because there was audio jitter, and audio being received now is treated as having occurred seconds in the past.

Well, that's my hypothesis at least, and I expect the issue to be some variant of this. Finding a regression range might help to narrow it down too.

Getting a pernosco recording of the receive side should be easy and should help in observing what is happening with jitter buffers.

Assignee: nobody → apehrson
Status: NEW → ASSIGNED

I've got a pernosco recording of the receive side of this. It's not very clean since we hit many intermittent connection issues because of rr slowness. It does however contain a/v in sync, then with video being behind, then again in sync, so hopefully we can learn something.

The recording has been processed and is at https://pernos.co/debug/zCPbfyGWqwDwj1ocSWrCaw/index.html

I'll try to populate the Notebook with my findings.

Thanks Andreas for looking into this. Sounds to me like we should consider sending silence packets while switching Bluetooth profiles?

I've been able to verify comment 1.

The send side will treat audio as continuous, always. Having a gap in the audio like we do when an AudioCallbackDriver switch is really slow is not detected in any way. The rtp timestamps end up being continuous whereas the flow of packets is not. This makes the receiving side very confused.

In the pernoscos recording I managed to get (with lots of connectivity issues) a/v sync was eventually saved by an experiment that was enabled by default (and by mistake) because the frame rate dropped below 5 (video froze for 15s).

When I simulate the same conditions by putting a usleep(2e6); in AsyncCubebTask::Run I can see how the gap in audio starts gradually growing the video jitter buffer (the video delay gradually increases). It grows even after audio is flowing again, for a while. I did not see it getting much lower. Perhaps being more patient would have lead there eventually.

I'd prefer to fix this universally, as MediaRecorder's DriftCompensator would also be impacted by this issue, though probably in a less drastic manner.

For now I have written a patch to AudioCallbackDriver that will, after an audio->audio switch, run the graph for the number of audio frames that correspond to the duration of the switch. This works well for RTCPeerConnection. My only worry is that it could lead to a lot of work for one iteration on some graph setups -- image a couple of AudioNodes that generate audio, and suddenly have to generate 2 seconds instead of 10 milliseconds of data, or 8 received audio tracks, where we now have to decode 2 seconds instead of 10 milliseconds of opus data. I'd need to do some tracing of this.

Some audio devices can take a long time to turn on and off. An example is a
bluetooth device that switches profile from high quality output to low quality
input-output when opening an input stream. This can take seconds.

Running video (off-graph) while audio is stuck like this can be confusing.
The most prominent example is a remote peer connection, as it's expecting to
continuously receive audio, clocked at an rtp timestamp. If opening or closing
an input stream takes a long time, the receiving end will see a large gap in
received audio samples, but with a continuous rtp timestamp sequence. It
interprets this as jitter, and delays incoming video as a consequence.

Compensating for the duration of a slow driver switch solves this, by letting
the graph process the number of samples that would normally have been processed
during the duration of the driver switch. This will update the rtp timestamps
accordingly on the send side, and send out silence if anything. No delayed video
on the receive side is observed.

Note that this is not in effect on linux, since when running with a realtime
priority thread this is likely to exceed the realtime budget. Profile selection
of a bluetooth device on Linux is not affected by Firefox however, so it should
be less of a problem there.

Blocks: 1542321
Attachment #9099794 - Attachment is obsolete: true

I found this while running local tests. In particular
./mach test dom/media/test/test_mediarecorder_record_addtracked_stream.html --headless --repeat 1.

Depends on D56065

This let's us remove GraphDriver's dependency on the graph's message queues.

Depends on D56067

This removes some driver-graph interdependencies.

It also changes the logic of EnsureNextIteration() so that it no longer blindly
wakes the driver up, should it be sleeping. Instead it waits until the driver's
next iteration would have occurred anyway, as that seems more expected, and
closer to how an AudioClockDriver works.

Depends on D56068

One less dependency on MTG from the driver.

Depends on D56071

This is where TrackTicks is defined, which is what they convert to and from.

Depends on D56072

This also removes the ones in MTGImpl that are no longer used.

Depends on D56073

This removes a level of indirection where the graph had to call back into
AudioContext. It also removes a dependency on the graph from GraphDriver, where
it can now just resolve a MozPromiseHolder instead.

Depends on D56074

This will let us get rid of such GraphDriver dependencies on MediaTrackGraphImpl
as SignalMainThreadCleanup and SetCurrentDriver.

Depends on D56075

This lets us iterate more things than MediaTrackGraphImpl, e.g., audio drivers
(from the fallback driver) and unit test classes.

Depends on D56081

Not that this will only switch to the fallback driver once, and never switch
back. This will improve in future patches.

Depends on D56082

This allows the graph to run in case starting the audio driver takes a long
time. We could also do this only for audio->audio driver switches as there is
not much point to keep the graph iterating if we are starting a new graph, or
switching to or from audio. That would however mean more paths, and implied,
harder-to-catch bugs.

Depends on D56084

See Also: → 1601034
See Also: → 1602723

Since we now run a fallback driver while an AudioCallbackDriver starts, this has
exposed a path where the double-append-during-iteration assertion fails.

It seems to happen at least when there's an audio->audio driver switch, and a
fallback driver was running in between.

The state for this assertion assumes it's reset when the AudioCallbackDriver
that's feeding it starts, but forgot to account for driver switches and
fallbacks, which could still cause silence to be pulled for the track.

Depends on D57036

This makes it simpler to maintain state in the GraphDriver in more complex
cases, such as when an AudioCallbackDriver is backed by a fallback driver.

Depends on D57552

Unfortunate, but this is an existing intermittent that is blocking bug 1586370
from landing.

Depends on D57037

Depends on: 1604941
Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/fddb3087359a
Clarify mixer callback calls. r=padenot
https://hg.mozilla.org/integration/autoland/rev/e87dc3e99cb1
Let FallbackToSystemClockDriver take its own monitor. r=padenot
https://hg.mozilla.org/integration/autoland/rev/cd5ee924f4ec
Make SystemClockDriver::mIsFallback const. r=padenot
https://hg.mozilla.org/integration/autoland/rev/48606faefff5
Move WaitForNextIteration to ThreadedDriver. r=padenot
https://hg.mozilla.org/integration/autoland/rev/666bcbd400e0
Remove unused GraphDriver::EnsureNextIteration. r=padenot
https://hg.mozilla.org/integration/autoland/rev/2a71737c9e59
Ensure there's another iteration when the front message queue becomes populated. r=padenot
https://hg.mozilla.org/integration/autoland/rev/af37c2c71ede
Remove GraphDriver dependency on GraphImpl()->StateComputedTime(). r=padenot
https://hg.mozilla.org/integration/autoland/rev/573025ffa140
Move SwapMessageQueues-on-first-iteration to MTGImpl. r=padenot
https://hg.mozilla.org/integration/autoland/rev/2523464caf47
Move EnsureNextIteration logic into ThreadedDriver . r=padenot
https://hg.mozilla.org/integration/autoland/rev/98e300e989c8
Move AudioMixer from MTG to AudioCallbackDriver. r=padenot
https://hg.mozilla.org/integration/autoland/rev/8684da9eab01
Don't query the graph for AudioCallbackDriver's sample rate. r=padenot
https://hg.mozilla.org/integration/autoland/rev/ff84b9ffa8e3
Give AudioCallbackDriver its own device ids. r=padenot
https://hg.mozilla.org/integration/autoland/rev/2faaa82d90d8
Move rate conversion functions to MediaSegment.h. r=padenot
https://hg.mozilla.org/integration/autoland/rev/b75af88f4726
Give GraphDriver its own time conversion methods. r=padenot
https://hg.mozilla.org/integration/autoland/rev/7759b2b568d1
Use MozPromise for AudioContextOperations and NotifyWhenGraphStarted. r=padenot
https://hg.mozilla.org/integration/autoland/rev/49c78f098b4c
Return a flexible object from OneIteration. r=padenot
https://hg.mozilla.org/integration/autoland/rev/ed5ae50f2d4a
Let IterationResult handle SignalMainThreadCleanup. r=padenot
https://hg.mozilla.org/integration/autoland/rev/054b3c992edc
Let MTG handle driver switching through IterationResult. r=padenot
https://hg.mozilla.org/integration/autoland/rev/659575de400f
Tighten some MTG threading asserts. r=padenot
https://hg.mozilla.org/integration/autoland/rev/26045584bc6a
Rename GraphDriver::OnGraphThread to InIteration. r=padenot
https://hg.mozilla.org/integration/autoland/rev/6b5d3b9abd98
Make GraphDriver iterate the Graph through an interface instead of directly. r=padenot
https://hg.mozilla.org/integration/autoland/rev/3cb0f8f105fc
Remove MediaTrackGraph dependency from AudioCallbackDriver gtest. r=padenot
https://hg.mozilla.org/integration/autoland/rev/76522c01a1ae
Pass IterationEnd up to the graph rather than back-querying the driver. r=padenot
https://hg.mozilla.org/integration/autoland/rev/2e501665daf9
Fall back to a SystemClockDriver if AudioCallbackDriver fails to start or hits an error. r=padenot
https://hg.mozilla.org/integration/autoland/rev/f6c628af82a4
Re-init an AudioCallbackDriver with a fallback driver if it previously failed to start. r=padenot
https://hg.mozilla.org/integration/autoland/rev/af4366cd0cbf
Run a fallback driver while an audio driver starts. r=padenot
https://hg.mozilla.org/integration/autoland/rev/583f9b88c25e
Update GraphDriver lifetime docs. r=padenot
https://hg.mozilla.org/integration/autoland/rev/773a2010fb56
Signal to AudioInputProcessing when an audio driver starts so it can reset state. r=padenot
https://hg.mozilla.org/integration/autoland/rev/8d48fe4b3512
Relax the timing requrements of test_mediarecorder_pause_resume_video.html. r=jib
Blocks: 1605041

https://hg.mozilla.org/mozilla-central/rev/fddb3087359a
https://hg.mozilla.org/mozilla-central/rev/e87dc3e99cb1
https://hg.mozilla.org/mozilla-central/rev/cd5ee924f4ec
https://hg.mozilla.org/mozilla-central/rev/48606faefff5
https://hg.mozilla.org/mozilla-central/rev/666bcbd400e0
https://hg.mozilla.org/mozilla-central/rev/2a71737c9e59
https://hg.mozilla.org/mozilla-central/rev/af37c2c71ede
https://hg.mozilla.org/mozilla-central/rev/573025ffa140
https://hg.mozilla.org/mozilla-central/rev/2523464caf47
https://hg.mozilla.org/mozilla-central/rev/98e300e989c8
https://hg.mozilla.org/mozilla-central/rev/8684da9eab01
https://hg.mozilla.org/mozilla-central/rev/ff84b9ffa8e3
https://hg.mozilla.org/mozilla-central/rev/2faaa82d90d8
https://hg.mozilla.org/mozilla-central/rev/b75af88f4726
https://hg.mozilla.org/mozilla-central/rev/7759b2b568d1
https://hg.mozilla.org/mozilla-central/rev/49c78f098b4c
https://hg.mozilla.org/mozilla-central/rev/ed5ae50f2d4a
https://hg.mozilla.org/mozilla-central/rev/054b3c992edc
https://hg.mozilla.org/mozilla-central/rev/659575de400f
https://hg.mozilla.org/mozilla-central/rev/26045584bc6a
https://hg.mozilla.org/mozilla-central/rev/6b5d3b9abd98
https://hg.mozilla.org/mozilla-central/rev/3cb0f8f105fc
https://hg.mozilla.org/mozilla-central/rev/76522c01a1ae
https://hg.mozilla.org/mozilla-central/rev/2e501665daf9
https://hg.mozilla.org/mozilla-central/rev/f6c628af82a4
https://hg.mozilla.org/mozilla-central/rev/af4366cd0cbf
https://hg.mozilla.org/mozilla-central/rev/583f9b88c25e
https://hg.mozilla.org/mozilla-central/rev/773a2010fb56
https://hg.mozilla.org/mozilla-central/rev/8d48fe4b3512

Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla73
Regressions: 1605118
Depends on: 1605134
Regressions: 1605150
Regressions: 1605703
Regressions: 1605293
Regressions: 1608505
Regressed by: 1609400
No longer regressed by: 1609400
Regressions: 1609400
Regressions: 1618444
Regressions: 1633493
Regressions: 1651745
Regressions: 1683971
Regressions: 1767549
See Also: → 1666116
See Also: → 1801190
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: