Closed Bug 991776 Opened 10 years ago Closed 10 years ago

Intermittent test_mediarecorder_record_audiocontext.html | Test timed out.

Categories

(Core :: Audio/Video: Recording, defect)

Product:
Core
Component:
Audio/Video: Recording
Platform:
ARM
Gonk (Firefox OS)
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla33
Tracking Flags:
Tracking Status
firefox31 --- fixed
firefox32 --- fixed
firefox33 --- fixed
firefox-esr24 --- unaffected
b2g-v1.4 --- unaffected
b2g-v2.0 --- fixed
b2g-v2.1 --- fixed

People

(Reporter: emorley, Assigned: bechen)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

bug-991776.patch
7.05 KB, patch
bechen
: review+
Details | Diff | Splinter Review 
b2g_emulator_vm mozilla-inbound opt test mochitest-3 on 2014-04-03 06:25:39 PDT for push 448bccfe7543

slave: tst-linux64-spot-612

https://tbpl.mozilla.org/php/getParsedLog.php?id=37218618&tree=Mozilla-Inbound

{
06:58:38     INFO -  1280 INFO TEST-START | /tests/content/media/test/test_mediarecorder_getencodeddata.html
06:58:40     INFO -  1281 INFO TEST-INFO | MEMORY STAT vsize after test: 120147968
06:58:40     INFO -  1282 INFO TEST-INFO | MEMORY STAT residentFast after test: 54628352
06:58:40     INFO -  1283 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 25734328
06:58:41     INFO -  1284 INFO TEST-END | /tests/content/media/test/test_mediarecorder_getencodeddata.html | finished in 3330ms
06:58:42     INFO -  1285 INFO TEST-START | /tests/content/media/test/test_mediarecorder_record_audiocontext.html
07:04:09     INFO -  1286 INFO TEST-INFO | dumping last 1 message(s)
07:04:09     INFO -  1287 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test
07:04:09     INFO -  1288 INFO TEST-PASS | /tests/content/media/test/test_mediarecorder_record_audiocontext.html | check record state recording
07:04:09     INFO -  1289 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_mediarecorder_record_audiocontext.html | Test timed out.
}
I don't really know whether this is a problem in MediaRecorder or AudioContext, but the test is waiting for MediaRecorder events, so moving component to get visibility for MediaRecorder people.
Component: Web Audio → Video/Audio: Recording
Thanks, I can check that.
Hi JW, 
Could you help on this?
Assignee: nobody → jwwang
Note - the spike of failures here are likely related to what's being seen in bug 969372.
Hi Benjamin,

Please take this bug. The cause should be the same as bug 969372.
Assignee: jwwang → bechen
Depends on: 969372
Here is the timeout log reproduced on my desktop. (./mach mochitest-plain content/media/test/test_mediarecorder_record_audiocontext.html --run-until-failure --repeat 500)

=== At 23:48, we starts a testcase.

23:48.72 4958 INFO Slowest: 8337ms - /tests/content/media/test/test_mediarecorder_record_audiocontext.html
23:48.72 4959 INFO SimpleTest START Loop 305
23:48.75 4960 INFO TEST-START | /tests/content/media/test/test_mediarecorder_record_audiocontext.html
23:48.88 ++DOMWINDOW == 172 (0x7f242482f000) [pid = 45425] [serial = 679] [outer = 0x7f243176a400]
23:50.25 2014-06-27 09:49:33.088177 UTC - 1510364992[7f2458b61260]: MediaRecorder.Start 7f2439f297a0
23:50.25 2014-06-27 09:49:33.088269 UTC - 1510364992[7f2458b61260]: Session.Start 7f242d4bdfd0
23:50.25 4961 INFO TEST-PASS | /tests/content/media/test/test_mediarecorder_record_audiocontext.html | check record state recording
23:52.92 2014-06-27 09:49:35.756869 UTC - 1510364992[7f2458b61260]: Session.NotifyTracksAvailable track type = (1)
23:52.92 2014-06-27 09:49:35.756927 UTC - 1510364992[7f2458b61260]: Session.AfterTracksAdded 7f242d4bdfd0
23:52.92 2014-06-27 09:49:35.758440 UTC - 1963980544[7f23df6ebfe0]: Session.ExtractRunnable shutdown = 0

=== Here the encoder thread go into extract function.

23:52.92 2014-06-27 09:49:35.758455 UTC - 1963980544[7f23df6ebfe0]: Session.Extract 7f242d4bdfd0

=== Then we saw a lot of MR objects are been destroyed.

23:52.94 --DOMWINDOW == 171 (0x7f242a5e5000) [pid = 45425] [serial = 657] [outer = (nil)] [url = http://mochi.test:8888/tests/content/media/test/test_mediarecorder_record_audiocontext.html]
23:52.94 2014-06-27 09:49:35.775191 UTC - 1510364992[7f2458b61260]: ~MediaRecorder (7f2434a6d920)
23:52.94 --DOMWINDOW == 170 (0x7f24100e8c00) [pid = 45425] [serial = 655] [outer = (nil)] [url = http://mochi.test:8888/tests/content/media/test/test_mediarecorder_record_audiocontext.html]
23:52.94 [45425] WARNING: Failed to unlock the wakelock.: '!rv.Failed()', file /home/benjamin/Documents/hg/mozilla-central/content/html/content/src/HTMLMediaElement.cpp, line 2276
23:52.94 --DOMWINDOW == 169 (0x7f242af8e000) [pid = 45425] [serial = 639] [outer = (nil)] [url = http://mochi.test:8888/tests/content/media/test/test_mediarecorder_record_audiocontext.html]
23:52.94 --DOMWINDOW == 168 (0x7f24267f0400) [pid = 45425] [serial = 637] [outer = (nil)] [url = http://mochi.test:8888/tests/content/media/test/test_mediarecorder_record_audiocontext.html]
23:52.94 --DOMWINDOW == 167 (0x7f2429fbe800) [pid = 45425] [serial = 487] [outer = (nil)] [url = http://mochi.test:8888/tests/content/media/test/test_mediarecorder_record_audiocontext.html]
23:52.94 --DOMWINDOW == 166 (0x7f241ab28000) [pid = 45425] [serial = 643] [outer = (nil)] [url = http://mochi.test:8888/tests/content/media/test/test_mediarecorder_record_audiocontext.html]
23:52.94 [45425] WARNING: Failed to unlock the wakelock.: '!rv.Failed()', file /home/benjamin/Documents/hg/mozilla-central/content/html/content/src/HTMLMediaElement.cpp, line 2276
23:52.94 [45425] WARNING: Failed to unlock the wakelock.: '!rv.Failed()', file /home/benjamin/Documents/hg/mozilla-central/content/html/content/src/HTMLMediaElement.cpp, line 2276
23:52.94 [45425] WARNING: Failed to unlock the wakelock.: '!rv.Failed()', file /home/benjamin/Documents/hg/mozilla-central/content/html/content/src/HTMLMediaElement.cpp, line 2276
23:52.95 2014-06-27 09:49:35.791466 UTC - 1510364992[7f2458b61260]: MediaRecorder 7f2439f297a0 document IsActive 1 isVisible 1
23:52.96 2014-06-27 09:49:35.803760 UTC - 1510364992[7f2458b61260]: ~MediaRecorder (7f2429d67d80)
23:52.96 2014-06-27 09:49:35.803826 UTC - 1510364992[7f2458b61260]: ~MediaRecorder (7f242b227600)
23:52.96 2014-06-27 09:49:35.803838 UTC - 1510364992[7f2458b61260]: ~MediaRecorder (7f2439d512e0)
23:52.96 2014-06-27 09:49:35.803848 UTC - 1510364992[7f2458b61260]: ~MediaRecorder (7f243b2137e0)
23:52.97 2014-06-27 09:49:35.803866 UTC - 1510364992[7f2458b61260]: ~MediaRecorder (7f2439f564c0)

...

== Then timeouts.

28:53.02 5025 INFO Error: Unable to restore focus, expect failures and timeouts.
28:53.13 2014-06-27 09:54:35.966483 UTC - 1510364992[7f2458b61260]: MediaRecorder 7f2439f297a0 document IsActive 1 isVisible 0
28:53.13 2014-06-27 09:54:35.966548 UTC - 1510364992[7f2458b61260]: MediaRecorder.Stop 7f2439f297a0
28:53.13 2014-06-27 09:54:35.966558 UTC - 1510364992[7f2458b61260]: Session.Stop 7f242d4bdfd0
28:53.13 2014-06-27 09:54:35.966633 UTC - 1510364992[7f2458b61260]: MediaRecorder 7f2439f297a0 document IsActive 1 isVisible 0
28:53.13 2014-06-27 09:54:35.966644 UTC - 1510364992[7f2458b61260]: MediaRecorder.Stop 7f2439f297a0
28:53.15 2014-06-27 09:54:35.989113 UTC - 1510364992[7f2458b61260]: MediaRecorder 7f2439f297a0 document IsActive 0 isVisible 0
28:53.15 2014-06-27 09:54:35.989185 UTC - 1510364992[7f2458b61260]: MediaRecorder.Stop 7f2439f297a0
28:53.15 ++DOMWINDOW == 17 (0x7f23df5b2800) [pid = 45425] [serial = 680] [outer = 0x7f243176a400]

===

So we can see the timeout MR and Session are still alive due to the bug 969372 last check in patches. That make sense. So we can exclude the MR and Session are dead.
And now I guess the encoder thread is blocked in OpusTrackEncoder because the source mediastream doesn't have any inputs... And also need to investigate whether the "a lot of MR destroyed" is relevant to this.
77:32.27 8837 INFO Passed:  2495
77:32.27 8838 INFO Failed:  0
77:32.28 8839 INFO Todo:    0
77:32.28 8840 INFO Slowest: 10619ms - /tests/content/media/test/test_mediarecorder_record_audiocontext.html
77:32.28 8841 INFO SimpleTest START Loop 500
77:32.33 8842 INFO TEST-START | /tests/content/media/test/test_mediarecorder_record_audiocontext.html
77:32.66 ++DOMWINDOW == 154 (0x7f8686786800) [pid = 33485] [serial = 1454] [outer = 0x7f8786eac400]
77:33.73 2014-06-30 07:35:11.197169 UTC - -1280596160[7f87b2561260]: MediaRecorder.Start 7f86f8b28880
77:33.73 2014-06-30 07:35:11.197254 UTC - -1280596160[7f87b2561260]: Session.Start 7f86dc884970
77:33.74 8843 INFO TEST-PASS | /tests/content/media/test/test_mediarecorder_record_audiocontext.html | check record state recording
77:36.03 2014-06-30 07:35:13.495208 UTC - -1280596160[7f87b2561260]: Session.NotifyTracksAvailable track type = (1)
77:36.03 2014-06-30 07:35:13.495262 UTC - -1280596160[7f87b2561260]: Session.AfterTracksAdded 7f86dc884970
77:36.03 2014-06-30 07:35:13.496169 UTC - 1713370880[7f866bcfe160]: Session.ExtractRunnable shutdown = 0
77:36.03 2014-06-30 07:35:13.496184 UTC - 1713370880[7f866bcfe160]: Session.Extract 7f86dc884970
77:36.03 wait 0x7f866f9eaa00
77:36.14 --DOMWINDOW == 153 (0x7f8678f5e800) [pid = 33485] [serial = 1441] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
77:36.14 --DOMWINDOW == 152 (0x7f8773795c00) [pid = 33485] [serial = 1433] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
77:36.14 --DOMWINDOW == 151 (0x7f86c27f9c00) [pid = 33485] [serial = 1443] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
77:36.14 --DOMWINDOW == 150 (0x7f878a463000) [pid = 33485] [serial = 1403] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
77:36.14 --DOMWINDOW == 149 (0x7f8784a51400) [pid = 33485] [serial = 1435] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
77:36.14 --DOMWINDOW == 148 (0x7f86c27ec000) [pid = 33485] [serial = 1437] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
77:36.14 --DOMWINDOW == 147 (0x7f871d1df400) [pid = 33485] [serial = 1413] [outer = (nil)] [url = about:blank]
77:36.14 --DOMWINDOW == 146 (0x7f871d1df000) [pid = 33485] [serial = 1431] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
77:36.15 2014-06-30 07:35:13.611287 UTC - -1280596160[7f87b2561260]: MediaRecorder 7f86f8b28880 document IsActive 1 isVisible 1
77:36.49 leave wait 1872669184
77:36.49 wait 0x7f866f9eaa00
77:36.49 leave wait 1872669184

...


===
The log shows that the encoder thread is staying in the while loop in OpusTrackEncoder::GetMetadata().
The only scenario is that the |mInitialized| is always false. Then we look into the function AudioTrackEncoder::NotifyQueuedTrackChanges.
If the AudioChunk arrives here is always null but has Duration (kick the encoder thread), it did the timeout. I'll verify the AudioChunk to see if we can get more evidences.
I have confirmed that the TrackEncoder is keeping receive null AudioChunk with non-zero duration. So the OpusTrackEncoder doesn't call Init function that cause the encoder thread stays in the while loop of OpusTrackEncoder::GetMetadata().
Then the AudioTrackEncoder::NotifyQueuedTrackChanges is still keeping append AudioSegments and kicking encoder thread that cause the memory-pressure I saw in the log.

So there are two bugs in there.
One is the TrackEncoder should handle this kind of AudioChunks? Another is what happened to the webaudio or MSG always send the null AudioChuncks with duration? We should open another bug to track it.
We can easily reproduce this bug by decreasing the buffer size in testcase.
var buffer = context.createBuffer(1, 1024, context.sampleRate); 
                                     ^^^^
81920 -> 1024.

In the case, only the first 1024 audio frames are valid to OpusTrackEncoder for initialization. Once the buffer run out, there is no valid frames.
http://dxr.mozilla.org/mozilla-central/source/content/media/MediaRecorder.cpp?from=mediarecorder.cpp&case=true#384
Because |mTrackUnionStream->AddListener| is not synchronous so the encoder might miss the first 1024 frames and then fall into an infinite loop in OpusTrackEncoder::GetMetadata().
Attached patch bug-991776.patch (obsolete) — — Splinter Review 
Hi roc:
The root cause of the timeout is that: It is not synchronous that MediaEncoder be hooked on the TrackUnionStream. Once the AudioBufferSourceNode ran out it's buffer, the encoder will receive the AudioChunk with duration but no channel. This kind of AudioChunks can not initialize the encoder. 
The Encoder might miss valid AudioChunks because the async hook, so the encoder thread will fall into an infinite loop.

I modify the testcase to make the |source.loop| is true, and also add logs in TrackEncoder.
Attachment #8449989 - Flags: review?(roc)
Comment on attachment 8449989 [details] [diff] [review]
bug-991776.patch

Review of attachment 8449989 [details] [diff] [review]:
-----------------------------------------------------------------

This patch looks OK but I think there is also an underlying bug that needs to be fixed.

> The Encoder might miss valid AudioChunks because the async hook, so the encoder thread will fall into an infinite loop.

If we get one of these AudioChunks containing no channels (silence), the encoder should still initialize and encode silence.
Attachment #8449989 - Flags: review?(roc) → review+
(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #56)
> Comment on attachment 8449989 [details] [diff] [review]
> bug-991776.patch
> 
> Review of attachment 8449989 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> This patch looks OK but I think there is also an underlying bug that needs
> to be fixed.
> 
> > The Encoder might miss valid AudioChunks because the async hook, so the encoder thread will fall into an infinite loop.
> 
> If we get one of these AudioChunks containing no channels (silence), the
> encoder should still initialize and encode silence.
For this case, what's the channel number should we use? 
ie, if OpusTrackEncoder init the opus encoder as channel = 1, then audio chunk start to feed the the stereo data, should we make the stereo PCM data as mono?
Or init the opus encoder as channel = 2 and make mono data as stereo?
See Also: → 1034471
Attached patch bug-991776.patch — — Splinter Review 
r=roc
try server: https://tbpl.mozilla.org/?tree=Try&rev=f069bbab9622
Attachment #8449989 - Attachment is obsolete: true
Attachment #8451499 - Flags: review+
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/3688d5116fd0
Status: NEW → RESOLVED
Closed: 10 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → mozilla33
Is this safe to backport? If so, please nominate it for Aurora consideration. Since this is B2G-only, I think we're OK wontfixing it for Beta31 unless you feel otherwise. Thanks :)
status-b2g-v1.4: --- → unaffected
status-b2g-v2.0: --- → affected
status-b2g-v2.1: --- → fixed
status-firefox31: --- → wontfix
status-firefox32: --- → affected
status-firefox33: --- → fixed
status-firefox-esr24: --- → unaffected
Flags: needinfo?(bechen)
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #62)
> Is this safe to backport? If so, please nominate it for Aurora
> consideration. Since this is B2G-only, I think we're OK wontfixing it for
> Beta31 unless you feel otherwise. Thanks :)

Yes, it's safe to previous version since I only modify the testcase and add some logs in code.
And the intermittent timeout appears on all platform not B2G-only, just because B2G platform's run speed is more slower than other platforms make the problem easily occurs.
Flags: needinfo?(bechen)
Comment on attachment 8451499 [details] [diff] [review]
bug-991776.patch

Review of attachment 8451499 [details] [diff] [review]:
-----------------------------------------------------------------

Approval Request Comment
[Feature/regressing bug #]: Bug 991776.
[User impact if declined]: fix testcase timeout.
[Describe test coverage new/current, TBPL]: Current
[Risks and why]: Low. Only modify testcases. Add logs in code.
[String/UUID change made/needed]: None.
Attachment #8451499 - Flags: approval-mozilla-aurora?
Comment on attachment 8451499 [details] [diff] [review]
bug-991776.patch

Going to land this a=test-only as the code changes are behind #ifdef PR_LOGGING and the only functional changes are to the tests themselves.
Attachment #8451499 - Flags: approval-mozilla-aurora?
See Also: → 1198157
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: