Closed Bug 1282262 Opened 8 years ago Closed 6 years ago

Intermittent dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | Test timed out.

Categories

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

Product:
Core
Component:
Audio/Video: MediaStreamGraph
Platform:
ARM
Android
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla62
Tracking Flags:
Tracking Status
firefox62 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: pehrsons)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell disable-recommended])

Attachments

(2 files)

Bug 1282262 - Reduce number of (slow) gUM requests in test_gUM_mediaStreamClone.
59 bytes, text/x-review-board-request
padenot
: review+
Details
Disable test on android
1.54 KB, patch
padenot
: review+
Details | Diff | Splinter Review
Rank: 35
Component: Audio/Video → Audio/Video: MediaStreamGraph
Priority: -- → P3
yesterday we really had a very high failure rate for this test on android/debug:
https://brasstacks.mozilla.com/orangefactor/index.html?display=Bug&bugid=1282262


this bug has been lingering for a few months, typically much fewer failures

:mreavy- could you help find someone to look at this?  Possibly an easy solution is to skip this on android/debug unless there is an easy fix.
Flags: needinfo?(mreavy)
Whiteboard: [stockwell needswork]
Andreas - can you look at this one?  The frequency has gone up a lot (perhaps due to timing changes)
Flags: needinfo?(mreavy) → needinfo?(apehrson)
Looking at how this got triggered on brasstacks it looks like bug 1366672 caused the increased fail rate.

My theory then is that this caused extra load on the android VM, which causes our audio stack to underrun, which causes the audio analysis in the test to time out.

I'd have to verify to be sure, so far the screenshots don't even contain the tab with the test.
Blocks: 1366672
Flags: needinfo?(apehrson)
See Also: → 1324932
Mass change P3->P4 to align with new Mozilla triage process.
Priority: P3 → P4
disabled this test case:
https://hg.mozilla.org/integration/mozilla-inbound/rev/550b6ae2740fcff21d9d0e8f35d4693ba65a0778

:mreavy- please make sure to remember this is disabled and assign it the proper priority.
Flags: needinfo?(mreavy)
Keywords: leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Jan-Ivar: FYI - this test was disabled.  It had significantly increased in frequency before being disabled.  Andreas was starting to look at it.
Flags: needinfo?(mreavy) → needinfo?(jib)
There are 30 failures in the last 7 days.
They occur on android-4-3-armv7-api16 and android-api-16-gradle. The affected build type is opt.
Here is a recent log example: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=152510917&lineNumber=2268
a relevant part of the log:
[task 2017-12-20T02:39:47.446Z] 02:39:47     INFO -  138 INFO TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | Test timed out.
2269
[task 2017-12-20T02:39:47.446Z] 02:39:47     INFO -      reportError@SimpleTest/TestRunner.js:121:7
2270
[task 2017-12-20T02:39:47.446Z] 02:39:47     INFO -      TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
2271
[task 2017-12-20T02:52:02.594Z] 02:52:02     INFO -  Browser unexpectedly found running. Killing...
2272
[task 2017-12-20T02:52:02.594Z] 02:52:02     INFO -  TEST-INFO | started process screentopng
2273
[task 2017-12-20T02:52:02.965Z] 02:52:02     INFO -  TEST-INFO | screentopng: exit 0
2274
[task 2017-12-20T02:52:06.768Z] 02:52:06     INFO -  org.mozilla.fennec_aurora still alive after SIGABRT: waiting...
2275
[task 2017-12-20T02:52:11.992Z] 02:52:11     INFO -  org.mozilla.fennec_aurora still alive after SIGABRT: waiting...
2276
[task 2017-12-20T02:52:17.217Z] 02:52:17     INFO -  org.mozilla.fennec_aurora still alive after SIGABRT: waiting...
2277
[task 2017-12-20T02:52:22.798Z] 02:52:22  WARNING -  TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | application timed out after 370 seconds with no output
2278
[task 2017-12-20T02:52:22.799Z] 02:52:22     INFO -  INFO | automation.py | Application ran for: 0:23:01.831690
2279
[task 2017-12-20T02:52:22.799Z] 02:52:22     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpSHRceTpidlog
2280
[task 2017-12-20T02:52:25.325Z] 02:52:25     INFO -  mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/TZ61erOmTtqUiTNUXbel3w/artifacts/public/build/target.crashreporter-symbols.zip
2281
[task 2017-12-20T02:52:28.916Z] 02:52:28     INFO -  mozcrash Copy/paste: /builds/worker/workspace/build/linux64-minidump_stackwalk /tmp/tmpT8NVFf/534ee2f8-5284-ffa2-7fdb-b23cf41ba546.dmp /tmp/tmpN2hnia
2282
[task 2017-12-20T02:52:28.933Z] 02:52:28     INFO -  mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/534ee2f8-5284-ffa2-7fdb-b23cf41ba546.dmp
2283
[task 2017-12-20T02:52:28.933Z] 02:52:28  WARNING -  PROCESS-CRASH | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | application crashed [None]
2284
[task 2017-12-20T02:52:28.933Z] 02:52:28     INFO -  Crash dump filename: /tmp/tmpT8NVFf/534ee2f8-5284-ffa2-7fdb-b23cf41ba546.dmp
2285
[task 2017-12-20T02:52:28.934Z] 02:52:28     INFO -  stderr from minidump_stackwalk:
2286
[task 2017-12-20T02:52:28.934Z] 02:52:28     INFO -  2017-12-20 02:52:28: minidump.cc:4359: INFO: Minidump opened minidump /tmp/tmpT8NVFf/534ee2f8-5284-ffa2-7fdb-b23cf41ba546.dmp
2287
[task 2017-12-20T02:52:28.934Z] 02:52:28     INFO -  2017-12-20 02:52:28: minidump.cc:4479: INFO: Minidump not byte-swapping minidump
2288
[task 2017-12-20T02:52:28.935Z] 02:52:28     INFO -  2017-12-20 02:52:28: minidump.cc:4956: INFO: GetStream: type 15 not present
2289
[task 2017-12-20T02:52:28.935Z] 02:52:28     INFO -  2017-12-20 02:52:28: minidump.cc:4956: INFO: GetStream: type 7 not present
2290
[task 2017-12-20T02:52:28.935Z] 02:52:28     INFO -  2017-12-20 02:52:28: minidump.cc:4956: INFO: GetStream: type 7 not present
2291
[task 2017-12-20T02:52:28.937Z] 02:52:28     INFO -  2017-12-20 02:52:28: minidump.cc:4956: INFO: GetStream: type 1197932545 not present
2292
[task 2017-12-20T02:52:28.937Z] 02:52:28     INFO -  2017-12-20 02:52:28: minidump.cc:4956: INFO: GetStream: type 6 not present
2293
[task 2017-12-20T02:52:28.937Z] 02:52:28     INFO -  2017-12-20 02:52:28: minidump.cc:4956: INFO: GetStream: type 1197932546 not present
2294
[task 2017-12-20T02:52:28.937Z] 02:52:28     INFO -  2017-12-20 02:52:28: minidump.cc:4956: INFO: GetStream: type 4 not present
2295
[task 2017-12-20T02:52:28.937Z] 02:52:28     INFO -  2017-12-20 02:52:28: minidump.cc:4956: INFO: GetStream: type 5 not present
2296
[task 2017-12-20T02:52:28.938Z] 02:52:28     INFO -  2017-12-20 02:52:28: minidump.cc:4956: INFO: GetStream: type 3 not present
2297
[task 2017-12-20T02:52:28.938Z] 02:52:28     INFO -  2017-12-20 02:52:28: minidump_processor.cc:152: ERROR: Minidump /tmp/tmpT8NVFf/534ee2f8-5284-ffa2-7fdb-b23cf41ba546.dmp has no thread list
2298
[task 2017-12-20T02:52:28.938Z] 02:52:28     INFO -  2017-12-20 02:52:28: stackwalk.cc:139: ERROR: MinidumpProcessor::Process failed
2299
[task 2017-12-20T02:52:28.938Z] 02:52:28     INFO -  2017-12-20 02:52:28: minidump.cc:4331: INFO: Minidump closing minidump
:jib, please take a look.
Whiteboard: [stockwell disabled] → [stockwell needswork]
There are 34 failures in the last 7 days.
Recent log example: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=154566031&lineNumber=2283 
For the failure pattern see Comment 53.
Whiteboard: [stockwell unknown] → [stockwell needswork]
This is failing on android-api-16-gradle (40 failures) and on android-4-3-armv7-api16 (13 failures).
Only the opt build type is affected.

