Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Freeze on Intel based Macs while playing VP9 encoded videos #4486

Closed
1 task done
low-batt opened this issue Jul 10, 2023 · 14 comments · Fixed by #4498
Closed
1 task done

Freeze on Intel based Macs while playing VP9 encoded videos #4486

low-batt opened this issue Jul 10, 2023 · 14 comments · Fixed by #4498

Comments

@low-batt
Copy link
Contributor

low-batt commented Jul 10, 2023

System and IINA version:

  • macOS 13.4.1
  • IINA 1.3.2

Expected behavior:
Playback of YouTube videos does not freeze.

Actual behavior:
@AlejandroVolkova has reported that IINA 1.3.2 will freeze while playing some YouTube videos.

This was encountered running on an Intel based Mac:
iMac Retina 4K, 21.5-Inch, 2019
Processor : 3 GHz 6-Core Intel Core i5
Graphics : Radeon Pro 560X 4 GB
Memory : 32 GB 2667 MHz DDR4

Steps to reproduce:
Play a YouTube video with VP9 encoding on an Intel based Mac with hardware decoding enabled.

  • MPV does not have this problem.

Has not be tested, but the expectation is that the problem will reproduce with mpv if hardware decoding is enabled.

This has now been reproduced with mpv. The playback core thread is blocked on a call to VTDecompressionSessionWaitForAsynchronousFrames as is seen with IINA.

How often does this happen?
Every time.

@low-batt
Copy link
Contributor Author

low-batt commented Jul 10, 2023

Analysis

@GreyAsteroid has identified the likely culprit as FFmpeg ticket 9599 "VideoToolbox VP9 hwaccel freezes ffmpeg".

Some background on what that defect is about…

File types such as mkv and mp4 are container formats. The video stream(s) contained within them must be decoded by a player in order to display the video. How this is done depends up the Codec used to encode the video. How videos are encoded has changed over time as newer codecs are developed. Generally newer codecs provide better compression maintaining video quality. VP9 is a video encoding format.

For audio/video playback IINA uses a library from the mpv project, which in turn uses libraries from FFmpeg. hwaccel is referring to hardware acceleration supported by FFmpeg, specifically support for VideoToolbox. Video Toolbox is Apple's framework that provides access to hardware encoders and decoders.

The full layering with respect to hardware decoding is:

With the last 3 being the most critical parts with respect to hardware decoding.

So the problem at hand seems to be isolated to using hardware decoding on Intel based Macs with vidoes encoded in VP9 format.

Request for More Information

One tool for debugging "freezes" is the sample command. This tool watches an application process and generates a report showing what code was being executed. This may or may not provide useful information about a problem.

As I do not have an Intel Mac that reproduces the problem it would be helpful if someone who can reproduce the problem runs this tool and posts the result.

To run this tool, start IINA and reproduce the problem. With IINA freezing open Terminal and run the sample command as shown here:

low-batt@gag ~$ sample -file process-sample.txt IINA
Sampling process 85549 for 10 seconds with 1 millisecond of run time between samples
Sampling completed, processing symbols...
Sample analysis of process 85549 written to file process-sample.txt
low-batt@gag ~$ 

Then drag and drop the report generated (process-sample.txt) to this issue.

Workaround

@GreyAsteroid also provided a workaround.

The workaround involves changing the value of the mpv --hwdec-codecs option:

Allow hardware decoding for a given list of codecs only.

This is usually only needed with broken GPUs, where a codec is reported as supported, but decoding causes more problems than it solves.

This option provides the ability to disable hardware decoding for specific codecs, exactly what is needed for this case. Many mpv features that are not available directly in the IINA GUI can be accessed using IINA's Advanced settings.

The default value for the hwdec-codecs mpv option is h264,vc1,hevc,vp8,vp9,av1,prores. We want to remove vp9 from that list. This preserves hardware decoding for videos encoded with other codecs. To do that follow these instructions:

  • Start IINA
  • Click on Settings… under the IINA menu
  • The settings panel appears
  • On the left side of the panel click on Advanced
  • Slide the Enable advanced settings toggle button to be on (blue)
  • In the Additional mpv options section click on +
  • A new entry appears in the table
  • Double click on name and replace it with hwdec-codecs
  • Double click on value and replace it with h264,vc1,hevc,vp8,av1,prores
  • Confirm the settings panel looks like the screenshot below
  • Restart IINA to activate the new settings

issue-vp9-freeze

@GreyAsteroid
Copy link

Happy to help any way I can, here's the output from sample. process-sample.txt

@low-batt
Copy link
Contributor Author

Thanks! I always like to gather extra evidence and confirm it is consistent with what we think is the cause of the problem.

The mpv core thread is stuck waiting on the Apple Video Toolbox method VTDecompressionSessionWaitForAsynchronousFrames, called by the FFmpeg libavcodec library:

    7828 Thread_53421: mpv/mpv core
    + 7828 ???  (in <unknown binary>)  [0x10000c680]
    +   7828 ???  (in libavcodec.60.dylib)  load address 0x10bf75000 + 0x4bfc5e  [0x10c434c5e]
    +     7241 VTDecompressionSessionWaitForAsynchronousFrames  (in VideoToolbox) + 708  [0x7ff818cd9891]
    +     ! 7241 FigSemaphoreWaitRelative  (in CoreMedia) + 161  [0x7ff81426e799]
    +     !   7241 WaitOnConditionTimed  (in CoreMedia) + 82  [0x7ff81428c2f1]
    +     !     7241 _pthread_cond_wait  (in libsystem_pthread.dylib) + 1211  [0x7ff809cab76b]
    +     !       7241 __psynch_cvwait  (in libsystem_kernel.dylib) + 10  [0x7ff809c6e5e6]
    +     587 VTDecompressionSessionWaitForAsynchronousFrames  (in VideoToolbox) + 454  [0x7ff818cd9793]
    +       587 FigSemaphoreWaitRelative  (in CoreMedia) + 161  [0x7ff81426e799]
    +         587 WaitOnConditionTimed  (in CoreMedia) + 82  [0x7ff81428c2f1]
    +           587 _pthread_cond_wait  (in libsystem_pthread.dylib) + 1211  [0x7ff809cab76b]
    +             587 __psynch_cvwait  (in libsystem_kernel.dylib) + 10  [0x7ff809c6e5e6]

Most of the other threads have gone idle. The main thread is blocked on a lock inside of mpv, freezing the UI:

    +                                 7828 PlayerCore.syncUI(_:)  (in IINA) + 660  [0x108d8c8d4]
    +                                   7828 mpv_get_property  (in libmpv.2.dylib) + 92  [0x10a71c4ac]
    +                                     7828 mp_dispatch_lock  (in libmpv.2.dylib) + 221  [0x10a7024bd]
    +                                       7828 _pthread_cond_wait  (in libsystem_pthread.dylib) + 1211  [0x7ff809cab76b]
    +                                         7828 __psynch_cvwait  (in libsystem_kernel.dylib) + 10  [0x7ff809c6e5e6]

That is a little disturbing. Raises the question of whether one of the mpv threads encountered an unexpected error and failed to released a lock.

With the mpv core thread blocked waiting on the Video Toolbox method this seems consistent with something going really wrong with hardware decoding in the FFmpeg library.

Hopefully someone from the FFmpeg team will investigate the problem.

@AlejandroVolkova
Copy link

Hi guys, I have reproduced the problem and I am attaching the report generated on my computer to further investigate this problem, if there is anything else needed just let me know.

File : process-sample.txt

@AlejandroVolkova
Copy link

AlejandroVolkova commented Jul 10, 2023

I was following @low-batt instructions to only disable vp9 and keep hardware decoding for videos encoded with other codecs, but IINA started freezing again, so I ran another sample to see if it adds more information, however it was happening because I just copied/pasted this.

  • Double click on value and replace it with h264,vc1,hevc,vp8,vp9,av1,prores

But I think you forgot to remove the vp9 value, it should be : h264,vc1,hevc,vp8,av1,prores

Anyways, I’m not sure if there are any differences with the other .txt I attached before, but I hope it helps.

Also, I tested this version of MPV player enabling hardware acceleration under :

~/.config/mpv/mpv.conf
hwdec=auto

And I can confirm it also gets unresponsive when playing VP9 videos. the only difference is that the mvp interface doesn't freeze, it just doesn't play the video and doesn't show the playback controls anymore.

Here is a process-sample.txt for the mpv player.

@low-batt
Copy link
Contributor Author

But I think you forgot to remove the vp9 value, it should be : h264,vc1,hevc,vp8,av1,prores

Sorry about the dumb mistake. I've corrected the instructions.

More information below, but I thought I should discuss the next step first. The reason to collect the process samples was to confirm they matched up with our expectation that this was a problem in FFmpeg or Video Toolbox. As expected the process samples confirm a freeze in the FFmpeg library. At this point we need a FFmpeg developer that knows Video Toolbox to investigate ticket 9599.

To get the attention of overloaded developers it is always helpful to supply as much technical details as possible. I took note that Mac and video details were supplied for the problem at hand. @GreyAsteroid, I suggest reproducing this problem with FFmpeg, taking a sample of FFmpeg with it frozen and attaching that to ticket 9599. It certainly can't hurt to provide that information.

Do you have the ability to build FFmpeg yourself? If so, the FFmpeg team pays more attention to problems when it is confirmed that they reproduce using the very latest sources. I just built FFmpeg from the latest sources and tested playing the video, but as expected an Intel Mac is required to reproduce this problem. If you don't have the ability to build FFmpeg posting a sample of FFmpeg 6 frozen is still useful.


I looked at the additional process samples and they are all consistent. The playback thread is blocked on a call to the FFmpeg libavcodec library which is in turn blocked on a call to the Apple Video Toolbox API VTDecompressionSessionWaitForAsynchronousFrames.

The results with the stolendata.net mpv build are interesting as that build of mpv 0.35.1 is using FFmpeg 5.1.2.

