Opened 3 years ago
Last modified 7 months ago
#9599 open defect
VideoToolbox VP9 hwaccel freezes ffmpeg
Reported by: | Eric Karnes | Owned by: | ePirat |
---|---|---|---|
Priority: | normal | Component: | avcodec |
Version: | git-master | Keywords: | videotoolbox vp9 |
Cc: | Eric Karnes, ePirat | Blocked By: | |
Blocking: | Reproduced by developer: | yes | |
Analyzed by developer: | yes |
Description (last modified by )
Summary of the bug:
When testing the new videotoolbox VP9 decoder support I ran into an issue on my machine where ffmpeg freezes.
ffmpeg doesn't respond to [q] or ? however I'm able to hard exit.
I'm using a 2017 iMac, imac18,3.
The input is a VP9 YouTube video, I've observed this issue with every VP9 YouTube video I've tried.
How to reproduce:
% ffmpeg -v 9 -loglevel 99 -hwaccel videotoolbox -threads 1 -i /Users/eric/Downloads/test.webm -f null - -benchmark -report ffmpeg version N-105288-g45e45a6060 built on 01/15/2022
Here is my output
ffmpeg started on 2022-01-15 at 15:34:58 Report written to "ffmpeg-20220115-153458.log" Log level: 99 Command line: ./ffmpeg -v 9 -loglevel 99 -hwaccel videotoolbox -threads 1 -i /Users/eric/Downloads/test.webm -f null - -benchmark -report ffmpeg version N-105288-g45e45a6060 Copyright (c) 2000-2022 the FFmpeg developers built with Apple clang version 13.0.0 (clang-1300.0.29.30) configuration: --enable-gpl --enable-libaom --enable-libdav1d --enable-libmp3lame --enable-libopus --enable-libsnappy --enable-libtheora --enable-libvmaf --enable-libvorbis --enable-libvpx --enable-libx264 --enable-libx265 --enable-libfontconfig --enable-libfreetype --enable-frei0r --enable-libass --enable-demuxer=dash --enable-opencl --enable-videotoolbox --disable-htmlpages --enable-libfdk-aac --enable-librav1e --enable-librubberband --enable-libspeex --enable-libwebp --enable-nonfree libavutil 57. 18.100 / 57. 18.100 libavcodec 59. 20.100 / 59. 20.100 libavformat 59. 17.101 / 59. 17.101 libavdevice 59. 5.100 / 59. 5.100 libavfilter 8. 25.100 / 8. 25.100 libswscale 6. 5.100 / 6. 5.100 libswresample 4. 4.100 / 4. 4.100 libpostproc 56. 4.100 / 56. 4.100 Splitting the commandline. Reading option '-v' ... matched as option 'v' (set logging level) with argument '9'. Reading option '-loglevel' ... matched as option 'loglevel' (set logging level) with argument '99'. Reading option '-hwaccel' ... matched as option 'hwaccel' (use HW accelerated decoding) with argument 'videotoolbox'. Reading option '-threads' ... matched as AVOption 'threads' with argument '1'. Reading option '-i' ... matched as input url with argument '/Users/eric/Downloads/test.webm'. Reading option '-f' ... matched as option 'f' (force format) with argument 'null'. Reading option '-' ... matched as output url. Reading option '-benchmark' ... matched as option 'benchmark' (add timings for benchmarking) with argument '1'. Reading option '-report' ... matched as option 'report' (generate a report) with argument '1'. Finished splitting the commandline. Parsing a group of options: global . Applying option v (set logging level) with argument 9. Applying option loglevel (set logging level) with argument 99. Applying option benchmark (add timings for benchmarking) with argument 1. Applying option report (generate a report) with argument 1. Successfully parsed a group of options. Parsing a group of options: input url /Users/eric/Downloads/test.webm. Applying option hwaccel (use HW accelerated decoding) with argument videotoolbox. Successfully parsed a group of options. Opening an input file: /Users/eric/Downloads/test.webm. [NULL @ 0x7faf14704100] Opening '/Users/eric/Downloads/test.webm' for reading [file @ 0x7faf247046c0] Setting default whitelist 'file,crypto,data' Probing matroska,webm score:100 size:2048 [matroska,webm @ 0x7faf14704100] Format matroska,webm probed with size=2048 and score=100 st:0 removing common factor 1000000 from timebase st:1 removing common factor 1000000 from timebase [matroska,webm @ 0x7faf14704100] Before avformat_find_stream_info() pos: 636 bytes read:32768 seeks:0 nb_streams:2 [vp9 @ 0x7faf24705580] Format yuv420p chosen by get_format(). [opus @ 0x7faf24705e80] skip 312/960 samples [matroska,webm @ 0x7faf14704100] All info found [matroska,webm @ 0x7faf14704100] stream 0: start_time: 0 duration: NOPTS [matroska,webm @ 0x7faf14704100] stream 1: start_time: -0.007 duration: NOPTS [matroska,webm @ 0x7faf14704100] format: start_time: -0.007 duration: 15.021 (estimate from stream) bitrate=1336 kb/s [matroska,webm @ 0x7faf14704100] After avformat_find_stream_info() pos: 1483 bytes read:32768 seeks:0 frames:2 Input #0, matroska,webm, from '/Users/eric/Downloads/test.webm': Metadata: ENCODER : Lavf58.76.100 Duration: 00:00:15.02, start: -0.007000, bitrate: 1336 kb/s Stream #0:0(eng), 1, 1/1000: Video: vp9 (Profile 0), 1 reference frame, yuv420p(tv, bt709), 720x1280, 0/1, SAR 1:1 DAR 9:16, 30 fps, 30 tbr, 1k tbn (default) Metadata: DURATION : 00:00:14.999000000 Stream #0:1(eng), 1, 1/1000: Audio: opus, 48000 Hz, stereo, fltp, delay 312 (default) Metadata: DURATION : 00:00:15.021000000 Successfully opened the file. Parsing a group of options: output url -. Applying option f (force format) with argument null. Successfully parsed a group of options. Opening an output file: -. Successfully opened the file. Stream mapping: Stream #0:0 -> #0:0 (vp9 (native) -> wrapped_avframe (native)) Stream #0:1 -> #0:1 (opus (native) -> pcm_s16le (native)) Press [q] to stop, [?] for help cur_dts is invalid st:0 (0) [init:0 i_done:0 finish:0] (this is harmless if it occurs once at the start per stream) [vp9 @ 0x7faf04704100] Format videotoolbox_vld chosen by get_format(). [vp9 @ 0x7faf04704100] Format videotoolbox_vld requires hwaccel initialisation. detected 8 logical cores [graph 0 input from stream 0:0 @ 0x7faf24723e40] Setting 'video_size' to value '720x1280' [graph 0 input from stream 0:0 @ 0x7faf24723e40] Setting 'pix_fmt' to value '23' [graph 0 input from stream 0:0 @ 0x7faf24723e40] Setting 'time_base' to value '1/1000' [graph 0 input from stream 0:0 @ 0x7faf24723e40] Setting 'pixel_aspect' to value '1/1' [graph 0 input from stream 0:0 @ 0x7faf24723e40] Setting 'frame_rate' to value '30/1' [graph 0 input from stream 0:0 @ 0x7faf24723e40] w:720 h:1280 pixfmt:nv12 tb:1/1000 fr:30/1 sar:1/1 [AVFilterGraph @ 0x7faf247198c0] query_formats: 3 queried, 2 merged, 0 already done, 0 delayed cur_dts is invalid st:0 (0) [init:1 i_done:0 finish:0] (this is harmless if it occurs once at the start per stream) cur_dts is invalid st:1 (0) [init:0 i_done:0 finish:0] (this is harmless if it occurs once at the start per stream) [opus @ 0x7faf04704980] skip 312/960 samples [graph_1_in_0_1 @ 0x7faf247258c0] Setting 'time_base' to value '1/48000' [graph_1_in_0_1 @ 0x7faf247258c0] Setting 'sample_rate' to value '48000' [graph_1_in_0_1 @ 0x7faf247258c0] Setting 'sample_fmt' to value 'fltp' [graph_1_in_0_1 @ 0x7faf247258c0] Setting 'channel_layout' to value '0x3' [graph_1_in_0_1 @ 0x7faf247258c0] tb:1/48000 samplefmt:fltp samplerate:48000 chlayout:0x3 [format_out_0_1 @ 0x7faf24725e80] Setting 'sample_fmts' to value 's16' [format_out_0_1 @ 0x7faf24725e80] auto-inserting filter 'auto_aresample_0' between the filter 'Parsed_anull_0' and the filter 'format_out_0_1' [AVFilterGraph @ 0x7faf247253c0] query_formats: 4 queried, 6 merged, 3 already done, 0 delayed [auto_aresample_0 @ 0x7faf24726540] [SWR @ 0x7faef8050000] Using fltp internally between filters [auto_aresample_0 @ 0x7faf24726540] ch:2 chl:stereo fmt:fltp r:48000Hz -> ch:2 chl:stereo fmt:s16 r:48000Hz Output #0, null, to 'pipe:': Metadata: encoder : Lavf59.17.101 Stream #0:0(eng), 0, 1/30: Video: wrapped_avframe, 1 reference frame, nv12(tv, bt709, progressive), 720x1280 (0x0) [SAR 1:1 DAR 9:16], 0/1, q=2-31, 200 kb/s, 30 fps, 30 tbn (default) Metadata: DURATION : 00:00:14.999000000 encoder : Lavc59.20.100 wrapped_avframe Stream #0:1(eng), 0, 1/48000: Audio: pcm_s16le, 48000 Hz, stereo, s16, 1536 kb/s (default) Metadata: DURATION : 00:00:15.021000000 encoder : Lavc59.20.100 pcm_s16le frame= 1 fps=0.0 q=-0.0 size=N/A time=00:00:00.03 bitrate=N/A speed=0.383x
Attachments (2)
Change History (30)
comment:1 by , 3 years ago
Description: | modified (diff) |
---|
follow-up: 3 comment:2 by , 3 years ago
comment:3 by , 3 years ago
Replying to Peter Xia:
I'm able to reproduce this. It's working on my apple silicon mac but freezing on my intel one.
What model Mac are you able to reproduce this with? I'm trying to figure out if this is an issue with all Intel Macs with VP9 decode support or specifically ones that use the Intel iGPU for VP9 decode.
follow-up: 11 comment:6 by , 19 months ago
I've since updated to FFMPEG 6.0 and am using Ventura 13.4 and the bug is still present however I'm given more information in the logs
[vp9 @ 0x7f84cf704080] Format videotoolbox_vld chosen by get_format(). [vp9 @ 0x7f84cf704080] Format videotoolbox_vld requires hwaccel initialisation. [vp9 @ 0x7f84cf704080] Unknown VideoToolbox session creation error -12907 [vp9 @ 0x7f84cf704080] Failed setup for format videotoolbox_vld: hwaccel initialisation returned error. [vp9 @ 0x7f84cf704080] Format videotoolbox_vld not usable, retrying get_format() without it. [vp9 @ 0x7f84cf704080] Format yuv420p chosen by get_format().
error -12907 seems to correlate to "kVTCouldNotCreateInstanceErr" while my Mac's console gives the error
[VP9] GVA error: ailed to create context
comment:8 by , 19 months ago
Replying to Balling:
ailed?
I would assume it's meant to be failed but that's the message it always gives.
follow-up: 10 comment:9 by , 19 months ago
but that's the message it always gives.
So that is some typo in MacOS system libraries or driver?
comment:10 by , 19 months ago
Replying to Balling:
but that's the message it always gives.
So that is some typo in MacOS system libraries or driver?
It would seem so yes.
follow-up: 13 comment:11 by , 19 months ago
Replying to Eric Karnes:
I've since updated to FFMPEG 6.0 and am using Ventura 13.4 and the bug is still present however I'm given more information in the logs
[vp9 @ 0x7f84cf704080] Format videotoolbox_vld chosen by get_format(). [vp9 @ 0x7f84cf704080] Format videotoolbox_vld requires hwaccel initialisation. [vp9 @ 0x7f84cf704080] Unknown VideoToolbox session creation error -12907 [vp9 @ 0x7f84cf704080] Failed setup for format videotoolbox_vld: hwaccel initialisation returned error. [vp9 @ 0x7f84cf704080] Format videotoolbox_vld not usable, retrying get_format() without it. [vp9 @ 0x7f84cf704080] Format yuv420p chosen by get_format().error -12907 seems to correlate to "kVTCouldNotCreateInstanceErr" while my Mac's console gives the error
[VP9] GVA error: ailed to create context
The hardware or OS doesn't support VP9 decoding. FFmpeg should be able to switch to software decoding.
Please reopen the ticket if there is other issue with FFmpeg master branch.
comment:12 by , 19 months ago
Resolution: | → needs_more_info |
---|---|
Status: | new → closed |
comment:13 by , 19 months ago
Replying to quinkblack:
Replying to Eric Karnes:
I've since updated to FFMPEG 6.0 and am using Ventura 13.4 and the bug is still present however I'm given more information in the logs
[vp9 @ 0x7f84cf704080] Format videotoolbox_vld chosen by get_format(). [vp9 @ 0x7f84cf704080] Format videotoolbox_vld requires hwaccel initialisation. [vp9 @ 0x7f84cf704080] Unknown VideoToolbox session creation error -12907 [vp9 @ 0x7f84cf704080] Failed setup for format videotoolbox_vld: hwaccel initialisation returned error. [vp9 @ 0x7f84cf704080] Format videotoolbox_vld not usable, retrying get_format() without it. [vp9 @ 0x7f84cf704080] Format yuv420p chosen by get_format().error -12907 seems to correlate to "kVTCouldNotCreateInstanceErr" while my Mac's console gives the error
[VP9] GVA error: ailed to create contextThe hardware or OS doesn't support VP9 decoding. FFmpeg should be able to switch to software decoding.
Please reopen the ticket if there is other issue with FFmpeg master branch.
Thanks for the clarification, it seems that when I have my eGPU plugged in it takes over for decoding and that doesn't actually support VP9 so that explains why my logs were different. If I unplug my eGPU so that only my iGPU which supports VP9 is used, then it goes back to minimal logs and freezing. I've verified this on the master branch.
comment:14 by , 19 months ago
Resolution: | needs_more_info |
---|---|
Status: | closed → reopened |
comment:15 by , 17 months ago
I've gone through and enabled some trace output for CoreMedia which gives me the following logs while reproducing this issue.
<<<< VT-DS >>>> vtDecompressionDuctCreate: decoder requested VideoToolbox handle QualityOfService <<<< VT-DS >>>> vtDecompressionDuctCreate: DecoderType: Hardware <<<< MemoryPool >>>> CMMemoryPoolCreate: pool 0x60000083a840 created vending allocator 0x600003328680 <<<< PixelBufferSharing >>>> pixelBufferRecipient_createRecipientPixelBuffer: created pixel buffer from components. Saved backing 0x7fd2b180b200 (ID 548) <<<< VT-DS >>>> VTDecompressionSessionWaitForAsynchronousFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionFinishDelayedFrames: [session: 0x600003927660] <<<< PixelBufferSharing >>>> pixelBufferRecipient_createRecipientPixelBuffer: created pixel buffer from components. Saved backing 0x7fd2e001a800 (ID 552) <<<< VT-DS >>>> VTDecompressionSessionWaitForAsynchronousFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionFinishDelayedFrames: [session: 0x600003927660] <<<< PixelBufferSharing >>>> pixelBufferRecipient_createRecipientPixelBuffer: created pixel buffer from components. Saved backing 0x7fd2e801f400 (ID 554) <<<< VT-DS >>>> VTDecompressionSessionWaitForAsynchronousFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionFinishDelayedFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionWaitForAsynchronousFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionFinishDelayedFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionWaitForAsynchronousFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionFinishDelayedFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionWaitForAsynchronousFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionFinishDelayedFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionWaitForAsynchronousFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionFinishDelayedFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionWaitForAsynchronousFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionFinishDelayedFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionWaitForAsynchronousFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionFinishDelayedFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionWaitForAsynchronousFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionFinishDelayedFrames: [session: 0x600003927660] <<<< RemoteDecode - client >>>> RemoteVideoDecoder_DecodeFrame: 1 frames still pending after synchronous decode <<<< VT-DS >>>> vtDecompressionDuctDecodeSingleFrame: (0x600003927660) frame 0xb still pending after synchronous immediate DecodeFrame call <<<< VT-DS >>>> VTDecompressionSessionWaitForAsynchronousFrames: [session: 0x600003927660] <<<< VT-DS >>>> VTDecompressionSessionFinishDelayedFrames: [session: 0x600003927660]
I would assume the most important bits would be,
<<<< RemoteDecode - client >>>> RemoteVideoDecoder_DecodeFrame: 1 frames still pending after synchronous decode <<<< VT-DS >>>> vtDecompressionDuctDecodeSingleFrame: (0x600003927660) frame 0xb still pending after synchronous immediate DecodeFrame call
considering they show up as errors in the console.
by , 17 months ago
Attachment: | process-sample.txt added |
---|
Output of 'sample' from the frozen ffmpeg process
comment:16 by , 17 months ago
I've reverified that the master branch is affected by this issue and attached the output from sample for the frozen ffmpeg process.
comment:17 by , 16 months ago
I've grabbed a backtrace of the freeze using lldb
(lldb) thread info -s thread #1: tid = 0x5c4f8, 0x00007ff81a0d08ec libsystem_pthread.dylib`_pthread_cond_updateval + 1, queue = 'com.apple.main-thread', stop reason = instruction step into (lldb) thread list Process 40009 stopped * thread #1: tid = 0x5c4f8, 0x00007ff81a0d08ec libsystem_pthread.dylib`_pthread_cond_updateval + 1, queue = 'com.apple.main-thread', stop reason = instruction step into thread #2: tid = 0x5c4fc, 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 thread #3: tid = 0x5c4fd, 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 thread #4: tid = 0x5c4ff, 0x00007ff81a095162 libsystem_kernel.dylib`__workq_kernreturn + 10 thread #5: tid = 0x5c50a, 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 thread #6: tid = 0x5c50b, 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 thread #7: tid = 0x5c50c, 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 thread #8: tid = 0x5c50d, 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 thread #9: tid = 0x5c50e, 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 thread #10: tid = 0x5c50f, 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 thread #11: tid = 0x5c510, 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 thread #12: tid = 0x5c511, 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 thread #13: tid = 0x5c512, 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 (lldb) bt all * thread #1, queue = 'com.apple.main-thread', stop reason = instruction step into * frame #0: 0x00007ff81a0d08ec libsystem_pthread.dylib`_pthread_cond_updateval + 1 frame #1: 0x00007ff81a0d37df libsystem_pthread.dylib`_pthread_cond_wait + 1327 frame #2: 0x000000010aef9f6b ffmpeg_g`tq_receive(tq=0x0000611000003b00, stream_idx=0x00007ff7b50c96e0, data=0x0000616000005180) at thread_queue.c:202:13 frame #3: 0x000000010ae39078 ffmpeg_g`dec_packet(ist=0x0000614000000440, pkt=0x0000610000010340, no_eof=0) at ffmpeg_dec.c:791:15 frame #4: 0x000000010af1a86a ffmpeg_g`process_input_packet(ist=0x0000614000000440, pkt=0x0000610000010340, no_eof=0) at ffmpeg.c:820:15 frame #5: 0x000000010af1c0ad ffmpeg_g`process_input(file_index=0) at ffmpeg.c:1144:11 frame #6: 0x000000010af18ac3 ffmpeg_g`transcode_step(ost=0x0000617000000780) at ffmpeg.c:1171:11 frame #7: 0x000000010af154a2 ffmpeg_g`transcode(err_rate_exceeded=0x00007ff7b50ca0c0) at ffmpeg.c:1232:15 frame #8: 0x000000010af14d9a ffmpeg_g`main(argc=15, argv=0x00007ff7b50ca4e0) at ffmpeg.c:1358:11 frame #9: 0x00007ff819d4a3a6 dyld`start + 1942 thread #2 frame #0: 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 frame #1: 0x00007ff81a0d376b libsystem_pthread.dylib`_pthread_cond_wait + 1211 frame #2: 0x00007ff8247741c1 CoreMedia`WaitOnConditionTimed + 82 frame #3: 0x00007ff82475620d CoreMedia`FigSemaphoreWaitRelative + 161 frame #4: 0x00007ff8291c9701 VideoToolbox`VTDecompressionSessionWaitForAsynchronousFrames + 708 frame #5: 0x000000010ea63577 ffmpeg_g`videotoolbox_session_decode_frame(avctx=0x0000619000026780) at videotoolbox.c:729:18 frame #6: 0x000000010ea61d0c ffmpeg_g`ff_videotoolbox_common_end_frame(avctx=0x0000619000026780, frame=0x0000616000005780) at videotoolbox.c:1021:14 frame #7: 0x000000010ea6af13 ffmpeg_g`videotoolbox_vp9_end_frame(avctx=0x0000619000026780) at videotoolbox_vp9.c:125:12 frame #8: 0x000000010ed05998 ffmpeg_g`vp9_decode_frame(avctx=0x0000619000026780, frame=0x0000616000005480, got_frame=0x0000700001f5d360, pkt=0x0000610000002a40) at vp9.c:1648:15 frame #9: 0x000000010d02eb34 ffmpeg_g`decode_simple_internal(avctx=0x0000619000026780, frame=0x0000616000005480, discarded_samples=0x0000700001f5d3e0) at decode.c:431:20 frame #10: 0x000000010d02e00b ffmpeg_g`decode_simple_receive_frame(avctx=0x0000619000026780, frame=0x0000616000005480) at decode.c:605:15 frame #11: 0x000000010d01ab09 ffmpeg_g`decode_receive_frame_internal(avctx=0x0000619000026780, frame=0x0000616000005480) at decode.c:633:15 frame #12: 0x000000010d01a552 ffmpeg_g`avcodec_send_packet(avctx=0x0000619000026780, avpkt=0x0000610000008040) at decode.c:730:15 frame #13: 0x000000010ae3ed84 ffmpeg_g`packet_decode(ist=0x0000614000000440, pkt=0x0000610000008040, frame=0x000061600000ff80) at ffmpeg_dec.c:555:11 frame #14: 0x000000010ae3db3b ffmpeg_g`decoder_thread(arg=0x0000614000000440) at ffmpeg_dec.c:702:15 frame #15: 0x00007ff81a0d3202 libsystem_pthread.dylib`_pthread_start + 99 frame #16: 0x00007ff81a0cebab libsystem_pthread.dylib`thread_start + 15 thread #3 frame #0: 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 frame #1: 0x00007ff81a0d376b libsystem_pthread.dylib`_pthread_cond_wait + 1211 frame #2: 0x000000010fa744f8 ffmpeg_g`av_thread_message_queue_send_locked(mq=0x0000611000003c40, msg=0x0000700001fe0c80, flags=0) at threadmessage.c:129:9 frame #3: 0x000000010fa743e0 ffmpeg_g`av_thread_message_queue_send(mq=0x0000611000003c40, msg=0x0000700001fe0c80, flags=0) at threadmessage.c:166:11 frame #4: 0x000000010ae5b473 ffmpeg_g`input_thread(arg=0x0000612000000640) at ffmpeg_demux.c:650:15 frame #5: 0x00007ff81a0d3202 libsystem_pthread.dylib`_pthread_start + 99 frame #6: 0x00007ff81a0cebab libsystem_pthread.dylib`thread_start + 15 thread #4 frame #0: 0x00007ff81a095162 libsystem_kernel.dylib`__workq_kernreturn + 10 frame #1: 0x00007ff81a0cfca0 libsystem_pthread.dylib`_pthread_wqthread + 416 frame #2: 0x00007ff81a0ceb97 libsystem_pthread.dylib`start_wqthread + 15 thread #5 frame #0: 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 frame #1: 0x00007ff81a0d376b libsystem_pthread.dylib`_pthread_cond_wait + 1211 frame #2: 0x000000010fa716a3 ffmpeg_g`thread_worker(v=0x0000619000028a80) at slicethread.c:82:13 frame #3: 0x00007ff81a0d3202 libsystem_pthread.dylib`_pthread_start + 99 frame #4: 0x00007ff81a0cebab libsystem_pthread.dylib`thread_start + 15 thread #6 frame #0: 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 frame #1: 0x00007ff81a0d376b libsystem_pthread.dylib`_pthread_cond_wait + 1211 frame #2: 0x000000010fa716a3 ffmpeg_g`thread_worker(v=0x0000619000028b08) at slicethread.c:82:13 frame #3: 0x00007ff81a0d3202 libsystem_pthread.dylib`_pthread_start + 99 frame #4: 0x00007ff81a0cebab libsystem_pthread.dylib`thread_start + 15 thread #7 frame #0: 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 frame #1: 0x00007ff81a0d376b libsystem_pthread.dylib`_pthread_cond_wait + 1211 frame #2: 0x000000010fa716a3 ffmpeg_g`thread_worker(v=0x0000619000028b90) at slicethread.c:82:13 frame #3: 0x00007ff81a0d3202 libsystem_pthread.dylib`_pthread_start + 99 frame #4: 0x00007ff81a0cebab libsystem_pthread.dylib`thread_start + 15 thread #8 frame #0: 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 frame #1: 0x00007ff81a0d376b libsystem_pthread.dylib`_pthread_cond_wait + 1211 frame #2: 0x000000010fa716a3 ffmpeg_g`thread_worker(v=0x0000619000028c18) at slicethread.c:82:13 frame #3: 0x00007ff81a0d3202 libsystem_pthread.dylib`_pthread_start + 99 frame #4: 0x00007ff81a0cebab libsystem_pthread.dylib`thread_start + 15 thread #9 frame #0: 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 frame #1: 0x00007ff81a0d376b libsystem_pthread.dylib`_pthread_cond_wait + 1211 frame #2: 0x000000010fa716a3 ffmpeg_g`thread_worker(v=0x0000619000028ca0) at slicethread.c:82:13 frame #3: 0x00007ff81a0d3202 libsystem_pthread.dylib`_pthread_start + 99 frame #4: 0x00007ff81a0cebab libsystem_pthread.dylib`thread_start + 15 thread #10 frame #0: 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 frame #1: 0x00007ff81a0d376b libsystem_pthread.dylib`_pthread_cond_wait + 1211 frame #2: 0x000000010fa716a3 ffmpeg_g`thread_worker(v=0x0000619000028d28) at slicethread.c:82:13 frame #3: 0x00007ff81a0d3202 libsystem_pthread.dylib`_pthread_start + 99 frame #4: 0x00007ff81a0cebab libsystem_pthread.dylib`thread_start + 15 thread #11 frame #0: 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 frame #1: 0x00007ff81a0d376b libsystem_pthread.dylib`_pthread_cond_wait + 1211 frame #2: 0x000000010fa716a3 ffmpeg_g`thread_worker(v=0x0000619000028db0) at slicethread.c:82:13 frame #3: 0x00007ff81a0d3202 libsystem_pthread.dylib`_pthread_start + 99 frame #4: 0x00007ff81a0cebab libsystem_pthread.dylib`thread_start + 15 thread #12 frame #0: 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 frame #1: 0x00007ff81a0d376b libsystem_pthread.dylib`_pthread_cond_wait + 1211 frame #2: 0x000000010fa716a3 ffmpeg_g`thread_worker(v=0x0000619000028e38) at slicethread.c:82:13 frame #3: 0x00007ff81a0d3202 libsystem_pthread.dylib`_pthread_start + 99 frame #4: 0x00007ff81a0cebab libsystem_pthread.dylib`thread_start + 15 thread #13 frame #0: 0x00007ff81a0965e6 libsystem_kernel.dylib`__psynch_cvwait + 10 frame #1: 0x00007ff81a0d376b libsystem_pthread.dylib`_pthread_cond_wait + 1211 frame #2: 0x000000010aef9f6b ffmpeg_g`tq_receive(tq=0x00006110000043c0, stream_idx=0x0000700002687e40, data=0x0000610000030040) at thread_queue.c:202:13 frame #3: 0x000000010aea3d62 ffmpeg_g`muxer_thread(arg=0x0000611000002fc0) at ffmpeg_mux.c:215:15 frame #4: 0x00007ff81a0d3202 libsystem_pthread.dylib`_pthread_start + 99 frame #5: 0x00007ff81a0cebab libsystem_pthread.dylib`thread_start + 15
comment:18 by , 16 months ago
Note that there are two problems here, the failure to decode the frame and the severe problem with permanently blocking the thread, preventing a fallback to software decoding.
Does FFmpeg have any Apple contacts? I've investigated this a bit and I'm not seeing a good way for FFmpeg to workaround Apple's bad error handling. See below for more details.
This problem is important as the mpv project added VP9 to the default value of its white-list of codecs that are considered safe to use with hardware decoding: hwdec-codecs
The IINA project was tripped up by this after upgrading mpv and FFmpeg and had to quickly issue a new release with a workaround to disable VP9 hardware decode on Intel Macs. See IINA issue #4486.
The open VLC issue 27874 references this FFmpeg ticket. That issue also references the closed Chromium issue 1115334. The Chromium issue contains this interesting post (from 2020):
After discussion with Apple this is due to the fact that they require VP9 alt-ref frames to be packaged as superframes. I've written some code to do this. On their side, they expect to make it an error when alt-ref frames are sent unpacked.
As that was back in 2020 the error handling must have been updated by now, right Apple? And if Video Toolbox has this restriction why in the case at hand is hardware decoding working under Apple Silicon? My development machine is a MacBookPro18,2 with a M1 Max processor under macOS 13.5 and the problem does not reproduce on that Mac.
In order to investigate this I purchased a reconditioned MacBookPro16,1 with a 6-Core Intel Core i7 processor. On that Mac using the file buck-1280x720-vp9.webm from the above mentioned Chromium issue FFmpeg hangs:
low-batt@urp ffmpeg (master *%=)$ ffmpeg -hide_banner -hwaccel videotoolbox -i buck-1280x720-vp9.webm -f null - Input #0, matroska,webm, from 'buck-1280x720-vp9.webm': Metadata: encoder : libwebm-0.2.1.0 Duration: 00:00:00.17, start: 0.000000, bitrate: 856 kb/s Stream #0:0(eng): Video: vp9 (Profile 0), yuv420p(tv), 1280x720, SAR 1:1 DAR 16:9, 29.92 fps, 29.92 tbr, 1k tbn (default) Stream mapping: Stream #0:0 -> #0:0 (vp9 (native) -> wrapped_avframe (native)) Press [q] to stop, [?] for help ^C^C^CReceived > 3 system signals, hard exiting
FFmpeg is hanging in the method videotoolbox_session_decode_frame
at the call to VTDecompressionSessionWaitForAsynchronousFrames in this code:
status = VTDecompressionSessionDecodeFrame(videotoolbox->session, sample_buf, 0, // decodeFlags NULL, // sourceFrameRefCon 0); // infoFlagsOut if (status == noErr) status = VTDecompressionSessionWaitForAsynchronousFrames(videotoolbox->session);
This code seems odd to me because the Apple documentation for VTDecompressionSessionDecodeFrame(\_:sampleBuffer:flags:frameRefcon:infoFlagsOut:) says:
decodeFlags
A bitfield of directives to the decompression session and decoder.
The kVTDecodeFrame_EnableAsynchronousDecompression bit indicates whether the video decoder may decompress the frame asynchronously.
The kVTDecodeFrame_EnableTemporalProcessing bit indicates whether the decoder may delay calls to the output callback so as to enable processing in temporal (display) order.
If both flags are clear, the decompression completes and your output callback function will be called before VTDecompressionSessionDecodeFrame returns.
For the decodeFlags
parameter the above code passes 0, requesting synchronous processing. Given that, why is FFmpeg calling VTDecompressionSessionWaitForAsynchronousFrames
?
A quick test on my M1 Mac with that call commented out it seemed like decoding worked. On the Intel Mac FFmpeg quickly froze in videotoolbox_stop
on the call to VTDecompressionSessionInvalidate:
+ 2348 ff_videotoolbox_common_end_frame (in ffmpeg) + 191 [0x10128255f] + 2348 VTDecompressionSessionInvalidate (in VideoToolbox) + 83 [0x7ff815d41a79] + 2347 ??? (in VideoToolbox) load address 0x7ff815d38000 + 0x28c356 [0x7ff815fc4356] + ! 2347 FigSemaphoreWaitRelative (in CoreMedia) + 152 [0x7ff8110fb066] + ! 2347 WaitOnConditionTimed (in CoreMedia) + 78 [0x7ff81110e3ff] + ! 2347 _pthread_cond_wait (in libsystem_pthread.dylib) + 1242 [0x7ff80783d758] + ! 2347 __psynch_cvwait (in libsystem_kernel.dylib) + 10 [0x7ff8078010fe]
With the call to VTDecompressionSessionInvalidate
commented out, FFmpeg froze on the following call to CFRelease which itself called VTDecompressionSessionInvalidate
.
Adding some print statements shows the first frame is decoded successfully. But the second call to VTDecompressionSessionDecodeFrame
returns without calling videotoolbox_decoder_callback
. Based on that behavior it seems there was a failure trying to decode the second frame and yet VTDecompressionSessionDecodeFrame
returned a successful OSStatus
. It also seems it did so without having signaled the internal semaphore that indicates VTDecompressionSessionDecodeFrame
is in progress.
If FFmpeg wanted to continue to use VTDecompressionSessionWaitForAsynchronousFrames
it could detect that no frame was generated and assume VTDecompressionSessionDecodeFrame
failed even though it returned success. But with the method VTDecompressionSessionInvalidate
also hanging I don't see how FFmpeg can workaround the mismanagement of the semaphore by Video Toolbox
.
Hopefully somebody has a contact at Apple that can explain why the error handing in VTDecompressionSessionDecodeFrame
is so badly broken and why decoding is working fine under Apple Silicon.
This is what the output of that test looked like:
low-batt@urp ffmpeg (master *%=)$ ./ffmpeg -hide_banner -hwaccel videotoolbox -i buck-1280x720-vp9.webm -f null - Input #0, matroska,webm, from 'buck-1280x720-vp9.webm': Metadata: encoder : libwebm-0.2.1.0 Duration: 00:00:00.17, start: 0.000000, bitrate: 856 kb/s Stream #0:0(eng): Video: vp9 (Profile 0), yuv420p(tv), 1280x720, SAR 1:1 DAR 16:9, 29.92 fps, 29.92 tbr, 1k tbn (default) Stream mapping: Stream #0:0 -> #0:0 (vp9 (native) -> wrapped_avframe (native)) Press [q] to stop, [?] for help Calling VTDecompressionSessionDecodeFrame In videotoolbox_decoder_callback OSStatus is: 0 Returned from VTDecompressionSessionDecodeFrame OSStatus is: 0 Calling VTDecompressionSessionWaitForAsynchronousFrames Calling VTDecompressionSessionDecodeFrame Returned from VTDecompressionSessionDecodeFrame OSStatus is: 0 Calling VTDecompressionSessionWaitForAsynchronousFrames
follow-up: 20 comment:19 by , 16 months ago
The osu-framework is another project that is affected by this, and is waiting for a fix or workaround before upgrading its ffmpeg libraries.
Thanks to low-batts extensive information, I have an idea on a possible workaround on the consumer end. Looking at the chromium issue, this is how they fixed the issue:
This assembles superframes from vp9 alt ref frames since that's what the macOS VP9 decoder is expecting.
More specifically, they use a bitstream filter (BSF) to modify the encoded bitstream before sending it to the HW decoder. I noticed that the ffmpeg libraries also include a bitstream filter called vp9_superframe that seems to do the exact same thing, though I haven't looked at the implementation to confirm this.
I do not have any Apple hardware, so I cannot confirm whether this workaround works. But the idea would be to change from this:
ffmpeg -hide_banner -hwaccel videotoolbox -i test.webm -f null -
to this:
ffmpeg -hide_banner -i test.webm -c:v copy -bsf:v vp9_superframe -f webm - | ffmpeg -hide_banner -f webm -hwaccel videotoolbox -i pipe: -f null -
Something like this should also be doable through libavcodec (BSFs, though named "filters", are part of avcodec, not avfilter), but again, I can't try this myself. I'd appreciate if someone could test this, as it would be a relatively simple workaround.
follow-up: 21 comment:20 by , 16 months ago
Replying to FreezyLemon:
The osu-framework is another project that is affected by this, and is waiting for a fix or workaround before upgrading its ffmpeg libraries.
Thanks to low-batts extensive information, I have an idea on a possible workaround on the consumer end. Looking at the chromium issue, this is how they fixed the issue:
This assembles superframes from vp9 alt ref frames since that's what the macOS VP9 decoder is expecting.
More specifically, they use a bitstream filter (BSF) to modify the encoded bitstream before sending it to the HW decoder. I noticed that the ffmpeg libraries also include a bitstream filter called vp9_superframe that seems to do the exact same thing, though I haven't looked at the implementation to confirm this.
I do not have any Apple hardware, so I cannot confirm whether this workaround works. But the idea would be to change from this:
ffmpeg -hide_banner -hwaccel videotoolbox -i test.webm -f null -to this:
ffmpeg -hide_banner -i test.webm -c:v copy -bsf:v vp9_superframe -f webm - | ffmpeg -hide_banner -f webm -hwaccel videotoolbox -i pipe: -f null -Something like this should also be doable through libavcodec (BSFs, though named "filters", are part of avcodec, not avfilter), but again, I can't try this myself. I'd appreciate if someone could test this, as it would be a relatively simple workaround.
I attempted your workaround on master and unfortunately it still locks up the same as it would otherwise.
comment:21 by , 16 months ago
Replying to Eric Karnes:
I attempted your workaround on master and unfortunately it still locks up the same as it would otherwise.
That is unfortunate. I checked the code and discovered that the BSF "vp9_superframe_split" is defined to be run in vp9.c:
.bsfs = "vp9_superframe_split",
This BSF does the opposite/reverse of vp9_superframe, namely splitting superframes into singular frames (this is apparently needed for the software decoder). So the work done by "vp9_superframe" is being undone right before decoding.
Not sure if there's a simple way to disable this for just videotoolbox. Removing this altogether would most likely break other decoders...
comment:22 by , 16 months ago
As a very quick hacky test, this change to vp9.c:
- .bsfs = "vp9_superframe_split", + .bsfs = "vp9_superframe",
Caused FFmpeg to be able to decode the example video from the Chromium bug as well as a longer video that showed the problem.
This is more evidence suggesting:
- Apple never fixed Video Toolbox error handling dispite having said they were going to causing problems for people all over the entire planet
- The Video Toolbox implementation for Apple Silicon does not impose the requirement to package alt-ref frames as superframes
- Apple never updated the Intel Video Toolbox implementation to match the Apple Silicon behavior
Late here and I am incoherent. I should have time to look into this some more tomorrow.
by , 16 months ago
Attachment: | ticket-9599.patch added |
---|
Patch that adds a separate VP9 Video Toolbox decoder.
comment:23 by , 16 months ago
A patch file should be attached. The changes create a separate decoder for VP9 decoding with Video Toolbox. That decoder uses vp9_superframe
instead of vp9_superframe_split
on Intel Macs.
I think this is how to change the BSF filter only when hardware decoding is enabled. What I'm not clear on is how FFmpeg decides not to use this decoder when software decoding. Really need a FFmpeg developer for this.
I built a libavcodec.dylib with these changes and tested it with IINA on my Intel Mac. The longer test video played fine with hardware decoding. This is what the mpv log showed:
[ 22.665][v][vd] Codec list: [ 22.665][v][vd] vp9 - Google VP9 [ 22.665][v][vd] vp9_videotoolbox (vp9) - VideoToolbox Google VP9 [ 22.665][v][vd] Opening decoder vp9 [ 22.665][v][vd] Looking at hwdec vp9_videotoolbox-videotoolbox... [ 22.665][v][vd] Trying hardware decoding via vp9_videotoolbox-videotoolbox. [ 22.665][v][vd] Using underlying hw-decoder 'vp9_videotoolbox' [ 22.665][v][vd] Selected codec: vp9 (Google VP9) … [ 22.786][i][vd] Using hardware decoding (videotoolbox).
I also tested disabling hardware decoding, which also played fine:
[ 3.990][v][vd] Codec list: [ 3.990][v][vd] vp9 - Google VP9 [ 3.990][v][vd] vp9_videotoolbox (vp9) - VideoToolbox Google VP9 [ 3.990][v][vd] Opening decoder vp9 [ 3.990][v][vd] No hardware decoding requested. [ 3.990][v][vd] Using software decoding. [ 3.990][v][vd] Detected 12 logical cores. [ 3.990][v][vd] Requesting 13 threads for decoding. [ 3.991][v][vd] Selected codec: vp9 (Google VP9)
comment:24 by , 16 months ago
Nice. Good to know that this can be worked around. I assume that forcing decoding via vp9_videotoolbox
without hwaccel would result in a crash, or corrupted output? That would make this workaround risky to use... Maybe there's a way to define a codec as "HW accelerated only", meaning it doesn't provide software decoding at all?
comment:25 by , 15 months ago
As I have never dug into FFmpeg sources I have the same questions you raised. I plan on getting back to reading FFmpeg sources and testing to see what else needs to be done to fix this properly soon. I'm juggling a number of tasks at the moment.
comment:26 by , 7 months ago
Cc: | added |
---|
comment:27 by , 7 months ago
Analyzed by developer: | set |
---|---|
Component: | undetermined → avcodec |
Owner: | set to |
Reproduced by developer: | set |
Status: | reopened → open |
Indeed this hang in Videotoolbox can be worked around with the vp9_superframe
bsf, I am currently investigating ways to make this work for VT without breaking the rest…
After some IRC discussion, given that VT expects packets not slices, one option would be to make VT its own codec, but downsides of this would be lack of software fallback and metadata propagation, which right now is parsed by the VP9 decoder IIUC.
comment:28 by , 7 months ago
In general the software fallback is a very important feature. Although things have improved there are still problems with hardware decoding. The automatic fallback to software decoding stops these problems from being a show stopper for users that don't understand hardware vs. software decoding and how to turn off hardware decoding.
In this particular case, because the defect in Video Toolbox prevented FFmpeg from falling back to software decoding IINA had to put out a release to disable VP9 hardware decoding for Intel Macs.
Thus a fix that does not allow for software fallback is concerning.
Thank you very much for looking into this problem. Users had been wanting VP9 hardware decoding and are disappointed that it is not working.
I'm able to reproduce this. It's working on my apple silicon mac but freezing on my intel one.