1523817 - Over 3s A/V sync delay when Firefox is the sender.

Status: VERIFIED FIXED

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

Description

[Jean-Yves Avenard [:jya]]

Made few calls with :cpearce using appear.in

Whenever he's using Firefox on his end, there's close to 3s delay between audio and video.

On my end, using Chrome or Firefox led to the same outcome.
If he used Chrome it was good.

Tried with and without IPv6, made no difference.

Comment 1

[Jean-Yves Avenard [:jya]]

Similar to bug 1521577, but obviously not the same

Comment 2

[Andreas Pehrson [:pehrsons]]

Was the delay observed on his or your side? Which revision of Nightly did he use? Which platform and what cam/mic did he use? If linux, is it the same with "media.cubeb.sandbox" set to false?

If the delay was observed on your side, it sounds like bug 1521577 to me -- If so, Chris, can you try https://mozilla.github.io/webrtc-landing/gum_test.html and compare "Audio" to "Audio & Video"? Also with latest Nightly to confirm. Thanks!

Comment 3

[Jean-Yves Avenard [:jya]]

I was on mac, he was on Windows.
Both running latest nightly.

the delay was observed on my side only, for him it was okay.

Comment 4

[Andreas Pehrson [:pehrsons]]

What we've concluded so far is that this is indeed another failure mode remaining after bug 1521577 was fixed. Like that bug it also seems to be triggered mainly by the camera device in a video+audio gUM request. It isn't related to sending, just capturing. It isn't reliably reproducing either, something makes it go away, unclear what.

A regression window could be useful just to confirm that it has the same source as bug 1521577 and isn't a regression from bug 1521577 itself. Alex, if you figure out how to reliably reproduce, could you attempt getting a window too?

Comment 5

[Andreas Pehrson [:pehrsons]]

[Tracking Requested - why for this release]:

Hopefully the last audio delay regression now. For sure the trickiest to figure out, but probably the simplest to solve.

We have a few reports of audio latency on Windows. This is not in theory bound to Windows however, but seems to be where it manifests. If I can read anything from the root of the issue, machine load would have the biggest say on whether you get a delay and how long that delay will be. The Windows-relatedness could also be because we can get the audio backend started faster there, but I don't know whether that's the case.

In detail this bug occurs when there's some delay between creating the MediaStream in the MSG [1] and adding the tracks to that MediaStream. In a case that Alex reproduced, the tracks are added at StreamTime ~25000 (rate 44100 so ~0.6s), and on the first iteration we pull in the same amount of samples as silence, and these are causing the delay.

Bug 1509548 caused this because it removed the known-tracks-time concept. For a gUM stream the known tracks time was 0 until tracks were added, causing the MediaStream's StreamTime to be kept at 0 too. When tracks were added we advanced the known tracks time to STREAM_TIME_MAX and the StreamTime started advancing.

The fact that we pull in ~25000 samples on the first iteration is a latent bug that is causing this delay. Why it happens intermittently is unclear but it's probably related to the fact that we create the stream (this being the first stream in the graph) with an AudioCallbackDriver and immediately switch to a SystemClockDriver (because there was no audio track yet). I haven't gone into depth on this, as it will be irrelevant to the fix required here.

If this audio was pulled like other audio we could perhaps have compensated this, but once the input callbacks from cubeb start coming in this audio is pushed into the graph, meaning we push the delay ahead of us as well. The video track is only pulled with as much as is needed for the current iteration, meaning that once we have consumed the initial silence/blank-frame we start seeing up-to-date video, as expected.

[1] https://searchfox.org/mozilla-central/rev/78cd247b5d7a08832f87d786541d3e2204842e8e/dom/media/MediaManager.cpp#1323
[2] https://searchfox.org/mozilla-central/rev/78cd247b5d7a08832f87d786541d3e2204842e8e/dom/media/MediaManager.cpp#4132,4136

Comment 6

[Liz Henry (:lizzard) (relman/hg->git project)]

Once you have a fix let's ask QA to verify. Seems possibly good for beta uplift.

Comment 7

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1523817 - Fix tracks that start at StreamTime t > 0. r?padenot

Comment 8

[Andreas Pehrson [:pehrsons]]

try push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=35fbca6c45dfb2cd2791b3471ecfbc1dcf42724c

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4fc0ae495571
Fix tracks that start at StreamTime t > 0. r=padenot

Comment 10

[Natalia Csoregi [:nataliaCs]]

https://hg.mozilla.org/mozilla-central/rev/4fc0ae495571

Comment 11

[Paul Adenot (:padenot)]

Comment on attachment 9040625 [details]
Bug 1523817 - Fix tracks that start at StreamTime t > 0. r?padenot

Beta/Release Uplift Approval Request

Feature/Bug causing the regression

Bug 1523817

User impact if declined

Long audio input latency when opening a microphone device under load, on Windows. This is possibly device-specific: devices that use a built-in driver don't seem to have this issue, but, say, webcam (that sometimes have microphones, like all flagship Logitechs) and some USB headsets that bring along their own driver seem to be sensitive to this problem a bit more.

In short, this makes having a conversation using WebRTC with such a configuration borderline impossible.

Is this code covered by automated tests?

No

Has the fix been verified in Nightly?

Yes

Needs manual test from QE?

Yes

If yes, steps to reproduce

Load the machine, try to make a call to another computer using for example appear.in. Observe that the latency is low.

List of other uplifts needed

none

Risk to taking this patch

Medium

Why is the change risky/not risky? (and alternatives if risky)

Not too risky in the sense that we've been able to find the reason and it makes sense, and we were able to reproduce reliably, and we can't anymore.

However this is device specific so it's a bit harder than usual to test. We can offer recommendations of devices and configurations to test, but we've been doing some testing ourselves on this one as it's a bit easier to characterize.

We have lots of test covering this code in general, but we don't have the required hardware on treeherder for those tests to be able to detect an issue like this, so I said "No" above on the test question.

String changes made/needed

Comment 12

[Ryan VanderMeulen [:RyanVM]]

Adrian, can we get someone to verify this fix on Nightly before we do the Beta/Release approvals? Thanks!

Comment 13

[Paul Adenot (:padenot)]

Alex, would you mind writing here the configuration on which you could repro ?

Comment 14

[Alex Chronopoulos [:achronop]]

In order to repro I use an external camera with microphone, Logitech c920 in my case. I go to gUM test page in [1] and I use "Video&Audio" option. In gUM request I am choosing, for the camera the built-in device and for the microphone the one from the external device. When it reproduces (it's sporadic), the audio is behind the video by 1-2 secs.

[1] https://mozilla.github.io/webrtc-landing/gum_test.html

Comment 15

[Jean-Yves Avenard [:jya]]

I have verified with a call to :cpearce and it was now working okay, no more A/V sync delay

Comment 16

[Hani Yacoub, Desktop QA]

I couldn't reproduce this issue using appear.in on Firefox Nightly 67.0a1 (2019-01-29) using Windows 10 x64 and Mac OS X 10.14, I also used 2 external camera with microphone (Logitech HD pro Webcam C920 and Microsoft LifeCam HD-3000).

I tried by accessing gUM test page but I couldn't reproduce the issue also.

Based on comment 15 I'll change "status-firefox67" flag to verified.

Comment 17

[Alex Chronopoulos [:achronop]]

I have also verified the fix, in my case I had 1 sec delay, which I haven't reproduced it again since the fix was landed.

Comment 18

[Liz Henry (:lizzard) (relman/hg->git project)]

Comment on attachment 9040625 [details]
Bug 1523817 - Fix tracks that start at StreamTime t > 0. r?padenot

Fix for a common WebRTC/ microphone configuration on Windows, verified in Nightly.
Let's uplift for beta 6.

Comment 19

[Stefan Hindli [:stefan_hindli]]

https://hg.mozilla.org/releases/mozilla-beta/rev/32e42cfd5f75

Comment 20

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 9040625 [details]
Bug 1523817 - Fix tracks that start at StreamTime t > 0. r?padenot

[Triage Comment]
Fixes lag over WebRTC calls in some circumstances. Approved for 65.0.1.

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-release/rev/8c8148a462cb

Comment 22

[Catalin Sasca, Desktop Test Engineering [:csasca]]

We couldn't reproduce the issue. We tried different combinations between Windows 10 , macOS 10.12 and Ubuntu 18.04, using hotspot, vpn connections, net limiter on Firefox Nightly (2019-01-29). Jean, can you look over Firefox 65 and 66 too, please?

Comment 23

[Jean-Yves Avenard [:jya]]

(In reply to Catalin Sasca, QA [:csasca] from comment #22)

We couldn't reproduce the issue. We tried different combinations between Windows 10 , macOS 10.12 and Ubuntu 18.04, using hotspot, vpn connections, net limiter on Firefox Nightly (2019-01-29). Jean, can you look over Firefox 65 and 66 too, please?

you need to use windows and have the right hardware.

Comment 24

[Catalin Sasca, Desktop Test Engineering [:csasca]]

We tried again with the Logitech C920 HD camera, both external and internal microphone, on the appear.in and the gum test page, and still couldn't reproduce it. We tested on Firefox Nightly (2019-01-29).

Comment 25

[Andreas Pehrson [:pehrsons]]

If I am to make a generic comment about the hardware needed to reproduce this, it would be to use an external USB microphone (in reported cases in the form of a camera or USB headset) and a camera from another device (internal or other external USB).

If that really doesn't work, achronop or cpearce can probably assist in verifying as they have both been able to reproduce in the past.

Comment 26

[Catalin Sasca, Desktop Test Engineering [:csasca]]

We tried all of the above, without success. If achronop or cpearce could verify it would be great.

Comment 27

[Alex Chronopoulos [:achronop]]

I have verified the issue already, mentioned in comment 17.

Comment 28

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

jya and I tested, and the bug appeared fixed in Nightly.