I tested that build of mpv playing the file that exhibits the problem and using --hwdec=auto to enable hardware decoding. As with IINA the problem did not reproduce on my MacBookPro18,2 which has the M1 chip. The video played using hardware decoding without reporting any errors. This is consistent with the expectation that this is only a problem on Macs with an Intel chip.

However, all is not well under Apple Silicon. If while playing you toggle the Hardware Decoding setting on the Video Panel off and then back on, FFmpeg is unable to transition from software decoding back to hardware decoding as can be seen in this clip from the mpv log:

[  28.641][v][vd] Trying hardware decoding via vp9-videotoolbox.
[  28.641][v][cplayer] Set property: hwdec="auto" -> 1
[  28.641][e][ffmpeg/video] vp9: Not all references are available
[  28.641][w][vd] Error while decoding frame (hardware decoding)!
[  28.641][e][ffmpeg/video] vp9: Not all references are available
[  28.641][w][vd] Error while decoding frame (hardware decoding)!
[  28.641][e][ffmpeg/video] vp9: Not all references are available
[  28.641][w][vd] Error while decoding frame (hardware decoding)!
[  28.641][w][vd] Falling back to software decoding.

I confirmed transitioning between hardware decoding and software decoding worked fine with a HEVC encoded video.

@low-batt
Copy link
Contributor Author

I forgot to comment on this mpv behavior:

the only difference is that the mvp interface doesn't freeze, it just doesn't play the video and doesn't show the playback controls anymore.

The process sample of the mpv player shows the mpv's on screen controller is frozen similar to IINA's:

    7234 Thread_195433: mpv/lua script (osc)
…
+  7234 luaD_call  (in liblua.5.1.dylib) + 80  [0x10cd6df89]
+    7234 luaD_precall  (in liblua.5.1.dylib) + 456  [0x10cd6db31]
+      7234 script_get_property_native  (in mpv) + 154  [0x10c9275ea]
+        7234 mpv_get_property  (in mpv) + 92  [0x10c90a7fc]
+          7234 mp_dispatch_lock  (in mpv) + 217  [0x10c8f0969]
+            7234 _pthread_cond_wait  (in libsystem_pthread.dylib) + 1242  [0x7ff8022db758]
+              7234 __psynch_cvwait  (in libsystem_kernel.dylib) + 10  [0x7ff80229f0ee]

The difference with IINA is that mpv's OSC is using a separate thread, whereas IINA is using the main thread. Blocking the main thread has more noticeable effects, such as causing macOS to show the Spinning Wheel of Death.

@GreyAsteroid
Copy link

@GreyAsteroid, I suggest reproducing this problem with FFmpeg, taking a sample of FFmpeg with it frozen and attaching that to ticket 9599. It certainly can't hurt to provide that information.

Thanks for the advice, I've followed through and hopefully we can get someone to take a peek at the issue.

@scrutinizer11
Copy link

scrutinizer11 commented Jul 10, 2023

I updated to IINA 1.3.2 and ran into a stuttered playback with one of the files that I downloaded from YouTube with yt-dlp 2023.07.06 (i.e., not the one that's shipped with IINA). The bad file was a low-resolution video. However, another video was silky smooth. macOS 10.14 on MBP mid-2012.

yt-dlp uses ffmpeg for conversion, but I have to admit I haven't updated it in quite a long time since I didn't find impetus.

IINA log of the bad file (level - verbose):

11:38:09.588 [iina][d] IINA 1.3.2 Build 135
11:38:09.593 [iina][d] Copyright © 2017-2023
11:38:09.593 [iina][d] Collider LI, et al.
11:38:09.593 [iina][d] Released under GPLv3.
11:38:09.594 [iina][d] FFmpeg 6.0
11:38:09.597 [iina][d]   libavcodec 60.3.100
11:38:09.597 [iina][d]   libavformat 60.3.100
11:38:09.597 [iina][d]   libavutil 58.2.100
11:38:09.597 [iina][d]   libswscale 7.1.100
11:38:09.599 [iina][d] Built 8 Jul 2023 at 18:19:29 from branch develop, commit 617dfc1cf7b113574a7e0cdddd94130eb6b445ed
11:38:09.599 [iina][d] App will launch
11:38:09.859 [iina][d] App launched
11:38:09.862 [iina][d] Loading key bindings
11:38:09.866 [iina][d] Set key bindings (63 mappings)
11:38:09.944 [player0][d] Set path to /Applications/*/IINA.app/Contents/MacOS:/Applications/Third Party Software/Other Utilities/IINA.app/Contents/MacOS:/usr/bin:/bin:/usr/sbin:/sbin
11:38:10.013 [iina][d] Using mpv 0.35.0-419-gf79458476b-dirty
11:38:10.013 [iina][d] Setting up MediaPlayer integration
11:38:21.433 [player0][d] Open URL: file:///Users/home/Movies/Downloaded%20From%20Internet/%F0%9F%94%A5%D0%A2%D0%90%D0%98%CC%86%D0%9D%D0%AB%D0%95%20%D0%94%D0%9E%D0%93%D0%9E%D0%92%D0%9E%D0%A0%D0%95%D0%9D%D0%9D%D0%9E%D0%A1%D0%A2%D0%98%20%D0%9F%D0%A3%D0%A2%D0%98%D0%9D%D0%90%20%D0%98%20%D0%A6%D0%A0%D0%A3%20%D0%9A%D1%82%D0%BE%20%D0%9F%D0%9E%D0%94%D0%A1%D0%A2%D0%90%D0%92%D0%9B%D0%AF%D0%95%D0%A2%20%D0%97%D0%B5%D0%BB%D0%B5%D0%BD%D1%81%D0%BA%D0%BE%D0%B3%D0%BE/%F0%9F%94%A5%D0%A2%D0%90%D0%98%CC%86%D0%9D%D0%AB%D0%95%20%D0%94%D0%9E%D0%93%D0%9E%D0%92%D0%9E%D0%A0%D0%95%D0%9D%D0%9D%D0%9E%D0%A1%D0%A2%D0%98%20%D0%9F%D0%A3%D0%A2%D0%98%D0%9D%D0%90%20%D0%98%20%D0%A6%D0%A0%D0%A3!%20%D0%9A%D1%82%D0%BE%20%D0%9F%D0%9E%D0%94%D0%A1%D0%A2%D0%90%D0%92%D0%9B%D0%AF%D0%95%D0%A2%20%D0%97%D0%B5%D0%BB%D0%B5%D0%BD%D1%81%D0%BA%D0%BE%D0%B3%D0%BE%EF%BC%9F%D0%9F%D1%83%D1%82%D0%B8%D0%BD%20%D1%83%D0%B4%D0%BE%D0%B1%D0%BD%D0%B5%D0%B5%20%D0%9F%D1%80%D0%B8%D0%B3%D0%BE%D0%B6%D0%B8%D0%BD%D0%B0%EF%BC%9F%20%D0%98%D0%BB%D0%BB%D0%B0%D1%80%D0%B8%D0%BE%D0%BD%D0%BE%D0%B2.webm
11:38:21.433 [player0][d] Opening /Users/home/Movies/Downloaded From Internet/🔥ТАЙНЫЕ ДОГОВОРЕННОСТИ ПУТИНА И ЦРУ Кто ПОДСТАВЛЯЕТ Зеленского/🔥ТАЙНЫЕ ДОГОВОРЕННОСТИ ПУТИНА И ЦРУ! Кто ПОДСТАВЛЯЕТ Зеленского?Путин удобнее Пригожина? Илларионов.webm in main window
11:38:22.363 [iina][d] Created OpenGL pixel format with [__C._CGLPixelFormatAttribute(rawValue: 5), __C._CGLPixelFormatAttribute(rawValue: 96), __C._CGLPixelFormatAttribute(rawValue: 58), __C._CGLPixelFormatAttribute(rawValue: 8), __C._CGLPixelFormatAttribute(rawValue: 64), __C._CGLPixelFormatAttribute(rawValue: 99), __C._CGLPixelFormatAttribute(rawValue: 12800), __C._CGLPixelFormatAttribute(rawValue: 73), __C._CGLPixelFormatAttribute(rawValue: 0)]
11:38:22.424 [iina][d] Falling back to nominal display refresh rate: 59.90145788336933 from 0.0
11:38:22.424 [hdr][d] Loading ICC profile
11:38:22.431 [iina][d] window!.screen: visible frame (0.0, 0.0, 1440.0, 877.0)
11:38:22.432 [iina][d] NSScreen.main: visible frame (0.0, 0.0, 1440.0, 877.0)
11:38:22.432 [iina][d] NSScreen.screens[0]: visible frame (0.0, 0.0, 1440.0, 877.0)
11:38:22.432 [iina][d] MainWindowLastPosition (0.0, 0.0) matched: visible frame (0.0, 0.0, 1440.0, 877.0)
11:38:22.565 [player0][d] File started
11:38:22.566 [player0][d] Started auto load
11:38:22.566 [player0][d] Track list changed
11:38:22.582 [fmatcher][d] **Start matching
11:38:22.582 [fmatcher][d] Getting all media files...
11:38:22.583 [fmatcher][d] Got all media files, video=1, audio=0
11:38:22.583 [fmatcher][d] Getting all sub files...
11:38:22.584 [fmatcher][d] Searching subtitles from 0 directories...
11:38:22.584 [fmatcher][d] Got 3 subtitles
11:38:22.584 [fmatcher][d] Adding files to playlist
11:38:22.584 [fmatcher][d] Grouping video files...
11:38:22.584 [fgroup][d] Start grouping 1 files
11:38:22.585 [fmatcher][d] Finished with 1 groups
11:38:22.585 [fmatcher][d] Grouping sub files...
11:38:22.585 [fgroup][d] Start grouping 3 files
11:38:22.587 [fmatcher][d] Finished with 1 groups
11:38:22.587 [fmatcher][d] Matching video and sub series...
11:38:22.588 [fmatcher][d] Calculated editing distance
11:38:22.588 [fmatcher][d] Finished matching.
11:38:22.588 [fmatcher][d] Matching subs with matched series, prefixes=0...
11:38:22.588 [fmatcher][d] Matching for 🔥ТАЙНЫЕ ДОГОВОРЕННОСТИ ПУТИНА И ЦРУ! Кто ПОДСТАВЛЯЕТ Зеленского?Путин удобнее Пригожина? Илларионов
11:38:22.589 [fmatcher][d] Matched 3 subtitles
11:38:22.589 [fmatcher][d] Force matching unmatched videos, video=0, sub=0...
11:38:22.589 [fmatcher][d] **Finished matching
11:38:22.590 [player0][d] Found 3 subs for current file
11:38:22.866 [hdr][d] Loading ICC profile
11:38:22.868 [player0][d] File loaded
11:38:22.869 [player0][d] Track list changed
11:38:22.911 [iina][d] Synchronized info.abLoopStatus cleared
11:38:22.985 [player0][d] Getting thumbnails
11:38:22.987 [player0][d] Found thumbnail cache
11:38:22.988 [thumbcache][d] Reading thumbnail cache...
11:38:22.988 [thumbcache][d] Reading from /Users/home/Library/Caches/com.colliderli.iina/thumb_cache/cd0c511d37fe42d3a82c10171b3ee100
11:38:22.993 [player0][d] Playback restarted
11:38:23.023 [thumbcache][d] Finished reading thumbnail cache, 101 in total
11:38:23.060 [player0][d] Track list changed
11:38:23.062 [mpv][e] [ffmpeg/video] error: vp9: Failed setup for format videotoolbox_vld: hwaccel initialisation returned error.
11:38:26.670 [player0][d] Track list changed
11:38:27.589 [player0][d] Track list changed
11:38:28.967 [player0][d] Track list changed
11:39:01.378 [iina][d] Set key bindings (63 mappings)
11:39:41.660 [mpv][w] [cplayer] warn: Audio device underrun detected.
11:39:41.660 [mpv][w] [cplayer] warn: 
11:39:41.660 [mpv][w] [cplayer] warn: Audio/Video desynchronisation detected! Possible reasons include too slow
11:39:41.660 [mpv][w] [cplayer] warn: hardware, temporary CPU spikes, broken drivers, and broken files. Audio
11:39:41.661 [mpv][w] [cplayer] warn: position will not match to the video (see A-V status field).
11:39:41.661 [mpv][w] [cplayer] warn: 
11:47:27.078 [player0][d] Playback restarted
12:14:08.384 [player0][d] Playback restarted
12:14:13.126 [player0][d] Playback restarted
12:14:17.708 [player0][d] Playback restarted
12:14:21.458 [player0][d] Playback restarted
12:14:27.663 [player0][d] Playback restarted
12:21:47.156 [player0][d] Playback restarted
12:21:47.707 [player0][d] Playback restarted
12:21:48.042 [player0][d] Playback restarted
12:21:48.325 [player0][d] Playback restarted
12:21:48.558 [player0][d] Playback restarted

MediaInfo analysis of the bad file:

{
"media": {
"@ref": "/Users/home/Movies/Downloaded From Internet/🔥ТАЙНЫЕ ДОГОВОРЕННОСТИ ПУТИНА И ЦРУ Кто ПОДСТАВЛЯЕТ Зеленского/🔥ТАЙНЫЕ ДОГОВОРЕННОСТИ ПУТИНА И ЦРУ! Кто ПОДСТАВЛЯЕТ Зеленского?Путин удобнее Пригожина? Илларионов.webm",
"track": [
{
"@type": "General",
"VideoCount": "1",
"AudioCount": "1",
"FileExtension": "webm",
"Format": "WebM",
"Format_Version": "4",
"FileSize": "82441817",
"Duration": "3198.561",
"OverallBitRate": "206197",
"FrameRate": "25.000",
"FrameCount": "79963",
"IsStreamable": "Yes",
"File_Modified_Date": "UTC 2023-07-09 16:57:06",
"File_Modified_Date_Local": "2023-07-09 19:57:06",
"Encoded_Application": "Lavf59.9.102",
"Encoded_Library": "Lavf59.9.102"
},
{
"@type": "Video",
"StreamOrder": "0",
"ID": "1",
"UniqueID": "10312341414908502156",
"Format": "VP9",
"CodecID": "V_VP9",
"Duration": "3198.520000000",
"Width": "640",
"Height": "360",
"PixelAspectRatio": "1.000",
"DisplayAspectRatio": "1.778",
"FrameRate_Mode": "CFR",
"FrameRate": "25.000",
"FrameCount": "79963",
"ColorSpace": "YUV",
"Language": "en",
"Default": "Yes",
"Forced": "No",
"colour_description_present": "Yes",
"colour_description_present_Source": "Container",
"colour_range": "Limited",
"colour_range_Source": "Container",
"colour_primaries": "BT.709",
"colour_primaries_Source": "Container",
"transfer_characteristics": "BT.709",
"transfer_characteristics_Source": "Container",
"matrix_coefficients": "BT.709",
"matrix_coefficients_Source": "Container"
},
{
"@type": "Audio",
"StreamOrder": "1",
"ID": "2",
"UniqueID": "13942358992718180841",
"Format": "Opus",
"CodecID": "A_OPUS",
"Duration": "3198.561000000",
"Channels": "2",
"ChannelPositions": "Front: L R",
"ChannelLayout": "L R",
"SamplingRate": "48000",
"SamplingCount": "153530928",
"BitDepth": "32",
"Compression_Mode": "Lossy",
"Delay": "0.000",
"Delay_Source": "Container",
"Language": "en",
"Default": "Yes",
"Forced": "No"
}
]
}
}

IINA log of the good file (level - verbose):

18:53:31.868 [iina][d] IINA 1.3.2 Build 135
18:53:31.872 [iina][d] Copyright © 2017-2023
18:53:31.872 [iina][d] Collider LI, et al.
18:53:31.872 [iina][d] Released under GPLv3.
18:53:31.874 [iina][d] FFmpeg 6.0
18:53:31.877 [iina][d]   libavcodec 60.3.100
18:53:31.877 [iina][d]   libavformat 60.3.100
18:53:31.877 [iina][d]   libavutil 58.2.100
18:53:31.877 [iina][d]   libswscale 7.1.100
18:53:31.879 [iina][d] Built 8 Jul 2023 at 18:19:29 from branch develop, commit 617dfc1cf7b113574a7e0cdddd94130eb6b445ed
18:53:31.880 [iina][d] App will launch
18:53:31.986 [iina][d] App launched
18:53:31.989 [iina][d] Loading key bindings
18:53:31.995 [iina][d] Set key bindings (63 mappings)
18:53:32.105 [player0][d] Set path to /Applications/*/IINA.app/Contents/MacOS:/usr/bin:/bin:/usr/sbin:/sbin
18:53:32.166 [iina][d] Using mpv 0.35.0-419-gf79458476b-dirty
18:53:32.167 [iina][d] Setting up MediaPlayer integration
18:53:32.260 [player0][d] Open URL: file:///Users/home/Movies/Downloaded%20From%20Internet/3.%20%D0%9A%D1%82%D0%BE%20%D0%B2%D0%B8%D0%BD%D0%BE%D0%B2%D0%B0%D1%82%20%D0%B2%20%D1%81%D0%BB%D0%BE%D0%B6%D0%B8%D0%B2%D1%88%D0%B5%D0%B8%CC%86%D1%81%D1%8F%20%D1%81%D0%B8%D1%82%D1%83%D0%B0%D1%86%D0%B8%D0%B8/3.%20%D0%9A%D1%82%D0%BE%20%D0%B2%D0%B8%D0%BD%D0%BE%D0%B2%D0%B0%D1%82%20%D0%B2%20%D1%81%D0%BB%D0%BE%D0%B6%D0%B8%D0%B2%D1%88%D0%B5%D0%B8%CC%86%D1%81%D1%8F%20%D1%81%D0%B8%D1%82%D1%83%D0%B0%D1%86%D0%B8%D0%B8..webm
18:53:32.260 [player0][d] Opening /Users/home/Movies/Downloaded From Internet/3. Кто виноват в сложившейся ситуации/3. Кто виноват в сложившейся ситуации..webm in main window
18:53:33.308 [iina][d] Created OpenGL pixel format with [__C._CGLPixelFormatAttribute(rawValue: 5), __C._CGLPixelFormatAttribute(rawValue: 96), __C._CGLPixelFormatAttribute(rawValue: 58), __C._CGLPixelFormatAttribute(rawValue: 8), __C._CGLPixelFormatAttribute(rawValue: 64), __C._CGLPixelFormatAttribute(rawValue: 99), __C._CGLPixelFormatAttribute(rawValue: 12800), __C._CGLPixelFormatAttribute(rawValue: 73), __C._CGLPixelFormatAttribute(rawValue: 0)]
18:53:33.382 [iina][d] Falling back to nominal display refresh rate: 59.90145788336933 from 0.0
18:53:33.383 [hdr][d] Loading ICC profile
18:53:33.393 [iina][d] window!.screen: visible frame (0.0, 0.0, 1440.0, 877.0)
18:53:33.393 [iina][d] NSScreen.main: visible frame (0.0, 0.0, 1440.0, 877.0)
18:53:33.393 [iina][d] NSScreen.screens[0]: visible frame (0.0, 0.0, 1440.0, 877.0)
18:53:33.393 [iina][d] MainWindowLastPosition (0.0, 0.0) matched: visible frame (0.0, 0.0, 1440.0, 877.0)
18:53:33.521 [player0][d] File started
18:53:33.521 [player0][d] Started auto load
18:53:33.538 [fmatcher][d] **Start matching
18:53:33.538 [fmatcher][d] Getting all media files...
18:53:33.539 [fmatcher][d] Got all media files, video=1, audio=0
18:53:33.539 [fmatcher][d] Getting all sub files...
18:53:33.540 [fmatcher][d] Searching subtitles from 0 directories...
18:53:33.540 [fmatcher][d] Got 3 subtitles
18:53:33.540 [fmatcher][d] Adding files to playlist
18:53:33.540 [fmatcher][d] Grouping video files...
18:53:33.540 [fgroup][d] Start grouping 1 files
18:53:33.541 [fmatcher][d] Finished with 1 groups
18:53:33.541 [fmatcher][d] Grouping sub files...
18:53:33.541 [fgroup][d] Start grouping 3 files
18:53:33.542 [fmatcher][d] Finished with 1 groups
18:53:33.542 [fmatcher][d] Matching video and sub series...
18:53:33.542 [fmatcher][d] Calculated editing distance
18:53:33.542 [fmatcher][d] Finished matching.
18:53:33.542 [fmatcher][d] Matching subs with matched series, prefixes=0...
18:53:33.542 [fmatcher][d] Matching for 3. Кто виноват в сложившейся ситуации.
18:53:33.543 [fmatcher][d] Matched 3 subtitles
18:53:33.544 [fmatcher][d] Force matching unmatched videos, video=0, sub=0...
18:53:33.544 [fmatcher][d] **Finished matching
18:53:33.544 [player0][d] Found 3 subs for current file
18:53:33.693 [hdr][d] Loading ICC profile
18:53:33.693 [player0][d] File loaded
18:53:33.695 [player0][d] Track list changed
18:53:33.760 [iina][d] Synchronized info.abLoopStatus cleared
18:53:34.203 [player0][d] Getting thumbnails
18:53:34.205 [player0][d] Request new thumbnails
18:53:34.255 [player0][d] Playback restarted
18:53:34.329 [player0][d] Track list changed
18:53:34.406 [player0][d] Got new thumbnails, progress 12
18:53:34.611 [player0][d] Got new thumbnails, progress 29
18:53:34.816 [player0][d] Got new thumbnails, progress 46
18:53:35.025 [player0][d] Got new thumbnails, progress 60
18:53:35.234 [player0][d] Got new thumbnails, progress 78
18:53:35.441 [player0][d] Got new thumbnails, progress 96
18:53:35.486 [player0][d] Got all thumbnails, succeeded=true
18:53:35.486 [thumbcache][d] Writing thumbnail cache...
18:53:35.734 [thumbcache][d] Finished writing thumbnail cache.
18:53:45.010 [player0][d] Track list changed
18:53:45.311 [player0][d] Track list changed
18:53:45.824 [player0][d] Track list changed
18:59:47.703 [player0][d] Playback restarted
18:59:48.350 [player0][d] Playback restarted

MediaInfo analysis of the good file:

{
"media": {
"@ref": "/Users/home/Movies/Downloaded From Internet/3. Кто виноват в сложившейся ситуации/3. Кто виноват в сложившейся ситуации..webm",
"track": [
{
"@type": "General",
"VideoCount": "1",
"AudioCount": "1",
"FileExtension": "webm",
"Format": "WebM",
"Format_Version": "4",
"FileSize": "121724875",
"Duration": "1798.581",
"OverallBitRate": "541426",
"FrameRate": "30.000",
"FrameCount": "53957",
"IsStreamable": "Yes",
"File_Modified_Date": "UTC 2023-07-10 07:35:47",
"File_Modified_Date_Local": "2023-07-10 10:35:47",
"Encoded_Application": "Lavf59.9.102",
"Encoded_Library": "Lavf59.9.102"
},
{
"@type": "Video",
"StreamOrder": "0",
"ID": "1",
"UniqueID": "1906723754787197585",
"Format": "VP9",
"CodecID": "V_VP9",
"Duration": "1798.566000000",
"Width": "1280",
"Height": "720",
"PixelAspectRatio": "1.000",
"DisplayAspectRatio": "1.778",
"FrameRate_Mode": "CFR",
"FrameRate": "30.000",
"FrameCount": "53957",
"ColorSpace": "YUV",
"Language": "en",
"Default": "Yes",
"Forced": "No",
"colour_description_present": "Yes",
"colour_description_present_Source": "Container",
"colour_range": "Limited",
"colour_range_Source": "Container",
"colour_primaries": "BT.709",
"colour_primaries_Source": "Container",
"transfer_characteristics": "BT.709",
"transfer_characteristics_Source": "Container",
"matrix_coefficients": "BT.709",
"matrix_coefficients_Source": "Container"
},
{
"@type": "Audio",
"StreamOrder": "1",
"ID": "2",
"UniqueID": "10758184371226142299",
"Format": "Opus",
"CodecID": "A_OPUS",
"Duration": "1798.581000000",
"Channels": "2",
"ChannelPositions": "Front: L R",
"ChannelLayout": "L R",
"SamplingRate": "48000",
"SamplingCount": "86331888",
"BitDepth": "32",
"Compression_Mode": "Lossy",
"Delay": "0.000",
"Delay_Source": "Container",
"Language": "en",
"Default": "Yes",
"Forced": "No"
}
]
}
}

@low-batt
Copy link
Contributor Author

What stands out to me is this line from the log where playback has trouble:

11:38:23.062 [mpv][e] [ffmpeg/video] error: vp9: Failed setup for format videotoolbox_vld: hwaccel initialisation returned error.

For this kind of problem we need the mpv log files. This does not look like the problem being discussed in this issue, although it is related in that this is about VP9 encoded videos and hardware acceleration.

I'm surprised FFmpeg is trying to use hardware acceleration for VP9 under macOS Mojave. I think support was added in macOS Big Sur.

The workaround described above should be effective for this issue as well.

@scrutinizer11
Copy link

I added some mpv options to the watch list in the IINA settings. Will those do? If they won't I'd like to know how to enable mpv logging.

@low-batt
Copy link
Contributor Author

Not sure where the "watch list" is in IINA's settings? Was busy today. I be looking into this more tomorrow. We should take a look at the mpv log file and see if it sheds any light on why playback differs with these two files.

To enable logging follow these instructions:

  • Start IINA
  • Click on Settings… under the IINA menu
  • The settings panel appears
  • On the left side of the panel click on Advanced
  • Slide the Enable advanced settings toggle button to be on (blue)
  • Click on the checkbox Enable logging to file
  • Confirm the settings panel looks like the screenshot below
  • Restart IINA to activate logging

issue-4486-logging

Once IINA has restarted, play the video and reproduce the problem. Then:

  • Click on Settings… under the IINA menu
  • The settings panel appears
  • On the left side of the panel click on Advanced
  • Click on Open log directory
  • A new Finder window appears containing the logs for this session
  • Quit IINA to complete the log files

The Finder window contains two files, iina.log and mpv.log. To attach the log files to this issue, drag-n-drop them from the Finder window to the Leave a comment section below. Include both the iina.log and the mpv.log

The log files can also be accessed using Terminal as shown here:

low-batt@gag com.colliderli.iina$ pwd
/Users/low-batt/Library/Logs/com.colliderli.iina
low-batt@gag com.colliderli.iina$ ls
2022-10-04-17-57-15_jVrbWy
low-batt@gag com.colliderli.iina$ cd 2022-10-04-17-57-15_jVrbWy
low-batt@gag 2022-10-04-17-57-15_jVrbWy$ ls
iina.log	mpv.log
low-batt@gag 2022-10-04-17-57-15_jVrbWy$ 

With logging enabled IINA creates a new log directory each time it is started. If accessing the logs using Terminal be sure to obtain them from the latest log directory.

DO NOT FORGET to disable logging once you have obtained log files for the problem being investigated. IINA does not restrict the size of log files or delete old logs. If you leave logging enabled the logs will continue to accumulate.

low-batt added a commit that referenced this issue Jul 13, 2023
This commit will add code to MPVController.mpvInit that changes the
value of the mpv option hwdec-codecs, removing VP9, if IINA is not
running on a Mac with an Apple Silicon chip. This change works around
the FFmpeg defect reported in ticket 9599.
@low-batt low-batt linked a pull request Jul 13, 2023 that will close this issue
2 tasks
@low-batt low-batt self-assigned this Jul 13, 2023
@scrutinizer11
Copy link

Turns out, extra logging had been already enabled. I attach the corresponding mpv log

mpv-bad-file.txt

low-batt added a commit that referenced this issue Jul 14, 2023
This commit will add code to MPVController.mpvInit that changes the
value of the mpv option hwdec-codecs, removing VP9, if IINA is not
running on a Mac with an Apple Silicon chip. This change works around
the FFmpeg defect reported in ticket 9599.
uiryuu pushed a commit that referenced this issue Jul 15, 2023
* Workaround freeze due to VP9 hardware decode, #4486

This commit will add code to MPVController.mpvInit that changes the
value of the mpv option hwdec-codecs, removing VP9, if IINA is not
running on a Mac with an Apple Silicon chip. This change works around
the FFmpeg defect reported in ticket 9599.

* Work around freeze due to VP9 hardware decode, #4486

This commit will add code to MPVController.mpvInit that changes the
value of the mpv option hwdec-codecs, removing VP9, if IINA is not
running on a Mac with an Apple Silicon chip. This change works around
the FFmpeg defect reported in ticket 9599.
@low-batt
Copy link
Contributor Author

This issue is closed because a workaround has been added in IINA 1.3.3. This workaround only activates on Intel Macs. The IINA log file will show the workaround being applied as seen here:

17:38:19.451 [iina][d] Disabling hardware acceleration for VP9 encoded videos to workaround FFmpeg 9599
17:38:19.451 [iina][d] Option hwdec-codecs has been set to: h264,vc1,hevc,vp8,av1,prores

This is the same workaround discussed above.

Of course this means VP9 hardware decoding is disabled on Intel Macs. For that IINA is waiting on FFmpeg to fix ticket 9599.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants