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

REOPENED
Assigned to

Status

()

defect
P4
normal
Rank:
35
REOPENED
2 years ago
3 months ago

People

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

Tracking

({intermittent-failure, test-disabled})

unspecified
mozilla59
ARM
Android
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox57 wontfix, firefox58 fixed, firefox59 fixed)

Details

(Whiteboard: [stockwell unknown])

Attachments

(2 attachments)

Updated

2 years ago
Rank: 35
Priority: -- → P3
Blocks: 1339438
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Mass change P3->P4 to align with new Mozilla triage process.
Priority: P3 → P4
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
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]
Comment hidden (Intermittent Failures Robot)
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

Comment 29

2 years ago
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 hidden (mozreview-request)
Comment hidden (Intermittent Failures Robot)

Comment 35

2 years ago
mozreview-review
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 36

2 years ago
mozreview-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+

Comment 37

2 years ago
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
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
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]

Comment 42

2 years ago
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)
OS: Unspecified → Android
Hardware: Unspecified → ARM

Comment 44

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/56774d8d43a4
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla59
Flags: needinfo?(padenot)
Comment hidden (Intermittent Failures Robot)
Flags: needinfo?(padenot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
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 → ---
Comment hidden (Intermittent Failures Robot)
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.
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
You need to log in before you can comment on or make changes to this bug.