Open Bug 1339889 Opened 8 years ago Updated 3 years ago

Intermittent dom/media/webaudio/test/test_mediaElementAudioSourceNodeFidelity.html | Found unexpected noise during analysis.

Categories

(Core :: Web Audio, defect, P4)

Product:
Core
Component:
Web Audio
Platform:
ARM
Android
Type:
defect

Tracking

()

Status:
REOPENED
Milestone:
mozilla59
Tracking Flags:
Tracking Status
firefox57 --- wontfix
firefox58 --- fixed
firefox59 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, test-disabled, Whiteboard: [stockwell unknown])

Attachments

(2 files)

bug 1339889 add logging of maximum noise
59 bytes, text/x-review-board-request
padenot
: review+
Details
bug 1339889 don't use AnalyserNode smoothing when testing signal
59 bytes, text/x-review-board-request
padenot
: review+
Details
Rank: 35
Priority: -- → P3
Blocks: 1339438
Mass change P3->P4 to align with new Mozilla triage process.
Priority: P3 → P4
In the last 7 days there are 32 failures. They occur on android. A recent log example: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=147638291&lineNumber=2272 :kentuckyfriedtakahe, can you please take a look?
Flags: needinfo?(ajones)
Whiteboard: [stockwell needswork]
here is a recent failure: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=148321901&lineNumber=2269 and some recent data from the above log: [task 2017-11-29T00:56:00.916Z] 00:56:00 INFO - 409 INFO TEST-PASS | dom/media/webaudio/test/test_mediaElementAudioSourceNodeFidelity.html | Found correct audio signal during analysis [task 2017-11-29T00:56:00.917Z] 00:56:00 INFO - 410 INFO 8.693424 8.902403 [task 2017-11-29T00:56:00.917Z] 00:56:00 INFO - 411 INFO energy at 440: -14.96330738067627, threshold -40 [task 2017-11-29T00:56:00.917Z] 00:56:00 INFO - 412 INFO currentTime: 9.157823 [task 2017-11-29T00:56:00.918Z] 00:56:00 INFO - 413 INFO TEST-PASS | dom/media/webaudio/test/test_mediaElementAudioSourceNodeFidelity.html | Found correct audio signal during analysis [task 2017-11-29T00:56:00.918Z] 00:56:00 INFO - 414 INFO 8.902403 9.157823 [task 2017-11-29T00:56:00.918Z] 00:56:00 INFO - Buffered messages logged at 00:55:54 [task 2017-11-29T00:56:00.918Z] 00:56:00 INFO - 415 INFO energy at 440: -14.96268081665039, threshold -40 [task 2017-11-29T00:56:00.919Z] 00:56:00 INFO - 416 INFO currentTime: 9.668662 [task 2017-11-29T00:56:00.919Z] 00:56:00 INFO - 417 INFO TEST-PASS | dom/media/webaudio/test/test_mediaElementAudioSourceNodeFidelity.html | Found correct audio signal during analysis [task 2017-11-29T00:56:00.919Z] 00:56:00 INFO - 418 INFO 9.157823 9.668662 [task 2017-11-29T00:56:00.919Z] 00:56:00 INFO - 419 INFO currentTime: 9.807981 [task 2017-11-29T00:56:00.919Z] 00:56:00 INFO - Buffered messages finished [task 2017-11-29T00:56:00.920Z] 00:56:00 INFO - 420 INFO TEST-UNEXPECTED-FAIL | dom/media/webaudio/test/test_mediaElementAudioSourceNodeFidelity.html | Found unexpected noise during analysis. [task 2017-11-29T00:56:00.920Z] 00:56:00 INFO - audioElement.onplaying/audioElement.ontimeupdate@dom/media/webaudio/test/test_mediaElementAudioSourceNodeFidelity.html:101:7 [task 2017-11-29T00:56:11.615Z] 00:56:11 INFO - 421 INFO TEST-OK | dom/media/webaudio/test/test_mediaElementAudioSourceNodeFidelity.html | took 60811ms
This error message has been reported intermittently since the test was overhauled in February for bug 1339438. There was a period of higher frequency between August and September, and the current period of higher frequency began around Nov 3. All reports have been on Android. Prior to Nov 16 UTC, there was only the single opt failure on 15 Jun From Nov 16 opt failures became sporadic, but became frequent on Nov 27 with the first reported failures on android-api-16-gradle. Perhaps that corresponds with the fix for bug 654787. Since then most opt failures have been on android-api-16-gradle.
Assignee: nobody → karlt
Pushed by ktomlinson@mozilla.com: https://hg.mozilla.org/integration/mozilla-inbound/rev/029c91eceacd fix typo to address review comment from bug 1339438#c4 r=pehrsons
Comment on attachment 8934019 [details] bug 1339889 don't use AnalyserNode smoothing when testing signal https://reviewboard.mozilla.org/r/204942/#review210562
Attachment #8934019 - Flags: review?(padenot) → review+
Comment on attachment 8934018 [details] bug 1339889 add logging of maximum noise https://reviewboard.mozilla.org/r/204940/#review210564
Attachment #8934018 - Flags: review?(padenot) → review+
Pushed by ktomlinson@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/73f34d2e0b70 add logging of maximum noise r=padenot https://hg.mozilla.org/integration/autoland/rev/2ac1235b3e00 don't use AnalyserNode smoothing when testing signal r=padenot
There are 34 failures in the last 7 days. The occur on android-4-3-armv7-api16 and the affected build type is debug. Here is a recent log example: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=152601589&lineNumber=2186 and a relevant part of the log where the job failed: [task 2017-12-20T13:24:14.449Z] 13:24:14 INFO - 340 INFO TEST-PASS | dom/media/webaudio/test/test_mediaElementAudioSourceNodeFidelity.html | Found correct audio signal during analysis 2181 [task 2017-12-20T13:24:14.449Z] 13:24:14 INFO - 341 INFO 4.063492 4.365351 2182 [task 2017-12-20T13:24:14.449Z] 13:24:14 INFO - Buffered messages logged at 13:24:05 2183 [task 2017-12-20T13:24:14.450Z] 13:24:14 INFO - 342 INFO energy at 440: -16.086347579956055, threshold -40; max noise at index 42: -52.42803955078125 2184 [task 2017-12-20T13:24:14.450Z] 13:24:14 INFO - 343 INFO currentTime: 4.883151 2185 [task 2017-12-20T13:24:14.450Z] 13:24:14 INFO - Buffered messages finished 2186 [task 2017-12-20T13:24:14.451Z] 13:24:14 INFO - 344 INFO TEST-UNEXPECTED-FAIL | dom/media/webaudio/test/test_mediaElementAudioSourceNodeFidelity.html | Found unexpected noise during analysis. 2187 [task 2017-12-20T13:24:14.451Z] 13:24:14 INFO - audioElement.onplaying/audioElement.ontimeupdate@dom/media/webaudio/test/test_mediaElementAudioSourceNodeFidelity.html:110:7 2188 [task 2017-12-20T13:24:14.452Z] 13:24:14 INFO - 345 INFO TEST-OK | dom/media/webaudio/test/test_mediaElementAudioSourceNodeFidelity.html | took 30257ms :karlt, can you please take a look?
Flags: needinfo?(karlt)
Whiteboard: [stockwell unknown] → [stockwell needswork]
Pushed by ktomlinson@mozilla.com: https://hg.mozilla.org/integration/mozilla-inbound/rev/56774d8d43a4 disable Android debug test_mediaElementAudioSourceNodeFidelity.html as build is too slow to provide continuous audio
Audacity shows 0.006s of silence in sine-440-10s.opus before the sine wave begins. If there is nothing to indicate that this portion should be skipped, then even seamless looping will not sound seamless. The test aims to filter out the seam by analysing samples only after ~3.95s and before 8s, as reported by audioElement.currentTime. The changesets in comment 31 and comment 38 improved this filtering logic, and since then there have been no failures from optimized builds. Remaining failures include both unexpected noise outside 440Hz and lack of signal at 440Hz. e.g. https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=152000242&lineNumber=2271 energy at 440: -16.08993911743164, threshold -40; max noise at index 42: -49.7230110168457 currentTime: 5.833492 https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=151767786&lineNumber=2299 energy at 440: -Infinity, threshold -40; max noise at index 42: -Infinity currentTime: 6.15195 This test has been failing on Android debug since the duration of the test was lengthened for bug 1339438. The "Buffered messages logged times" indicate that currentTime is advancing slower than the clock used by the logger. e.g. for the second example above, currentTime advances 4s in 14s of elapsed time: Buffered messages logged at 03:03:33 390 INFO currentTime: 2.500929 Buffered messages logged at 03:03:41 403 INFO currentTime: 4.821791 Buffered messages logged at 03:03:47 419 INFO currentTime: 6.15195 If the decoding is not keeping up with real time, then the AudioNode will receive portions of silence. The -Infinity max energy is evidence of this. Apparently debug Android builds are not fast enough to keep up. I've disabled the test for these builds. I've skipped review request due to expected absence, but adding a needinfo to the author as a notification. Removing leave-open, because I don't see a way to run this test reliably on Android debug.
Flags: needinfo?(karlt)
Keywords: leave-open → test-disabled
OS: Unspecified → Android
Hardware: Unspecified → ARM
https://hg.mozilla.org/mozilla-central/rev/56774d8d43a4
Status: NEW → RESOLVED
Closed: 8 years ago
status-firefox59: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla59
Flags: needinfo?(padenot)
Flags: needinfo?(padenot)
This doesn't look fixed.
Flags: needinfo?(ajones) → needinfo?(giles)
Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=162838582&repo=autoland&lineNumber=2017
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
It doesn't look fixed. I've not wanted to spend dev time on it.
Flags: needinfo?(giles)
I have a fix for this one, I think I put a try link in the linux variant of this one.

(In reply to Jean-Yves Avenard [:jya] from comment #66)

https://pernos.co/debug/iDOY6EnWNEU8-Juh-2KHwg/index.html

This is an underrun, causing silence to be inserted into the stream because decoding couldn't keep up. See https://pernos.co/debug/iDOY6EnWNEU8-Juh-2KHwg/index.html#f{m[DP5E,Bu2K_,t[BQ4,H0Q_,f{e[DP5E,Bu2K_,s{af96wKiAA,bARY,oEm1Grg,uEmJSbg___ where 70 frames of silence is inserted.

By comment 28 this had issues on Android arm emulator in the past, and in this case it ran under rr. It makes sense that a slower machine suffers from some degree of underruns.

Flags: needinfo?(padenot)
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: