1513973 - Audio input latency, possibly in MediaStreamGraph

Status: VERIFIED FIXED

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

Description

[Andreas Pehrson [:pehrsons]]

On the dec 8th Nightly on Ubuntu [1] I'm experiencing latency on the microphone side in one-on-one calls on appear.in. So far two out of two calls today have experienced roughly 1s latency.

It doesn't appear to be in pulseaudio as pavucontrol's volume meter for the active Firefox recording is snappy.

It is not on the other party's speaker side, as unmuting my local media element exhibits the latency too.

The remote party's audio on my end is all right.

Meanwhile another tab running [2] is perfectly fine. That would use another MediaStreamGraph and cubeb stream, so perhaps that makes sense.

I have disabled cubeb sandboxing and am on the pulse-rust cubeb backend.

To me it seems like the latency is in either cubeb or MediaStreamGraph or in between.

[1] https://launchpad.net/~ubuntu-mozilla-daily/+archive/ubuntu/ppa
[2] https://mozilla.github.io/webrtc-landing/gum_test.html

Comment 1

[Alastor Wu [:alwu]]

Mark this one as P2 for now, free feel to change priority.

Comment 2

[Andreas Pehrson [:pehrsons]]

I can reproduce this with audio+video gum_test.html [1]. That points to MSG indeed. I'm making this a P1 as I for now assume all audio input is affected when paired with a non-instant camera.

This is likely a regression from my first MSG refactor work.


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

Comment 3

[Andreas Pehrson [:pehrsons]]

65 is also affected.

Comment 4

[Andreas Pehrson [:pehrsons]]

I'll also note that this does not happen with the microphone in my camera, but only the Plantronics USB headset I have.

Comment 5

[Andreas Pehrson [:pehrsons]]

At least this wasn't the big first landing of the MSG refactor, but the smaller followup, bug 1509548.

Comment 6

[Andreas Pehrson [:pehrsons]]

The final output of mozregression: https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=f988af9437f591cc5c7d3917ba370e2edc82d1a6&tochange=daaecb62f373d33c60e6a77bcce01d27e19a3282

Comment 7

[Andreas Pehrson [:pehrsons]]

I'm not sure of the exact details of how this regressed, but it's clear that with per-track pulling the observed latency is equal to the time between MediaEngineSource::Start (happens first for audio, then for video -- so this essentially equals the time it takes to start the video source) and enabling pulling.

I'm shuffling this around so that we enable pulling even before calling Start(). This is simple now that microphone sources are no longer shared.

Comment 8

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

Tracking this regression from 65.

Comment 9

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1513973 - Remove check for `false`. r?jib

The microphone source is no longer shared so this check is moot.

Comment 10

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1513973 - Make MediaEngineSource::SetTrack return void. r?jib

All subclasses are now returning NS_OK, so there's no point in keeping nsresult
as the return type.

Comment 11

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1513973 - Enable pulling at the same time as starting audio sources. r?jib

Otherwise we risk building up a buffer in the microphone source from when
Start() is run until pulling is enabled. This manifests itself as input latency
to the user.

Comment 12

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1513973 - Log NotifyPull per track instead of per stream. r?jib

This better reflects the actual pulling that we do.

Comment 13

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1513973 - Remove mutable keyword from MediaEngineWebRTCMicrophoneSource runnables.

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/f1892f178011
Remove check for `false`. r=jib
https://hg.mozilla.org/integration/autoland/rev/6781e633d62c
Make MediaEngineSource::SetTrack return void. r=jib
https://hg.mozilla.org/integration/autoland/rev/5669b30f2265
Enable pulling at the same time as starting audio sources. r=jib
https://hg.mozilla.org/integration/autoland/rev/6c839f548745
Log NotifyPull per track instead of per stream. r=jib
https://hg.mozilla.org/integration/autoland/rev/2ddf61b1db11
Remove mutable keyword from MediaEngineWebRTCMicrophoneSource runnables. r=jib

Comment 15

[Andreas Pehrson [:pehrsons]]

Comment on attachment 9032915 [details]
Bug 1513973 - Enable pulling at the same time as starting audio sources. r?jib

[Beta/Release Uplift Approval Request]

Feature/Bug causing the regression: Bug 1509548

User impact if declined: Your microphone audio may be delayed when acquiring both camera and microphone at the same time. This mostly shows on video conferencing sites where it seems like you're talking to other people over a satellite link. Other people also see that your audio and video is out of sync.

Is this code covered by automated tests?: No

Has the fix been verified in Nightly?: No

Needs manual test from QE?: Yes

If yes, steps to reproduce: This depends on both platform and what camera you have. I can easily reproduce this on Ubuntu 18.04 with a Logitech Brio.

1 Go to https://mozilla.github.io/webrtc-landing/gum_test.html, click "Audio & Video"
2 Click "Allow" on the permission prompt
3 Uncheck the "Mute" checkbox
Expected: audio and video is in sync in the self-view
Actual: audio is behind video in the self-view

List of other uplifts needed: None

Risk to taking this patch: Low

Why is the change risky/not risky? (and alternatives if risky): The other patches are more or less trivial (but we need most of them too, so let's take all). This patch contains the real fix and changes the timing of when we start processing microphone data. The code handling the processing is already designed to handle it both when the microphone is on and when it's off, and does handle both cases *during* an audio capture too (including in automation). The part that remains not-so-well tested is thus quite small.

String changes made/needed: None

Comment 16

[Dorel Luca [:dluca]]

Backed out 5 changesets (bug 1513973) for browser-chrome failures in browser/base/content/test/webrtc/browser_devices_get_user_media_screen.js. CLOSED TREE

Log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=218409124&repo=autoland&lineNumber=9603

  INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_screen.js | audio global indicator attribute as expected - 
[task 2018-12-21T21:04:55.021Z] 21:04:55     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_screen.js | screen global indicator attribute as expected - 
[task 2018-12-21T21:04:55.023Z] 21:04:55     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_screen.js | only one global indicator window - 
[task 2018-12-21T21:04:55.026Z] 21:04:55     INFO - Stop the camera, this should stop everything.
[task 2018-12-21T21:04:55.027Z] 21:04:55     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_screen.js | got recording-device-events notification - 
[task 2018-12-21T21:04:55.029Z] 21:04:55     INFO - Console message: [JavaScript Error: "remote browser crashed while on https://example.com/browser/browser/base/content/test/webrtc/get_user_media.html
[task 2018-12-21T21:04:55.030Z] 21:04:55     INFO - " {file: "chrome://mochikit/content/mochitest-e10s-utils.js" line: 8}]
[task 2018-12-21T21:04:55.031Z] 21:04:55     INFO - e10s_init/<@chrome://mochikit/content/mochitest-e10s-utils.js:8:5
[task 2018-12-21T21:04:55.034Z] 21:04:55     INFO - EventListener.handleEvent*e10s_init@chrome://mochikit/content/mochitest-e10s-utils.js:6:3
[task 2018-12-21T21:04:55.035Z] 21:04:55     INFO - testInit@chrome://mochikit/content/browser-test.js:102:5
[task 2018-12-21T21:04:55.036Z] 21:04:55     INFO - setTimeout handler*@chrome://mochikit/content/browser-test.js:22:1
[task 2018-12-21T21:04:55.037Z] 21:04:55     INFO - loadChromeScripts@jar:file:///tmp/tmp0VTmfP.mozrunner/extensions/[e-mail]!/api.js:15:3
[task 2018-12-21T21:04:55.038Z] 21:04:55     INFO - loadMochitest@jar:file:///tmp/tmp0VTmfP.mozrunner/extensions/[e-mail]!/api.js:111:3
[task 2018-12-21T21:04:55.039Z] 21:04:55     INFO - @tests/mochitest/runtests.py:1735:1
[task 2018-12-21T21:04:55.040Z] 21:04:55     INFO - @tests/mochitest/runtests.py:1714:2
[task 2018-12-21T21:04:55.041Z] 21:04:55     INFO - evaluate.sandbox/promise<@chrome://marionette/content/evaluate.js:128:13
[task 2018-12-21T21:04:55.042Z] 21:04:55     INFO - evaluate.sandbox@chrome://marionette/content/evaluate.js:97:17
[task 2018-12-21T21:04:55.044Z] 21:04:55     INFO - GeckoDriver.prototype.execute_@chrome://marionette/content/driver.js:1028:19
[task 2018-12-21T21:04:55.045Z] 21:04:55     INFO - async*GeckoDriver.prototype.executeScript@chrome://marionette/content/driver.js:898:24
[task 2018-12-21T21:04:55.049Z] 21:04:55     INFO - Async*despatch@chrome://marionette/content/server.js:291:20
[task 2018-12-21T21:04:55.050Z] 21:04:55     INFO - async*execute@chrome://marionette/content/server.js:264:11
[task 2018-12-21T21:04:55.051Z] 21:04:55     INFO - async*onPacket/<@chrome://marionette/content/server.js:237:15
[task 2018-12-21T21:04:55.055Z] 21:04:55     INFO - async*onPacket@chrome://marionette/content/server.js:236:8
[task 2018-12-21T21:04:55.056Z] 21:04:55     INFO - _onJSONObjectReady/<@chrome://marionette/content/transport.js:490:9
[task 2018-12-21T21:04:55.057Z] 21:04:55     INFO - 
[task 2018-12-21T21:04:55.058Z] 21:04:55     INFO - Buffered messages finished
[task 2018-12-21T21:04:55.059Z] 21:04:55     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/webrtc/browser_devices_get_user_media_screen.js | Test timed out - 
[task 2018-12-21T21:04:55.060Z] 21:04:55     INFO - GECKO(2644) | MEMORY STAT | vsize 2078MB | residentFast 320MB | heapAllocated 89MB
[task 2018-12-21T21:04:55.063Z] 21:04:55     INFO - TEST-OK | browser/base/content/test/webrtc/browser_devices_get_user_media_screen.js | took 90163ms
[task 2018-12-21T21:04:55.064Z] 21:04:55     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-12-21T21:04:55.065Z] 21:04:55     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/webrtc/browser_devices_get_user_media_screen.js | Found a tab after previous test timed out: https://example.com/browser/browser/base/content/test/webrtc/get_user_media.html - 
[task 2018-12-21T21:04:55.070Z] 21:04:55     INFO - GECKO(2644) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmp0VTmfP.mozrunner/runtests_leaks_tab_pid3109.log
[task 2018-12-21T21:04:55.071Z] 21:04:55     INFO - checking window state
[task 2018-12-21T21:04:55.072Z] 21:04:55     INFO - GECKO(2644) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2018-12-21T21:04:55.074Z] 21:04:55     INFO - TEST-START | browser/base/content/test/webrtc/browser_devices_get_user_media_tear_off_tab.js
[task 2018-12-21T21:04:55.130Z] 21:04:55     INFO - GECKO(2644) | ++DOCSHELL 0x7fa644215800 == 1 [pid = 2749] [id = {30a831c1-422d-478f-9eb8-31cadf71194a}]
[task 2018-12-21T21:04:55.132Z] 21:04:55     INFO - GECKO(2644) | ++DOMWINDOW == 1 (0x7fa645bb8c00) [pid = 2749] [serial = 13] [outer = (nil)]
[task 2018-12-21T21:04:55.197Z] 21:04:55     INFO - GECKO(2644) | ++DOCSHELL 0x7fa644217800 == 2 [pid = 2749] [id = {d11acaff-bc9c-4ae7-8fb1-7e278cb9f0cf}]
[task 2018-12-21T21:04:55.198Z] 21:04:55     INFO - GECKO(2644) | ++DOMWINDOW == 2 (0x7fa645bba800) [pid = 2749] [serial = 14] [outer = (nil)]
[task 2018-12-21T21:04:55.218Z] 21:04:55     INFO - GECKO(2644) | ++DOMWINDOW == 3 (0x7fa645bbb800) [pid = 2749] [serial = 15] [outer = 0x7fa645bb8c00]
[task 2018-12-21T21:04:55.296Z] 21:04:55     INFO - GECKO(2644) | ++DOCSHELL 0x7fbfa98d4000 == 1 [pid = 3109] [id = {6306d464-1699-4d37-9015-27a2fa6e0a6f}]
[task 2018-12-21T21:04:55.344Z] 21:04:55     INFO - GECKO(2644) | ++DOMWINDOW == 4 (0x7fa645bbf800) [pid = 2749] [serial = 16] [outer = 0x7fa645bba800]
[task 2018-12-21T21:04:55.425Z] 21:04:55     INFO - GECKO(2644) | ++DOMWINDOW == 5 (0x7fa645bc0000) [pid = 2749] [serial = 17] [outer = 0x7fa645bb8c00]
[task 2018-12-21T21:04:55.430Z] 21:04:55     INFO - GECKO(2644) | ++DOMWINDOW == 1 (0x7fbfa9719400) [pid = 3109] [serial = 1] [outer = (nil)]
[task 2018-12-21T21:04:55.599Z] 21:04:55     INFO - GECKO(2644) | ++DOMWINDOW == 2 (0x7fbfaa747400) [pid = 3109] [serial = 2] [outer = 0x7fbfa9719400]
[task 2018-12-21T21:04:55.660Z] 21:04:55     INFO - GECKO(2644) | [Parent 2644, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/netwerk/url-classifier/UrlClassifierCommon.cpp, line 121
[task 2018-12-21T21:04:55.678Z] 21:04:55     INFO - GECKO(2644) | ++DOMWINDOW == 6 (0x7fa645bc3800) [pid = 2749] [serial = 18] [outer = 0x7fa645bba800]
[task 2018-12-21T21:04:55.902Z] 21:04:55     INFO - GECKO(2644) | TEST DEVICES: Using media devices:
[task 2018-12-21T21:04:55.904Z] 21:04:55     INFO - GECKO(2644) | audio: Monitor of Null Output
[task 2018-12-21T21:04:55.905Z] 21:04:55     INFO - GECKO(2644) | video: Dummy video device (0x0000)
[task 2018-12-21T21:04:56.276Z] 21:04:56     INFO - GECKO(2644) | ++DOCSHELL 0x7efc3541f000 == 7 [pid = 2644] [id = {f0ebfdc4-37cf-465d-b3ef-eb33d38c33f1}]
[task 2018-12-21T21:04:56.277Z] 21:04:56     INFO - GECKO(2644) | ++DOMWINDOW == 13 (0x7efc36e74c00) [pid = 2644] [serial = 58] [outer = (nil)]
[task 2018-12-21T21:04:56.279Z] 21:04:56     INFO - GECKO(2644) | ++DOMWINDOW == 14 (0x7efc391ba400) [pid = 2644] [serial = 59] [outer = 0x7efc36e74c00]
[task 2018-12-21T21:04:56.336Z] 21:04:56     INFO - GECKO(2644) | [Parent 2644, Main Thread] WARNING: NS_FAILED internal_GetScalarByEnum for CHILD: file /builds/worker/workspace/build/src/toolkit/components/telemetry/core/TelemetryScalar.cpp, line 2161
[task 2018-12-21T21:04:56.338Z] 21:04:56     INFO - GECKO(2644) | [Parent 2644, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x805D0021: file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 1010
[task 2018-12-21T21:04:56.378Z] 21:04:56     INFO - GECKO(2644) | [Parent 2644, Main Thread] WARNING: NS_ENSURE_TRUE(root) failed: file /builds/worker/workspace/build/src/layout/base/nsDocumentViewer.cpp, line 3297
[task 2018-12-21T21:04:56.467Z] 21:04:56     INFO - GECKO(2644) | ++DOCSHELL 0x7efc3af57000 == 8 [pid = 2644] [id = {7a0162c8-0711-47b4-ab25-89f46afd3a87}]
[task 2018-12-21T21:04:56.469Z] 21:04:56     INFO - GECKO(2644) | ++DOMWINDOW == 15 (0x7efc391db800) [pid = 2644] [serial = 60] [outer = (nil)]
[task 2018-12-21T21:04:56.470Z] 21:04:56     INFO - GECKO(2644) | ++DOMWINDOW == 16 (0x7efc391dbc00) [pid = 2644] [serial = 61] [outer = 0x7efc391db800]
[task 2018-12-21T21:04:56.550Z] 21:04:56     INFO - GECKO(2644) | [Parent 2644, Main Thread] WARNING: Attempting to get a displayport from a content with no primary frame!: file /builds/worker/workspace/build/src/layout/base/nsLayoutUtils.cpp, line 753
[task 2018-12-21T21:04:56.556Z] 21:04:56     INFO - GECKO(2644) | [Parent 2644, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x805D0021: file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 1010
[task 2018-12-21T21:04:56.838Z] 21:04:56     INFO - GECKO(2644) | ++DOCSHELL 0x7efc3af5f000 == 9 [pid = 2644] [id = {f39bb4c3-7da8-466b-b739-c52ccfc06051}]
[task 2018-12-21T21:04:56.840Z] 21:04:56     INFO - GECKO(2644) | ++DOMWINDOW == 17 (0x7efc3a6a0000) [pid = 2644] [serial = 62] [outer = (nil)]
[task 2018-12-21T21:04:57.061Z] 21:04:57     INFO - GECKO(2644) | ++DOCSHELL 0x7fa645b78800 == 3 [pid = 2749] [id = {2775929d-f442-4c34-956a-fd0fc2f5c239}]
[task 2018-12-21T21:04:57.063Z] 21:04:57     INFO - GECKO(2644) | ++DOMWINDOW == 7 (0x7fa646e1b000) [pid = 2749] [serial = 19] [outer = (nil)]
[task 2018-12-21T21:04:57.142Z] 21:04:57     INFO - GECKO(2644) | ++DOMWINDOW == 18 (0x7efc36744c00) [pid = 2644] [serial = 63] [outer = 0x7efc3a6a0000]
[task 2018-12-21T21:04:57.160Z] 21:04:57     INFO - GECKO(2644) | [Parent 2644, Main Thread] WARNING: NS_FAILED internal_GetScalarByEnum for CHILD: file /builds/worker/workspace/build/src/toolkit/components/telemetry/core/TelemetryScalar.cpp, line 2161
[task 2018-12-21T21:04:57.183Z] 21:04:57     INFO - GECKO(2644) | ++DOMWINDOW == 8 (0x7fa646e1c000) [pid = 2749] [serial = 20] [outer = 0x7fa646e1b000]
[task 2018-12-21T21:04:57.306Z] 21:04:57     INFO - GECKO(2644) | [Parent 2644, Compositor] WARNING: ConnectReferentLayer failed - Incorrect LayerManager: file /builds/worker/workspace/build/src/gfx/layers/Layers.h, line 2607
[task 2018-12-21T21:04:57.327Z] 21:04:57     INFO - GECKO(2644) | [Parent 2644, Compositor] WARNING: ConnectReferentLayer failed - Incorrect LayerManager: file /builds/worker/workspace/build/src/gfx/layers/Layers.h, line 2607
[task 2018-12-21T21:04:57.343Z] 21:04:57     INFO - GECKO(2644) | [Parent 2644, Compositor] WARNING: ConnectReferentLayer failed - Incorrect LayerManager: file /builds/worker/workspace/build/src/gfx/layers/Layers.h, line 2607
[task 2018-12-21T21:04:57.360Z] 21:04:57     INFO - GECKO(2644) | [Parent 2644, Compositor] WARNING: ConnectReferentLayer failed - Incorrect LayerManager: file /builds/worker/workspace/build/src/gfx/layers/Layers.h, line 2607
[task 2018-12-21T21:04:57.377Z] 21:04:57     INFO - GECKO(2644) | [Parent 2644, Compositor] WARNING: ConnectReferentLayer failed - Incorrect LayerManager: file /builds/worker/workspace/build/src/gfx/layers/Layers.h, line 2607
[task 2018-12-21T21:04:57.394Z] 21:04:57     INFO - GECKO(2644) | [Parent 2644, Compositor] WARNING: ConnectReferentLayer failed - Incorrect LayerManager: file /builds/worker/workspace/build/src/gfx/layers/Layers.h, line 2607
[task 2018-12-21T21:04:57.411Z] 21:04:57     INFO - GECKO(2644) | [Parent 2644, Compositor] WARNING: ConnectReferentLayer failed - Incorrect LayerManager: file /builds/worker/workspace/build/src/gfx/layers/Layers.h, line 2607
[task 2018-12-21T21:04:57.428Z] 21:04:57     INFO - GECKO(2644) | [Parent 2644, Compositor] WARNING: ConnectReferentLayer failed - Incorrect LayerManager: file /builds/worker/workspace/build/src/gfx/layers/Layers.h, line 2607
[task 2018-12-21T21:04:57.440Z] 21:04:57     INFO - GECKO(2644) | [Parent 2644, Compositor] WARNING: ConnectReferentLayer failed - Incorrect LayerManager: file /builds/worker/workspace/build/src/gfx/layers/Layers.h, line 2607
[task 2018-12-21T21:04:57.457Z] 21:04:57     INFO - GECKO(2644) | [Parent 2644, Compositor] WARNING: ConnectReferentLayer failed - Incorrect LayerManager: file /builds/worker/workspace/build/src/gfx/layers/Layers.h, line 2607
[task 2018-12-21T21:04:57.475Z] 21:04:57     INFO - GECKO(2644) | [Parent 2644, Compositor] WARNING: ConnectReferentLayer failed - Incorrect LayerManager: file /builds/worker/workspace/build/src/gfx/layers/Layers.h, line 2607
[task 2018-12-21T21:04:57.715Z] 21:04:57     INFO - GECKO(2644) | ###!!! [Parent][DispatchAsyncMessage] Error: PQuotaUsageRequest::Msg_Cancel Route error: message sent to unknown actor ID
[task 2018-12-21T21:04:58.105Z] 21:04:58     INFO - GECKO(2644) | MEMORY STAT | vsize 2082MB | residentFast 325MB | heapAllocated 94MB
[task 2018-12-21T21:04:58.107Z] 21:04:58     INFO - TEST-OK | browser/base/content/test/webrtc/browser_devices_get_user_media_tear_off_tab.js | took 3143ms
[task 2018-12-21T21:04:58.125Z] 21:04:58     INFO - GECKO(2644) | ++DOCSHELL 0x7fa644226800 == 4 [pid = 2749] [id = {a735aa99-fffb-4ae0-aace-e60a11f90fa2}]
[task 2018-12-21T21:04:58.128Z] 21:04:58     INFO - GECKO(2644) | ++DOMWINDOW == 9 (0x7fa645bc4400) [pid = 2749] [serial = 21] [outer = (nil)]
[task 2018-12-21T21:04:58.165Z] 21:04:58     INFO - GECKO(2644) | ++DOMWINDOW == 10 (0x7fa645bc6000) [pid = 2749] [serial = 22] [outer = 0x7fa645bc4400]
[task 2018-12-21T21:04:58.187Z] 21:04:58     INFO - checking window state
[task 2018-12-21T21:04:58.189Z] 21:04:58     INFO - GECKO(2644) | must wait for focus
[task 2018-12-21T21:04:58.347Z] 21:04:58     INFO - TEST-START | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js

Push with failures:
https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=2ddf61b1db11219e203fe17fe5aaa84424fed362

Backout:
https://hg.mozilla.org/integration/autoland/rev/c559079456f465e97f01fbb592e4f7d7abf1ced8

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/70e41e116eac
Remove check for `false`. r=jib
https://hg.mozilla.org/integration/autoland/rev/0eade7c45f95
Make MediaEngineSource::SetTrack return void. r=jib
https://hg.mozilla.org/integration/autoland/rev/227e7219ae35
Enable pulling at the same time as starting audio sources. r=jib
https://hg.mozilla.org/integration/autoland/rev/0ad57a96ed21
Log NotifyPull per track instead of per stream. r=jib
https://hg.mozilla.org/integration/autoland/rev/58d11f769452
Remove mutable keyword from MediaEngineWebRTCMicrophoneSource runnables. r=jib

Comment 18

[Oana Pop-Rus]

https://hg.mozilla.org/mozilla-central/rev/70e41e116eac
https://hg.mozilla.org/mozilla-central/rev/0eade7c45f95
https://hg.mozilla.org/mozilla-central/rev/227e7219ae35
https://hg.mozilla.org/mozilla-central/rev/0ad57a96ed21
https://hg.mozilla.org/mozilla-central/rev/58d11f769452

Comment 19

[Andreas Pehrson [:pehrsons]]

Comment on attachment 9032915 [details]
Bug 1513973 - Enable pulling at the same time as starting audio sources. r?jib

[Beta/Release Uplift Approval Request]

Feature/Bug causing the regression: Bug 1509548

User impact if declined: Your microphone audio may be delayed when acquiring both camera and microphone at the same time. This mostly shows on video conferencing sites where it seems like you're talking to other people over a satellite link. Other people also see that your audio and video is out of sync.

Is this code covered by automated tests?: No

Has the fix been verified in Nightly?: No

Needs manual test from QE?: Yes

If yes, steps to reproduce: This depends on both platform and what camera you have. I can easily reproduce this on Ubuntu 18.04 with a Logitech Brio.

1 Go to https://mozilla.github.io/webrtc-landing/gum_test.html, click "Audio & Video"
2 Click "Allow" on the permission prompt
3 Uncheck the "Mute" checkbox
Expected: audio and video is in sync in the self-view
Actual: audio is behind video in the self-view

List of other uplifts needed: None

Risk to taking this patch: Low

Why is the change risky/not risky? (and alternatives if risky): The other patches are more or less trivial (but we need most of them too, so let's take all). This patch contains the real fix and changes the timing of when we start processing microphone data. The code handling the processing is already designed to handle it both when the microphone is on and when it's off, and does handle both cases *during* an audio capture too (including in automation). The part that remains not-so-well tested is thus quite small.

String changes made/needed: None

Comment 20

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 9032915 [details]
Bug 1513973 - Enable pulling at the same time as starting audio sources. r?jib

[Triage Comment]
Makes me a bit nervous since we're getting late in the cycle and this doesn't have great test coverage. OTOH, the impact sounds not great and the code changes are reasonably localized to WebRTC. Approving for 65.0b9 and requesting QA to do some verification around this.

Comment 21

[Raul Gurzau (:RaulG)]

Using arc patch command for Attachment 9032915 [details] fails to apply:  Rebase onto fd1ac788b655e9c9df7bce5c02c231583f7eeeb9 failed!

Comment 22

[Andreas Pehrson [:pehrsons]]

Minor conflict because of bug 1512280. Trivial to fix. I'll have new versions of the conflicted patches up in a bit.

Comment 23

[Andreas Pehrson [:pehrsons]]

Attachment: [beta 65] 2 - Make MediaEngineSource::SetTrack return void

Comment 24

[Andreas Pehrson [:pehrsons]]

Attachment: [beta 65] 3 - Enable pulling at the same time as starting audio sources

Comment 25

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/962f5d3b5330
https://hg.mozilla.org/releases/mozilla-beta/rev/59f2b329c3a1
https://hg.mozilla.org/releases/mozilla-beta/rev/1a2283b8f8c9
https://hg.mozilla.org/releases/mozilla-beta/rev/7fcc850b0e9e
https://hg.mozilla.org/releases/mozilla-beta/rev/61fc844e1f48

Comment 26

[Catalin Sasca, Desktop QA [:csasca]]

I tried reproducing the issue with a Microsoft HD-3000 webcam and with a Logitech HD Pro C920 under Ubuntu 18.04 (x64). With the Microsoft webcam, all went well and with the Logitech one I experienced a 0.5 second delay on the affected Nightly build (2018-12-13) after some 30 seconds in the gum_test.html. Is this the delay experienced by you, or is it worse? Thanks.

Comment 27

[Andreas Pehrson [:pehrsons]]

Half a second is in the right ballpark, yes. With the Brio I probably had closer to one second, but it depends on the OS and the camera so it's within what I'd expect.

Did it take 30 seconds before the delay emerged though, or was it present as soon as audio started?

If there's a gradual buildup of delay we have worse problems on our hands, but it's not something I've noticed, or heard reports of.

Comment 28

[Catalin Sasca, Desktop QA [:csasca]]

In the first 30 seconds, the audio was synced with the video, but after that, it was slowly delaying to max 0.5 second, and I never got more than that. From the testings, I reproduced the issue on Ubuntu 18.04 (x64) with the Logitech camera, but on macOS and Windows it wasn't happening on 65.0b8, which is still said to be affected by the issue.

Comment 29

[Andreas Pehrson [:pehrsons]]

Interesting.

On linux, could you also test with both values of the pref "media.cubeb.sandbox"?

There are some other problems than can appear as a delay when that pref is true (which is default on linux), though I hadn't expected them on gum_test.html. When finding and debugging this issue I probably had that pref set to false, as this helps with audio performance.

Comment 30

[Catalin Sasca, Desktop QA [:csasca]]

So with the media.cubeb.sandbox default (on) I can see the 0.5 delay, but with the pref set on false, I could not see it reproducing.

Comment 31

[Andreas Pehrson [:pehrsons]]

That's a different issue than what this bug is about then. If you find that it's a regression from 64, please file a new bug.

Comment 32

[Catalin Sasca, Desktop QA [:csasca]]

The issue has been verified on Firefox Beta 65.0b9 and latest Nightly (2019-01-08). Tests were performed with a logitech HD Pro C920 and a external microphone from A4tech headsets, under Ubuntu 18.04 (x64) with media.cubeb.sandbox pref set to off, Windows 10 (x64) and macOS 10.12 systems.

Comment 33

[Nils Ohlmeier [:drno]]

Landing this caused a new regression tracked in bug 1518834.