1693250 - Suspended seamless-looping audio cannot be resumed properly

Status: NEW

(Core :: Audio/Video: Playback, defect, P3)

Description

[Ethan Chen]

Attachment: audio_loop_test.zip

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/88.0.4324.150 Safari/537.36

Steps to reproduce:

Prerequisite: "media.seamless-looping" pref is true.
Steps:

1. Extract the attached zip and open index.html in Firefox Nightly.
2. Click "Audio Test" link, and then click "Play Audio" to play the sample music.
3. Wait more than 10 seconds to make sure the audio has looped at least once.
4. Go back to previous page and then go forward to the audio test page.

Actual results:

The audio resumes after 8 seconds of silence. Note that the silence would be longer if the audio has looped more than once in step 3.

Expected results:

The audio should resume immediately.

Comment 1

[Ethan Chen]

Here is some analysis:
If seamless looping is enabled, LoopingDecodingState in decoder state machine adjusts the decoded timestamps by adding |mAudioLoopingOffset| to them. But when the media element is suspended and then resumed, MediaDecoderStateMachine::ResumeMediaSink() is called to create a new MediaSink, whose clock is reset to current media time (without adding the looping offset). So the decoded audio frames will need to wait for a long time until the clock reaches their adjusted timestamps.

If my analysis is correct, I think there should be a way to "adjust" the MediaSink clock with the same looping offset from LoopingDecodingState.

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

The Bugbug bot thinks this bug should belong to the 'Core::Audio/Video: Playback' component, and is moving the bug to that component. Please revert this change in case you think the bot is wrong.

Comment 3

[Alastor Wu [:alwu]]

Start working on this today, as what comment1 said, we use non-adjusted time when we recreate a media sink. That caused AudioSink adding a lot of silence based on the time difference. Even if the audio sink was still keeping playing audio, but all data we played were actually silence.

Comment 4

[Alastor Wu [:alwu]]

I have patches already, and now I'm thinking about how to test that, because the issue happens on the lower level that isn't exposed to JS side.

Comment 5

[Alastor Wu [:alwu]]

Attachment: Bug 1693250 - part1 : keep clock time being monotonically increased even if the media sink has been changed.

Comment 6

[Alastor Wu [:alwu]]

Attachment: Bug 1693250 - part2 : use adjusted clock time in 'CompletedState::Step()'.

Depends on D113548

Comment 7

[Alastor Wu [:alwu]]

Attachment: Bug 1693250 - part2 : reset the audible state when the audio sink get shutdown.

When the audio sink shutdown, we should also reset the audible state for the listeners. Otherwise, MediaDecoderStateMachine would possibly rely on the incorrect audible state that is produced by previous sink, which would cause showing the sound indicator even if no sound is being playing.

Eg.
Considering following case without the reset of the audible state

1. Sink A is audible -> MDSM set mIsAudioDataAudible=true
2. Stop sink
3. Recreate sink B and it's playing silence -> MDSM's mIsAudioDataAudible=true is still true, this is wrong!

Depends on D113549

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/45cd86944c9f
part1 : keep clock time being monotonically increased even if the media sink has been changed. r=bryce
https://hg.mozilla.org/integration/autoland/rev/0e0f90271853
part2 : reset the audible state when the audio sink get shutdown. r=bryce

Comment 9

[Natalia Csoregi [:nataliaCs]]

Backed out for failures on test_recreate_media_sink_audible_change.html

backout: https://hg.mozilla.org/integration/autoland/rev/87fa6a377c53e9d1f8ce32dbd691edffe8fa01bb

push: https://treeherder.mozilla.org/jobs?repo=autoland&revision=0e0f90271853d78e745b7a9b60b3f406d4a53225&group_state=expanded&selectedTaskRun=M3pBqLUkQWCefBazNZh5hA.0

tier 1 failure seen on a later push: https://treeherder.mozilla.org/jobs?repo=autoland&revision=0b1c1f980faac6c37d79028bcc85d42fed89919b&searchStr=mda&group_state=expanded&test_paths=dom%2Fmedia%2Ftest%2Fmochitest.ini&selectedTaskRun=UgjOa4UyTp6zk7jFuxOCpw.0

failure log: https://treeherder.mozilla.org/logviewer?job_id=338863295&repo=autoland&lineNumber=4227

[task 2021-05-05T21:38:14.856Z] 21:38:14 INFO - TEST-PASS | dom/media/test/test_recreate_media_sink_audible_change.html | received mozaudiblestatechanged 2 times.
[task 2021-05-05T21:38:14.856Z] 21:38:14 INFO - Buffered messages finished
[task 2021-05-05T21:38:14.857Z] 21:38:14 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_recreate_media_sink_audible_change.html | Become audible in 23 times of looping
[task 2021-05-05T21:38:14.857Z] 21:38:14 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2021-05-05T21:38:14.858Z] 21:38:14 INFO - testRecreateMediaSinkWhenChangeSinkId@dom/media/test/test_recreate_media_sink_audible_change.html:53:5
[task 2021-05-05T21:38:14.858Z] 21:38:14 INFO - add_task | Leaving test testRecreateMediaSinkWhenChangeSinkId
[task 2021-05-05T21:38:14.859Z] 21:38:14 INFO - GECKO(5968) | MEMORY STAT | vsize 2103815MB | vsizeMaxContiguous 68863355MB | residentFast 95MB | heapAllocated 10MB
[task 2021-05-05T21:38:14.859Z] 21:38:14 INFO - TEST-OK | dom/media/test/test_recreate_media_sink_audible_change.html | took 9618ms

Comment 10

[Andrew McCreight [:mccr8]]

This patch also caused a failure in browser_ProcessPriorityManager.js. It was kind of masked by my own patch in bug 1618547 which changed that test and landed immediately after this one, but I've confirmed with local backouts that this seems to be the patch at fault.

Specifically, it broke test_audio_background_tab and test_video_background_tab which play audio or video in a background tab and checks what happens with the process priority manager. Let me know if you want some help figuring out the priority manager, as I've been looking at it recently. The test is only enabled on Windows, but you can hack around that and get the test working on other platforms.

Comment 11

[Alastor Wu [:alwu]]

Thank you for letting me know that. I will check those failure later today to see what's happened.

Comment 12

[Alastor Wu [:alwu]]

The reason of the failure that happened on test_recreate_media_sink_audible_change.html on Windows is the clock time we got from the audio sink had a huge difference between the media data that we've played. I'm not sure why this would happen, and that only happens on Windows intermittently (I can run that succefully on my local environment)

The failure reason for browser_ProcessPriorityManager.js is because now we would reset the audible state when we starts the media sink, which would cause media element releases the wakelock first, and then request wakelock again later when audio becomes audible. That test assumes that the priority of tab won't change even if media happens looping, but now the prority would change everytime when we restart the media sink, that causes an error.

Comment 13

[Alastor Wu [:alwu]]

The backout is all about the second patch (audible behavior changes + test failure). I'm thinking about to land the first patch only because of this and file a new bug to handle the test failure for both test_recreate_media_sink_audible_change.html and browser_ProcessPriorityManager.js. Bryce, WDYT?

Comment 14

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

Fine by me.

Comment 15

[Alastor Wu [:alwu]]

Just found out that bug 1712598 helps on the issue I mentioned, so I will no need to land the first patch (that will further improve the overall mechanism, but not urgent for now). I will go back to this bug after I finish media stream related work.

Comment 16

[BugBot [:suhaib / :marco/ :calixte]]

There are some r+ patches which didn't land and no activity in this bug for 2 weeks.
:alwu, could you have a look please?
For more information, please visit auto_nag documentation.

Comment 17

[Alastor Wu [:alwu]]

Just rebased these patches, and then I am going to see if they still break any tests on the try server.

Comment 18

[Alastor Wu [:alwu]]

Add a NI for this Phabricator comment.

Comment 19

[Alastor Wu [:alwu]]

Attachment: Bug 1693250 - part3 : add another test to check whether audio sink incorrectly inserts silence.

Depends on D113550

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/54b9fbe63086
part1 : keep clock time being monotonically increased even if the media sink has been changed. r=bryce
https://hg.mozilla.org/integration/autoland/rev/f869096a85f2
part2 : reset the audible state when the audio sink get shutdown. r=bryce,karlt
https://hg.mozilla.org/integration/autoland/rev/7a2f57793a3b
part3 : add another test to check whether audio sink incorrectly inserts silence. r=media-playback-reviewers,webidl,saschanaz,padenot

Comment 21

[Natalia Csoregi [:nataliaCs]]

Backed out for causing high frequency failures on test_recreate_audio_sink_clock_time.html.

• backout: https://hg.mozilla.org/integration/autoland/rev/0fee5c0cff815bf87611613b1db563ce153c7247
• push:
  • tier 1 failures
  • push that caused the failures
• failure log: https://treeherder.mozilla.org/logviewer?job_id=422940217&repo=autoland&lineNumber=3046

[task 2023-07-18T02:25:02.225Z] 02:25:02     INFO - TEST-PASS | dom/media/test/test_recreate_audio_sink_clock_time.html | received seeked 3 times. 
[task 2023-07-18T02:25:02.225Z] 02:25:02     INFO - suspend then resume the media element, which would result in creating a new audio sink
[task 2023-07-18T02:25:02.225Z] 02:25:02     INFO - Buffered messages finished
[task 2023-07-18T02:25:02.226Z] 02:25:02     INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_recreate_audio_sink_clock_time.html | gap 2 : too many gaps in this audio! 
[task 2023-07-18T02:25:02.226Z] 02:25:02     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:424:16
[task 2023-07-18T02:25:02.226Z] 02:25:02     INFO -     testConsistentGrowingClockTimeBetweenSinks/<@dom/media/test/test_recreate_audio_sink_clock_time.html:37:9
[task 2023-07-18T02:25:02.226Z] 02:25:02     INFO -     EventListener.handleEvent*testConsistentGrowingClockTimeBetweenSinks@dom/media/test/test_recreate_audio_sink_clock_time.html:32:9
[task 2023-07-18T02:25:02.226Z] 02:25:02     INFO -     async*add_task/nextTick/<@SimpleTest/SimpleTest.js:2147:34
[task 2023-07-18T02:25:02.226Z] 02:25:02     INFO -     async*nextTick@SimpleTest/SimpleTest.js:2182:11
[task 2023-07-18T02:25:02.226Z] 02:25:02     INFO -     setTimeout handler*SimpleTest_setTimeoutShim@SimpleTest/SimpleTest.js:920:41
[task 2023-07-18T02:25:02.226Z] 02:25:02     INFO -     add_task@SimpleTest/SimpleTest.js:2096:17
[task 2023-07-18T02:25:02.226Z] 02:25:02     INFO -     @dom/media/test/test_recreate_audio_sink_clock_time.html:16:9
[task 2023-07-18T02:25:03.272Z] 02:25:03     INFO - TEST-PASS | dom/media/test/test_recreate_audio_sink_clock_time.html | received timeupdate 5 times.