There are 127 failures in the last month.
This was disabled 4 months ago.

Here is a recent log file and a snippet with the error:
https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=151852143&lineNumber=2266

[task 2017-12-15T18:44:12.299Z] 18:44:12     INFO -  136 INFO TEST-FAIL | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts
2264
[task 2017-12-15T18:44:12.299Z] 18:44:12     INFO -  137 INFO TEST-FAIL | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts
2265
[task 2017-12-15T18:44:12.299Z] 18:44:12     INFO -  Buffered messages finished
2266
[task 2017-12-15T18:44:12.299Z] 18:44:12     INFO -  138 INFO TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | Test timed out.
2267
[task 2017-12-15T18:44:12.300Z] 18:44:12     INFO -      reportError@SimpleTest/TestRunner.js:121:7
2268
[task 2017-12-15T18:44:12.300Z] 18:44:12     INFO -      TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
2269
[task 2017-12-15T18:44:12.300Z] 18:44:12     INFO -  139 INFO TEST-FAIL | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts
2270
[task 2017-12-15T18:44:12.300Z] 18:44:12     INFO -  140 INFO TEST-FAIL | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts
2271
[task 2017-12-15T18:56:35.192Z] 18:56:35     INFO -  Browser unexpectedly found running. Killing...

:pehrsons, could you please take another look?
Flags: needinfo?(apehrson)
This bug is still failing. It has 25 failures in the last 7 days on android affecting opt build type.
Link to a recent log:
Part of the log [task 2018-05-05T21:09:54.438Z] 21:09:54     INFO -  Buffered messages logged at 21:05:08
[task 2018-05-05T21:09:54.439Z] 21:09:54     INFO -  139 INFO Analysing audio output enabled and disabled tracks that don't affect each other
[task 2018-05-05T21:09:54.439Z] 21:09:54     INFO -  140 INFO TEST-FAIL | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts
[task 2018-05-05T21:09:54.439Z] 21:09:54     INFO -  141 INFO TEST-FAIL | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts
[task 2018-05-05T21:09:54.440Z] 21:09:54     INFO -  Buffered messages logged at 21:05:26
[task 2018-05-05T21:09:54.440Z] 21:09:54     INFO -  142 INFO TEST-FAIL | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts
[task 2018-05-05T21:09:54.441Z] 21:09:54     INFO -  143 INFO TEST-FAIL | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts
[task 2018-05-05T21:09:54.441Z] 21:09:54     INFO -  Buffered messages finished
[task 2018-05-05T21:09:54.441Z] 21:09:54     INFO -  144 INFO TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | Test timed out.
[task 2018-05-05T21:09:54.441Z] 21:09:54     INFO -      reportError@SimpleTest/TestRunner.js:121:7
[task 2018-05-05T21:09:54.442Z] 21:09:54     INFO -      TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
[task 2018-05-05T21:10:04.945Z] 21:10:04     INFO -  145 INFO TEST-PASS | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | Test must leave no active gUM streams behind.
[task 2018-05-05T21:10:04.945Z] 21:10:04     INFO -  146 ERROR [SimpleTest.finish()] this test already called finish!
[task 2018-05-05T21:10:04.945Z] 21:10:04     INFO -  147 INFO TEST-UNEXPECTED-ERROR | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | called finish() multiple times
[task 2018-05-05T21:10:04.945Z] 21:10:04     INFO -  TEST-INFO took 311767ms
[task 2018-05-05T21:10:04.945Z] 21:10:04     INFO -  148 INFO TEST-OK | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html
[task 2018-05-05T21:10:15.467Z] 21:10:15     INFO -  149 INFO TEST-START | dom/media/tests/mochitest/test_getUserMedia_mediaStreamConstructors.html


:drno,:jib do you guys have any update on this bug?
Flags: needinfo?(drno)
In the last 7 days there are 32 failures.
They occur on android-4-3-armv7-api16 - opt.
Recent failure log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=178000582&lineNumber=2175
[task 2018-05-11T05:38:21.916Z] 05:38:21     INFO -  143 INFO TEST-FAIL | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts
[task 2018-05-11T05:38:21.916Z] 05:38:21     INFO -  144 INFO TEST-FAIL | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts
[task 2018-05-11T05:38:21.917Z] 05:38:21     INFO -  Buffered messages finished
[task 2018-05-11T05:38:21.917Z] 05:38:21     INFO -  145 INFO TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | Test timed out.
[task 2018-05-11T05:38:21.918Z] 05:38:21     INFO -      reportError@SimpleTest/TestRunner.js:121:7
[task 2018-05-11T05:38:21.918Z] 05:38:21     INFO -      TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
[task 2018-05-11T05:47:49.836Z] 05:47:49     INFO -  Browser unexpectedly found running. Killing...
[task 2018-05-11T05:47:49.837Z] 05:47:49     INFO -  TEST-INFO | started process screentopng
[task 2018-05-11T05:47:50.193Z] 05:47:50     INFO -  TEST-INFO | screentopng: exit 0
[task 2018-05-11T05:48:04.950Z] 05:48:04  WARNING -  TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html | application timed out after 370 seconds with no output
[task 2018-05-11T05:48:04.951Z] 05:48:04     INFO -  INFO | automation.py | Application ran for: 0:24:56.757676
[task 2018-05-11T05:48:04.951Z] 05:48:04     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpcJfU_Xpidlog
[task 2018-05-11T05:48:05.267Z] 05:48:05     INFO -  Contents of /data/anr/traces.txt:
[task 2018-05-11T05:48:05.267Z] 05:48:05     INFO -  ----- pid 813 at 2018-05-11 05:47:49 -----
[task 2018-05-11T05:48:05.268Z] 05:48:05     INFO -  Cmd line: org.mozilla.fennec_aurora
[task 2018-05-11T05:48:05.269Z] 05:48:05     INFO -  JNI: CheckJNI is on; workarounds are off; pins=0; globals=274
[task 2018-05-11T05:48:05.269Z] 05:48:05     INFO -  DALVIK THREADS:
[task 2018-05-11T05:48:05.269Z] 05:48:05     INFO -  (mutexes: tll=0 tsl=0 tscl=0 ghl=0)
[task 2018-05-11T05:48:05.269Z] 05:48:05     INFO -  "main" prio=5 tid=1 NATIVE
[task 2018-05-11T05:48:05.269Z] 05:48:05     INFO -    | group="main" sCount=1 dsCount=0 obj=0x414c9578 self=0x2a00d090
[task 2018-05-11T05:48:05.269Z] 05:48:05     INFO -    | sysTid=813 nice=0 sched=0/0 cgrp=apps handle=1073811452
Whiteboard: [stockwell unknown] → [stockwell unknown][stockwell needswork]
The right people are on NI here already.

Looks like our best bet right now is to attempt to decrease the load on the emulators as requested over in bug 1366672
Flags: needinfo?(drno)
OS: Unspecified → Android
Hardware: Unspecified → ARM
FYI we captured this bug and made it debuggable in the Pernosco debugger:
https://pernos.co/debug/406GedM_PKbK4BGMNlNU5g/index.html
Access details here: https://mana.mozilla.org/wiki/display/TS/Debugging+with+Pernosco
Email me if you need any help.
See roc's comment 80
Flags: needinfo?(drno)
I've been looking at this in Pernosco, to see whether it has caught a legit timeout or not.

It does appear like a legit timeout indeed, and it confirms that we do some crazy things wrt device enumeration.

Pernosco like rr runs the recorded app on a single core, so some things are inherently slow. But there's lots of room for improvements. We could probably do fewer gUM calls in the test as a treatment of the symptoms. And really we should improve video device enumeration to do fewer IPC calls.

The timeline in the pernosco recording is (in seconds, with some things further drilled into than others, to show where we are slow):

- 158, test start

- 214, 1st gUM(a+v)
- 233, 1st gUM(a+v) resolved (took 19s)

- 239, 2nd gUM(v)
- 281, 2nd gUM(v) resolved (took 42s)

- 282, 3rd gUM(v)
- 305, before 3rd gUM(v) video GetBestFitnessDistance()
- 308, after 3rd gUM(v) video GetBestFitnessDistance()
- 308, before 3rd gUM(v) video Allocate()
- 308, before 3rd gUM(v) video ChooseCapability()
- 312, after 3rd gUM(v) video ChooseCapability()
- 314, after 3rd gUM(v) video Allocate()
- 315, before 3rd gUM(v) video Start()
- 317, after 3rd gUM(v) video Start()
- 318, 3rd gUM(v) resolved (took 36s)

- 331.6, before 2nd gUM(v) video Stop()

- 331.7, before awaiting playback
- 336.4, awaited playback

- 336.6, before 3rd gUM(v) video Stop()

- 337, 4th gUM(a+v)
- 337, EnumerateDevicesImpl()
- 338, EnumerateRawDevices()
- 338, before GetSources() for camera
- 338, before MediaEngineWebRTC::EnumerateDevices() for camera
- 338.3, [Sync IPC!] calling CamerasChild::NumberOfCaptureDevices (returned 8)
- 338.8, [Sync IPC!] calling CamerasChild::GetCaptureDevice (returned platform:v4l2loopback-000)
- 339.8, [Sync IPC!] calling CamerasChild::NumberOfCapabilities (returned 1)
- 341.1, [Sync IPC!] calling CamerasChild::GetCaptureCapability (returned 320x240@30)
- 342.8, [Sync IPC!] calling CamerasChild::GetCaptureDevice (returned platform:v4l2loopback-000) (from MediaEngineRemoteVideoSource::Init())
- 343.8, [Sync IPC!] calling CamerasChild::GetCaptureDevice (returned platform:v4l2loopback-001)
- 345.3, [Sync IPC!] calling CamerasChild::NumberOfCapabilities (returned 0)
- 346.4, [Sync IPC!] calling CamerasChild::GetCaptureDevice (returned platform:v4l2loopback-001) (from MediaEngineRemoteVideoSource::Init())
- 346.6, [Sync IPC!] calling CamerasChild::GetCaptureDevice (returned platform:v4l2loopback-002)
- 347.3, [Sync IPC!] calling CamerasChild::NumberOfCapabilities (returned 0)
- 349.8, [Sync IPC!] calling CamerasChild::GetCaptureDevice (returned platform:v4l2loopback-002) (from MediaEngineRemoteVideoSource::Init())
- 351.6, [Sync IPC!] calling CamerasChild::GetCaptureDevice (returned platform:v4l2loopback-003)
- 353.3, [Sync IPC!] calling CamerasChild::NumberOfCapabilities (returned 0)
- 353.3, [Sync IPC!] calling CamerasChild::GetCaptureDevice (returned platform:v4l2loopback-003) (from MediaEngineRemoteVideoSource::Init())
- 356.7, [Sync IPC!] calling CamerasChild::GetCaptureDevice (returned platform:v4l2loopback-004)
- 357.4, [Sync IPC!] calling CamerasChild::NumberOfCapabilities (returned 0)
- 358.0, [Sync IPC!] calling CamerasChild::GetCaptureDevice (returned platform:v4l2loopback-004) (from MediaEngineRemoteVideoSource::Init())
- 358.2, [Sync IPC!] calling CamerasChild::GetCaptureDevice (returned platform:v4l2loopback-005)
- 358.5, [Sync IPC!] calling CamerasChild::NumberOfCapabilities (returned 0)
- 358.9, [Sync IPC!] calling CamerasChild::GetCaptureDevice (returned platform:v4l2loopback-005) (from MediaEngineRemoteVideoSource::Init())
- 359.6, [Sync IPC!] calling CamerasChild::GetCaptureDevice (returned platform:v4l2loopback-006)
- 360.0, [Sync IPC!] calling CamerasChild::NumberOfCapabilities (returned 0)
- 360.6, [Sync IPC!] calling CamerasChild::GetCaptureDevice (returned platform:v4l2loopback-006) (from MediaEngineRemoteVideoSource::Init())
- 361.0, [Sync IPC!] calling CamerasChild::GetCaptureDevice (returned platform:v4l2loopback-007)
- 361.5, [Sync IPC!] calling CamerasChild::NumberOfCapabilities (returned 0)
- 361.8, [Sync IPC!] calling CamerasChild::GetCaptureDevice (returned platform:v4l2loopback-007) (from MediaEngineRemoteVideoSource::Init())
- 362.9, after MediaEngineWebRTC::EnumerateDevices() for camera
- 362.9, after GetSources() for camera

