1906761 - Fail to decode EncodedVideoChunk with empty or null duration

Status: RESOLVED FIXED

(Core :: Audio/Video: Web Codecs, defect, P3)

Description

[Andri Yngvason]

I've implemented a WebCodecs based H.264 decoder for noVNC: https://github.com/novnc/noVNC/pull/1876

After a few frames have been decoded, the error callback is called and decoding stops. We are seeing errors like these on the command line:

[RDD 15365: MediaPDecoder #1]: D/FFmpegVideo FFMPEG: Frame decode takes 0.35 ms average decode time 1.45 ms frame duration 0.00 average frame duration 0.00 decoded 12 frames
[RDD 15365: MediaPDecoder #1]: D/FFmpegVideo FFMPEG:   slow decode: failed to decode in time (decoded late 12)

What appears to be happening here is that Firefox doesn't receive a duration parameter with each encoded frame chunk, and sets the duration to zero instead of disabling the "slow decode" code path or deriving duration from timestamp.

According to the specification, the duration parameter is optional, so it should not be relied upon for such calculations.

Side note: It looks like the decoder object goes into an unrecoverable state when this happens, so the only way forward is to instantiate a new one. This means that we end up in a loop where the decoder gets switched to sw, fails, gets recreated and configured, get switched to sw, fails, etc.

Comment 1

[Alastor Wu [:alwu]]

This is a Web Codec video issue, Chun-min would you mind to take a look on this? If this is serious, feel free to change its priority and severity.

Comment 2

[C.M.Chang[:chunmin]]

(In reply to Andri Yngvason from comment #0)

I've implemented a WebCodecs based H.264 decoder for noVNC: https://github.com/novnc/noVNC/pull/1876

Hi Andri,

Could you create a test page demonstrating the issue and upload it here, or create a minimal test environment with steps-to-reproduce? It would greatly help us diagnose the issue.

After a few frames have been decoded, the error callback is called and decoding stops. We are seeing errors like these on the command line:

[RDD 15365: MediaPDecoder #1]: D/FFmpegVideo FFMPEG: Frame decode takes 0.35 ms average decode time 1.45 ms frame duration 0.00 average frame duration 0.00 decoded 12 frames
[RDD 15365: MediaPDecoder #1]: D/FFmpegVideo FFMPEG:   slow decode: failed to decode in time (decoded late 12)

What appears to be happening here is that Firefox doesn't receive a duration parameter with each encoded frame chunk, and sets the duration to zero instead of disabling the "slow decode" code path or deriving duration from timestamp.

According to the specification, the duration parameter is optional, so it should not be relied upon for such calculations.

Additionaly, I am failing to see why null or 0 duration causes the issue. Those logs are for statistics only.

Yes, duration is optional. On my Ubuntu machine, both video-decode-display sample or videoDecoder-codec-specific WPT works fine with forcing duration to null or 0. They have similar logs, but the decoding works fine.

0:14.39 pid:15010 [RDD 15390: MediaPDecoder #3]: D/FFmpegVideo FFMPEG: Frame decode takes 2.36 ms average decode time 46.24 ms frame duration 0.00 average frame duration 0.00 decoded 2 frames
0:14.39 pid:15010 [RDD 15390: MediaPDecoder #3]: D/FFmpegVideo FFMPEG:   slow decode: failed to decode in time (decoded late 2)

Side note: It looks like the decoder object goes into an unrecoverable state when this happens, so the only way forward is to instantiate a new one. This means that we end up in a loop where the decoder gets switched to sw, fails, gets recreated and configured, get switched to sw, fails, etc.

Did you see any issue in the logs with MOZ_LOG="WebCodecs:5"?

Comment 3

[Andri Yngvason]

(In reply to C.M.Chang[:chunmin] from comment #2)

(In reply to Andri Yngvason from comment #0)

I've implemented a WebCodecs based H.264 decoder for noVNC: https://github.com/novnc/noVNC/pull/1876

Could you create a test page demonstrating the issue and upload it here, or create a minimal test environment with steps-to-reproduce? It would greatly help us diagnose the issue.

It will be a while until I have time for that.

After a few frames have been decoded, the error callback is called and decoding stops. We are seeing errors like these on the command line:

[RDD 15365: MediaPDecoder #1]: D/FFmpegVideo FFMPEG: Frame decode takes 0.35 ms average decode time 1.45 ms frame duration 0.00 average frame duration 0.00 decoded 12 frames
[RDD 15365: MediaPDecoder #1]: D/FFmpegVideo FFMPEG:   slow decode: failed to decode in time (decoded late 12)

What appears to be happening here is that Firefox doesn't receive a duration parameter with each encoded frame chunk, and sets the duration to zero instead of disabling the "slow decode" code path or deriving duration from timestamp.

According to the specification, the duration parameter is optional, so it should not be relied upon for such calculations.

Additionaly, I am failing to see why null or 0 duration causes the issue. Those logs are for statistics only.

Yes, duration is optional. On my Ubuntu machine, both video-decode-display sample or videoDecoder-codec-specific WPT works fine with forcing duration to null or 0. They have similar logs, but the decoding works fine.

This is the code path that we're hitting: https://searchfox.org/mozilla-central/source/dom/media/platforms/ffmpeg/FFmpegVideoDecoder.cpp#1171

It is a result of this: https://searchfox.org/mozilla-central/rev/1cc09ebc0b32f69fd30057582671b0811f2cb9c8/dom/media/platforms/ffmpeg/FFmpegVideoDecoder.cpp#1028

... and this: https://searchfox.org/mozilla-central/source/dom/media/platforms/ffmpeg/FFmpegVideoDecoder.cpp#1001

0:14.39 pid:15010 [RDD 15390: MediaPDecoder #3]: D/FFmpegVideo FFMPEG: Frame decode takes 2.36 ms average decode time 46.24 ms frame duration 0.00 average frame duration 0.00 decoded 2 frames
0:14.39 pid:15010 [RDD 15390: MediaPDecoder #3]: D/FFmpegVideo FFMPEG:   slow decode: failed to decode in time (decoded late 2)

Side note: It looks like the decoder object goes into an unrecoverable state when this happens, so the only way forward is to instantiate a new one. This means that we end up in a loop where the decoder gets switched to sw, fails, gets recreated and configured, get switched to sw, fails, etc.

Did you see any issue in the logs with MOZ_LOG="WebCodecs:5"?

https://paste.sr.ht/~andri/bbbd0611ad9090f498f19fcd8a3c3aaab5973682

Comment 4

[C.M.Chang[:chunmin]]

I suspect we should restore the behavior that skips UpdateDecodeTimes if duration is zero: https://hg.mozilla.org/mozilla-central/rev/05d7a7c92cf24c6b47bf84a693c71a507b312f3c#l7.51, then mDecodedFramesLate won't be increased in this case. Without a test page, what I can do is to upload a test version of Firefox. I am going to create one in try server for test later today.

Comment 5

[C.M.Chang[:chunmin]]

(In reply to C.M.Chang[:chunmin] from comment #4)

I suspect we should restore the behavior that skips UpdateDecodeTimes if duration is zero: https://hg.mozilla.org/mozilla-central/rev/05d7a7c92cf24c6b47bf84a693c71a507b312f3c#l7.51, then mDecodedFramesLate won't be increased in this case. Without a test page, what I can do is to upload a test version of Firefox. I am going to create one in try server for test later today.

I've pushed a modified version on try: https://treeherder.mozilla.org/jobs?repo=try&revision=7878c74d998a4b787736773eae17d9418c0c1a0e

The downloadable executable is here: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/boBmU_pgSY24B4FWfQmUFQ/runs/0/artifacts/public/build/target.tar.bz2

Hi Andri, could you try if this change solves the issue?

Comment 6

[David Turner]

I've just tried this out and it works for me, thanks!

Comment 7

[Andri Yngvason]

(In reply to David Turner from comment #6)

I've just tried this out and it works for me, thanks!

That's good enough for me.

Comment 8

[C.M.Chang[:chunmin]]

Attachment: Bug 1906761 - Skip UpdateDecodeTimes for non-positive-duration frames

This patch restores the behavior that skips UpdateDecodeTimes if the
duration of the frame pending to be decoded is not positive [1].
Consequently, frames with non-positive duration will not be counted as
decoded frames behind their PTS time.

[1] https://hg.mozilla.org/mozilla-central/rev/05d7a7c92cf24c6b47bf84a693c71a507b312f3c#l7.51

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/419262953752
Skip UpdateDecodeTimes for non-positive-duration frames r=media-playback-reviewers,alwu

Comment 10

[Cristina Horotan [:chorotan]]

https://hg.mozilla.org/mozilla-central/rev/419262953752

Comment 11

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

Set release status flags based on info from the regressing bug 1889978

Comment 12

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

The patch landed in nightly and beta is affected.
:chunmin, is this bug important enough to require an uplift?

• If yes, please nominate the patch for beta approval.
• If no, please set status-firefox129 to wontfix.

For more information, please visit BugBot documentation.

Comment 13

[C.M.Chang[:chunmin]]

This doesn't seem urgent, so uplifting it is unnecessary. If we keep getting the same issue reported, we can reconsider the need to uplift the patch.