Open Bug 1339889 Opened 4 years ago Updated 2 months 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: 3 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)
You need to log in before you can comment on or make changes to this bug.