1954835 - video-encoder-rescaling.https.any.js fails with ffmpeg + DMABUF

Status: NEW

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

Description

[Andrew Osmond [:aosmond] (he/him)]

Attachment: WebCodecs/FFmpeg/Dmabuf logs

Each of the test cases in https://wpt.live/webcodecs/video-encoder-rescaling.https.any.html?h264_annexb fails with:
promise_test: Unhandled rejection with value: object "TypeError: Failed to convert videoframe in the defined format"

Delving into the log, we appear to be decoding just fine and producing a frame:

 0:10.83 INFO: b'[RDD 2146933: MediaPDecoder #1]: D/Dmabuf VideoFrameSurface: VAAPI locking dmabuf surface UID 1 FFMPEG ID 0x18 mAVHWFrameContext 7f8a9d991c00 mHWAVBuffer 7f8a9d991a80'
 0:10.83 INFO: b'[RDD 2146933: MediaPDecoder #1]: D/Dmabuf DMABUFSurfaceImage::DMABUFSurfaceImage (7f8a8fbdd6f0) aSurface 7f8ab9c5ed90 UID 1'
 0:10.83 INFO: b'[RDD 2146933: MediaSupervisor #1]: D/Dmabuf DMABufSurfaceYUV::Serialize() UID 1'
 0:10.83 INFO: b'[RDD 2146933: MediaSupervisor #1]: D/Dmabuf DMABufSurfaceYUV::Serialize() UID 1'
 0:10.83 INFO: b'[Parent 2146794: Compositor]: D/Dmabuf DMABufSurfaceYUV::ImportSurfaceDescriptor() UID 1'
 0:10.83 INFO: b'[Parent 2146794: Compositor]: D/Dmabuf     plane 0 fd 130 size 128 x 128 format 20203852'
 0:10.83 INFO: b'[Parent 2146794: Compositor]: D/Dmabuf     plane 1 fd 134 size 64 x 64 format 38385247'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: V/WebCodecs DecoderAgent #1 (7f8aa40b7a80) decode successfully'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs DecoderAgent #1 (7f8aa40b7a80) state change: Decoding -> Configured'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: V/WebCodecs VideoDecoder 7f8aa41aaa00, DecoderAgent #1 decode #1 (config #1) has been resolved'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: V/WebCodecs VideoDecoder 7f8aa41aaa00, schedule 1 decoded data output for decode #1 (config #1)'

Then we seem to move into flushing which results in a close:

 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs VideoDecoder 7f8aa41aaa00 starts processing flush #1 (config #1)'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs DecoderAgent #1 (7f8aa40b7a80) state change: Configured -> Flushing'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs DecoderAgent #1 (7f8aa40b7a80) is drainng the decoder'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs VideoFrame 7f8aa41bf100 ctor'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs VideoFrame 7f8aa41bf100, start monitoring resource release, watcher 7f8aa40b3c10'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs Outputing decoded data: ts: 0'
 0:10.83 INFO: b'[RDD 2146933: MediaPDecoder #1]: D/FFmpegVideo FFMPEG: FFmpegDataDecoder: draining buffers'
 0:10.83 INFO: b'[RDD 2146933: MediaPDecoder #1]: D/FFmpegVideo FFMPEG:   End of stream.'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs DecoderAgent #1 (7f8aa40b7a80) is dry now'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs DecoderAgent #1 (7f8aa40b7a80) has dried the decoder. Now flushing the decoder'
 0:10.83 INFO: b'[RDD 2146933: MediaPDecoder #2]: D/FFmpegVideo FFMPEG: ProcessFlush()'
 0:10.83 INFO: b'[RDD 2146933: MediaPDecoder #2]: D/FFmpegVideo FFMPEG: FFmpegDataDecoder: flushing buffers'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs DecoderAgent #1 (7f8aa40b7a80) has flushed the decoder'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs DecoderAgent #1 (7f8aa40b7a80) state change: Flushing -> Configured'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs VideoDecoder 7f8aa41aaa00, DecoderAgent #1 flush #1 (config #1) has been resolved'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs VideoDecoder 7f8aa41aaa00 gets no data for flush #1 (config #1)'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs VideoDecoder 7f8aa41aaa00, resolving the promise for flush 1 (unique id)'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs VideoEncoder 7f8aa4174400, Close'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs VideoEncoder::Reset 7f8aa4174400'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs VideoEncoder 7f8aa4174400 destroys EncoderAgent #1 @ 7f8aa40a3d30'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs EncoderAgent #1 (7f8aa40a3d30) shutdown in Configured state'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: V/WebCodecs EncoderAgent #1 (7f8aa40a3d30) state change: Configured -> Unconfigured'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/FFmpegVideo FFMPEG: Shutdown'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs EncoderAgent #1 (7f8aa40a3d30) dtor'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs === Message queue unblocked'

It looks to me like the flush/close causes us to release the DMABuf before the readback comes in (BuildSurfaceDescriptorBuffer) resulting in us failing because the texture backing the GPUVideoImage is gone:

 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs VideoDecoder 7f8aa41aaa00, Close'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs VideoDecoder 7f8aa41aaa00 destroys DecoderAgent #1 @ 7f8aa40b7a80'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs DecoderAgent #1 (7f8aa40b7a80), shutdown in Configured state'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs DecoderAgent #1 (7f8aa40b7a80) state change: Configured -> Unconfigured'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs DecoderAgent #1 (7f8aa40b7a80) dtor'
 0:10.83 INFO: b'[Child 2147052: MediaPEncoder #1]: D/FFmpegVideo FFMPEG: ProcessShutdown'
 0:10.83 INFO: b'[Child 2147052: MediaPEncoder #1]: D/FFmpegVideo FFMPEG: ShutdownInternal'
 0:10.83 INFO: b'[Child 2147052: Main Thread]: D/WebCodecs VideoDecoder 7f8aa41aaa00 now has its message queue unblocked'
 0:10.83 INFO: b'[RDD 2146933: MediaPDecoder #2]: D/Dmabuf ~VideoFrameSurface: deleting dmabuf surface UID 1'
 0:10.83 INFO: b'[RDD 2146933: MediaPDecoder #2]: D/Dmabuf VideoFrameSurface: Releasing dmabuf surface UID 1 FFMPEG ID 0x18 aForFrameRecycle 0 mLib 7f8ab5083690 mAVHWFrameContext 7f8a9d991c00 mHWAVBuffer 7f8a9d991a80'
 0:10.83 INFO: b'[RDD 2146933: MediaSupervisor #1]: D/Dmabuf DMABufSurfaceYUV::BuildSurfaceDescriptorBuffer UID 1'
 0:10.83 INFO: b'[RDD 2146933: MediaPDecoder #2]: D/Dmabuf DMABufSurfaceYUV::ReleaseSurface() UID 1'
 0:10.83 INFO: b'[RDD 2146933: MediaPDecoder #2]: D/Dmabuf DMABufSurfaceYUV::ReleaseTextures() UID 1'
 0:10.83 INFO: b'[RDD 2146933: MediaPDecoder #2]: D/Dmabuf DMABufSurface::ReleaseDMABuf() UID 1'
 0:10.83 INFO: b'[RDD 2146933: MediaPDecoder #2]: D/FFmpegVideo FFMPEG: FFmpegDataDecoder: shutdown'
 0:10.84 INFO: b'[RDD 2146933: MediaSupervisor #1]: D/Dmabuf DMABufSurface::ReadIntoBuffer UID 1'
 0:10.84 INFO: b'[Child 2147052: Main Thread]: E/WebCodecs VideoFrame 7f8aa41bf100, failed to convert image into RGBX format: NS_ERROR_FAILURE (0x80004005) - Failed to convert into RGBX image'

Comment 1

[Andrew Osmond [:aosmond] (he/him)]

If you prefer the OpenH264 decoder, while using the ffmpeg encoder path, it works. Just flip media.gmp.decoder.preferred to true and restart. If you have the patch from bug 1953601, enable/prefer the OpenH264 encoder as well by flipping media.gmp.encoder.preferred and media.gmp.encoder.enabled to true and restart, it also works. It breaks with the OpenH264 encoder and ffmpeg decoder. So it just seems to be an issue with the ffmpeg decoder path.

Comment 2

[C.M.Chang[:chunmin]]

Ideally, each VideoFrame should function independently once it's produced rather than depend on the VideoDecoder. If the DMABuf isn't ready, we should consider deferring any decoder flush, close, or shut down operations until it becomes available.

:stransky, do you have any suggestions on how we could accomplish this?

Comment 3

[Martin Stránský [:stransky] (ni? me)]

Can you try to set media.ffmpeg.vaapi.force-surface-zero-copy to 0, restart and try again?

DMABufSurface itself may survive VideoFrameSurface::~VideoFrameSurface(), we're releasing ffmpeg references only (as ffmpeg instance is deleted) but surface itself is valid until any its fd is opened.