- 362.9, before GetSources() for microphone
- 362.9, before AudioInputCubeb::UpdateDevicesList()
- 362.9, [Sync IPC!] calling audioipc client enumerate_devices()
- 431.2, after AudioInputCubeb::UpdateDevicesList()
- 431.2, after GetSources() for microphone

- 432.8, SelectSettings
- 437.7, before 4th gUM(a+v) video Allocate()
- 438.7, before 4th gUM(a+v) video Start()
- 440, 4th gUM(a+v) resolved (took 97s)
- 440, start "cloning stream into inception"
- 441, done "cloning stream into inception"
- 442, setting up playback of "inception clone"
- 451, media element is playing

- 451, about to look up loopback devices from prefs
- 467.8, audio loopback pref read
- 468.2, video loopback pref read
- 468.2, 5th gUM(a+v)
- 468.3, test timed out
Flags: needinfo?(jib)
Flags: needinfo?(drno)
Flags: needinfo?(apehrson)
Note that there's no IPC for enumeration in this test on platforms other than linux (virtual device driver (IPC) vs builtin fake device (no IPC)), but hopefully reducing the number of gUM calls will still help.

And I'm unsure why windows has suddenly started to time out. I'm checking with Bryce if there was any recent landings there that could explain it.
Assignee: nobody → apehrson
Status: NEW → ASSIGNED
Looking at some of the Windows failures suggests that these failures may be other test failures that have been attributed to this bug[0][1][2]. I've eyeballed all the failures in the last week reported for Windows and this appears to be the case.

[0]: https://treeherder.mozilla.org/logviewer.html#?repo=try&job_id=179530279&lineNumber=19206
[1]: https://treeherder.mozilla.org/logviewer.html#?repo=try&job_id=179530434&lineNumber=2182
[2]: https://treeherder.mozilla.org/logviewer.html#?repo=try&job_id=179530305&lineNumber=2808
Thanks Bryce, indeed those attributions look wrong.

From comment 83 we can see that all the IPC calls for video enumeration takes ~25 seconds. That's bad. But more worringly the one IPC call for audio enumeration takes ~70 seconds. Dan, could you help check the pernosco recording for where all this time is spent? Is it a known issue?
Flags: needinfo?(dglastonbury)
Comment on attachment 8981845 [details]
Bug 1282262 - Reduce number of (slow) gUM requests in test_gUM_mediaStreamClone.

https://reviewboard.mozilla.org/r/247896/#review254054
Attachment #8981845 - Flags: review?(padenot) → review+
Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/86af7f209e19
Reduce number of (slow) gUM requests in test_gUM_mediaStreamClone. r=padenot
The failure rate actually went up after that patch landed. It seems like we're now timing out doing audio analysis on android-opt. That indicates underruns that cause audio artifacts. I think that basically warrants disabling the test on android emulator.

        Attachment #8983383 -
        Flags: review?(padenot)

    
  
Keywords: leave-open

    
  
See Also:  → 1282264

    
    

    
      
  

        Attachment #8983383 -
        Flags: review?(padenot) → review+

    
    

    
  
https://hg.mozilla.org/mozilla-central/rev/dc0f09259b73
Status: ASSIGNED → RESOLVED
Closed: 6 years ago

          status-firefox62:
          --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla62

    
    

    
      
  

    
  
Flags: needinfo?(dglastonbury)

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






  

    
  







  

    

      
Attachment

      

      
      
      
      
    

    

      

        

          

            
General

            

              Creator: 



            

            
Created: 

            
Updated: 

            
Size: