Audio input latency, possibly in MediaStreamGraph

VERIFIED FIXED in Firefox 65

Status

()

defect
P1
normal
VERIFIED FIXED
4 months ago
3 months ago

People

(Reporter: pehrsons, Assigned: pehrsons)

Tracking

({regression})

65 Branch
mozilla66
Points:
---
Dependency tree / graph
Bug Flags:
in-testsuite -

Firefox Tracking Flags

(firefox-esr60 unaffected, firefox64 unaffected, firefox65+ verified, firefox66+ verified)

Details

Attachments

(7 attachments)

(Assignee)

Description

4 months ago
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

4 months ago
Mark this one as P2 for now, free feel to change priority.
Priority: -- → P2
(Assignee)

Comment 2

4 months ago
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
Assignee: nobody → apehrson
Status: NEW → ASSIGNED
Component: WebRTC: Audio/Video → Audio/Video: MediaStreamGraph
Keywords: regression
Priority: P2 → P1
(Assignee)

Comment 3

4 months ago
65 is also affected.
(Assignee)

Comment 4

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

Comment 5

4 months ago
At least this wasn't the big first landing of the MSG refactor, but the smaller followup, bug 1509548.
Blocks: 1509548
(Assignee)

Comment 7

4 months ago
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.
Tracking this regression from 65.
(Assignee)

Comment 9

4 months ago
The microphone source is no longer shared so this check is moot.
(Assignee)

Comment 10

4 months ago
All subclasses are now returning NS_OK, so there's no point in keeping nsresult
as the return type.
(Assignee)

Comment 11

4 months ago
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.
(Assignee)

Comment 12

4 months ago
This better reflects the actual pulling that we do.
Attachment #9032915 - Attachment description: Bug 1513973 - Enable pulling of audio before starting MediaEngineSources. r?jib → Bug 1513973 - Enable pulling at the same time as starting audio sources. r?jib
Attachment #9032995 - Attachment description: Bug 1513973 - Remove mutable keyword from MediaEngineWebRTCMicrophoneSource runnables. r?jib → Bug 1513973 - Remove mutable keyword from MediaEngineWebRTCMicrophoneSource runnables.

Comment 14

4 months ago
Pushed by pehrsons@gmail.com:
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
(Assignee)

Comment 15

4 months ago
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
Attachment #9032915 - Flags: approval-mozilla-beta?
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/mochikit@mozilla.org.xpi!/api.js:15:3
[task 2018-12-21T21:04:55.038Z] 21:04:55     INFO - loadMochitest@jar:file:///tmp/tmp0VTmfP.mozrunner/extensions/mochikit@mozilla.org.xpi!/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
Flags: needinfo?(apehrson)
(Assignee)

Updated

4 months ago
Flags: needinfo?(apehrson)
Attachment #9032915 - Flags: approval-mozilla-beta?

Comment 17

4 months ago
Pushed by pehrsons@gmail.com:
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
(Assignee)

Comment 19

4 months ago
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
Attachment #9032915 - Flags: approval-mozilla-beta?
Flags: qe-verify+
Flags: in-testsuite-
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.
Attachment #9032915 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Using arc patch command for Attachment 9032915 [details] fails to apply:  Rebase onto fd1ac788b655e9c9df7bce5c02c231583f7eeeb9 failed!
Flags: needinfo?(ryanvm)
(Assignee)

Comment 22

4 months ago
Minor conflict because of bug 1512280. Trivial to fix. I'll have new versions of the conflicted patches up in a bit.
Flags: needinfo?(ryanvm)
(Assignee)

Updated

4 months ago
Depends on: 1517710
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.
Flags: needinfo?(apehrson)
(Assignee)

Updated

3 months ago
Depends on: 1517711
(Assignee)

Comment 27

3 months ago

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.

Flags: needinfo?(apehrson) → needinfo?(catalin.sasca)

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.

Flags: needinfo?(catalin.sasca)
(Assignee)

Comment 29

3 months ago

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.

Flags: needinfo?(catalin.sasca)

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.

Flags: needinfo?(catalin.sasca)
(Assignee)

Comment 31

3 months ago

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.

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.

Status: RESOLVED → VERIFIED
Flags: qe-verify+
Depends on: 1518834

Landing this caused a new regression tracked in bug 1518834.

You need to log in before you can comment on or make changes to this bug.