Frame drops unnoticed by mpv/iina

[krackers]

I found a curious issue, and was hoping some of the developers here more familiar with OpenGL development on macOS could opine. I am on an M1 Pro mbp running macos14, and when playing a 60fps video (e.g. https://www.youtube.com/watch?v=Cyxixzi2dgQ where it is very easy to see framedrops), and video-taping it in slow-motion, I get occasional (about once every 30 seconds) frame drops that are not registerd on mpv/iina's osc. This happens regardless of the config used (I have tried no-config, opengl-dumb-mode and with/without display-resample. It is more likely to happen when the stats panel of mpv is open.

The issue seems reproducible on both mpv and iina so I think it's likely an issue with the CAOpenGLLayer that both of them use, but I hesitate to open an issue upstream since it seems libmpv is being deprecated anyway. I was wondering if anyone else could reproduce this. My intuition is that it's somehow related to the timings of the glFlush compared to vsync boundary.

[low-batt]

On this:

it seems libmpv is being deprecated

Where can I find the announcement that libmpv is being deprecated?

It is likely the experts are overloaded with school or work or both and may not respond. This is outside of my technical expertise, but here are my thoughts anyway…

I am typing this on a MacBookPro18,2 with the Apple M1 Max chip. I'm currently still on macOS Ventura as I read some reports of problems with macOS Sonoma related to closed clamshell mode. @svobs has upgraded and is experiencing a problem I have not been able to reproduce. You caught us wondering if it is due to Sonoma. I am going to have to upgrade at some point and see if that causes the problem to appear for me. Back to the problem at hand…

I have not been too concerned about details on how IINA is managing the display on the new MacBook Pros because of the following from MacBook Pro (16-inch, 2021) - Technical Specifications:

Refresh rates

• ProMotion technology for adaptive refresh rates up to 120Hz

An unfortunate choice for the name of this display feature as if you search for ProMotion you will have to dig through a billion hits from marketers.

The WWDC 2021 video Optimize for variable refresh rate displays discusses this feature from a developer's perspective. Thus, when it comes to properly handling display refresh on the MacBook Pros there is definitely work to do.

The root cause of problems that are reproducible with mpv are almost always in code that is not a part of the IINA project and must be reported "upstream". As you are able to reproduce it directly with the mpv player, the state of support for libmpv does not matter. I would enter a mpv issue for this.

[krackers]

Thank you for responding:

Where can I find the announcement that libmpv is being deprecated?

It was not an official announcement, it was the sense I got based on #12486. My guess is that once the moltenvk backend becomes ready they will probably add support for wid embedding, and that will remove the remaining use-case for libmpv vo. But this is only conjecture.

reports of problems with macOS Sonoma related to closed clamshell mode

Not sure if it is the issue you are talking about but when switching into/out of closed clamshell mode with external display I've had to manually restart the Dock process. Sometimes peripherals don't recognize input either and I have to disconnect/reconnect a few times.

ProMotion technology for adaptive refresh rates up to 120Hz

I was actually testing and reproduced this on a fixed 59.995Hz external display. I did some experimentation with a plain NSOpenGLView (where you have more precise control over swap timings) and it seems that maybe since Ventura even an NSOpenGLView is layer-backed by default, as I have not been able to cause tearing even with the swap interval param set to 0. (Also another well known issue with OpenGL on Ventura+ is that the swap-interval = 1 param to enable vsync is broken, as it gives you twice the fps it should). My findings seemed to indicate that with these layer backed views, there is no "blocking" if you try to swap with an already-busy back-buffer. In this scenario the layer will just silently drop the frame. I'm still trying to investigate why such a scenario happens, since I was seeing that in some cases frames were not ready to be submitted before the next display link callback (about once every 15-20sec).

I wonder if https://forum.juce.com/t/poor-performance-with-opengl-renderer-on-apple-m1-machines/48725/12 is possibly related 🤔

Edit: I added some tracing/logging code, and here is what i see

Waiting for displaylink: 12409.333333
Flushing drawable: 489.541667
	Total presentation time: 12908.958333

Waiting for displaylink: 13021.625000
Flushing drawable: 18046.541667
	Total presentation time: 31087.083333

Waiting for displaylink: 13477.833333
Flushing drawable: 477.375000
	Total presentation time: 13967.041667
	Vsync skip detected, delta 800000


Wait for cvdisplaylink time 13393.375000
Flush drawable time 416.375000
	...

So it's the opengl flush that ends up occasionally blocking for 4 times longer than it normally does. And this happens whether or not swapInterval is set to 0.

[low-batt]

On libmpv deprecation, my reading of #12486 is not that there is a plan to deprecate it, although there are some voices suggesting that, the issue is about having technical difficulties finding a way to support a render API for GPU Next. That is very concerning, but not as bad a declaration that is it not possible. Hopefully a solution will be found.

Although most reports I've read about macOS Sonoma were good, there were a number of posts on MacRumors that made me concerned enough to decide to drag my feet for a while before upgrading. I don't remember the details now, but closed clamshell mode was mentioned and as I frequently operate in that mode I didn't want to deal with such problems.

You are definitely more than an expert than me in this area. Apple made lots of changes to graphics for macOS Ventura as a part of Metal 3 that definitely introduced regressions. @svobs mentioned seeing new Metal related messages in the log files after upgrading to Sonoma.

Thanks for posting the link to the JUCE issue. Definitely could be applicable.

I have experienced very noticeable video pauses when leaving IINA running for a long time with many windows open (only one playing). It is as if some periodic task is holding a lock and blocking rendering threads. I have wondered if this problem is always there, but difficult to notice until it gets really bad. From what I recall the time between pauses was longer than 15-20 seconds, but there is something going on that can disrupt rendering.

[krackers]

Thanks for posting the link to the JUCE issue. Definitely could be applicable.

After some more experimentation, I definitely think that what they were discussing is related to the issue I'm observing. As they suggested I used Instrument's CPU counters to identify whether threads were being executed on the P or E core. And I saw that while majority of the time the VO thread was running on the performance cores, it was occasionally running on the efficiency cores. The fact that the VO thread waits for mutexes and yields the cpu a lot probably causes the system to move it to the efficiency core. This also aligns with the timing of the frame delays I'm seeing (they aren't related to the complexity of the video, but seem like random scheduling delays).

As they suggested I tried setting an explicit QOS on the VO thread. As Apple describes in https://developer.apple.com/documentation/apple-silicon/tuning-your-code-s-performance-for-apple-silicon it seems the scheduler takes the QOS into account when determining which core to schedule the thread on. This helped a lot (reduced the number of delayed frames from ~1 in 15-20 sec to ~1 in 30-45 sec). Unfortunately there does not seem to be a way to set affinity to pin a thread to the performance core, so this is the best I could do.

I have wondered if this problem is always there

The issue you described seems like it could possibly be related as well, if the VO thread gets stuck on the efficiency core for a while. I wish I still had a Ventura machine so I could test whether the issue I'm describing existed even in Ventura or whether it's Sonoma that's especially sensitive to this scheduling. If someone is curious and has time to experiment, it's easy enough to check: you can load the clock tick video and film it in slow-motion, to see if there are any frame drops or delays. I recommend also enabling the stats overlay (shift+i in mpv, also in iina after enabling the mpv osd) since it seems to trigger the issue more frequently (stats overlay rendering uses cpu-heavy libass which results in reduced leeway for frame timing).

[low-batt]

I tested using closed clamshell mode attached to a 27" Apple/LG UltraFine 5K monitor. Super busy today and I have run out of time to carefully review the screen capture. Hopefully I can find time tomorrow.

[low-batt]

Reproduced.

Here is what I did. I performed this test on my MacBookPro18,2 with an Apple M1 Max and 64 GB memory which is still running macOS Ventura 13.5.2. I attached the Mac to my 27" 5K UHD UltraFine™ IPS Monitor with macOS Compatibility (60hz refresh rate). In System Settings on the Battery tab Energy Mode for On power adapter was set to Automatic. I performed the test in closed clamshell mode.

I downloaded YouTube 60fps Tester. I started IINA 1.3.3 playing the video. With IINA configured to use the mpv key bindings I pressed ⇧i to display statistics. I then opened Screenshot and started a screen recording of IINA. Once the video finished I reviewed the screen capture at 0.02x. A very tedious exercise. A good ways into the test I noticed a tick was skipped over. The statistics still showed 0 for dropped frames.

The following is a second screen capture, this one shows me stepping forwards and backwards by individual frames around the skipped tick while reviewing the screen capture of the test.

discussion-4652-tick-skipped.mov

Does this sound like a valid test? Did this reproduce what you are reporting?

MediaInfo reports the video downloaded from YouTube as having a variable frame rate. Not sure if that is impacting the test:

Frame rate mode                          : Variable
Frame rate                               : 60.000 FPS
Minimum frame rate                       : 58.824 FPS
Maximum frame rate                       : 62.500 FPS

Full MediaInfo Output:

low-batt@gag youtube-dl$ mediainfo YouTube\ 60fps\ Tester\ \[Cyxixzi2dgQ\].mp4 
General
Complete name                            : YouTube 60fps Tester [Cyxixzi2dgQ].mp4
Format                                   : MPEG-4
Format profile                           : Base Media
Codec ID                                 : isom (isom/iso2/mp41)
File size                                : 2.57 MiB
Duration                                 : 1 min 0 s
Overall bit rate                         : 360 kb/s
Frame rate                               : 60.000 FPS
Writing application                      : Lavf60.3.100

Video
ID                                       : 1
Format                                   : vp09
Codec ID                                 : vp09
Duration                                 : 59 s 999 ms
Bit rate                                 : 220 kb/s
Width                                    : 1 280 pixels
Height                                   : 720 pixels
Display aspect ratio                     : 16:9
Frame rate mode                          : Variable
Frame rate                               : 60.000 FPS
Minimum frame rate                       : 58.824 FPS
Maximum frame rate                       : 62.500 FPS
Color space                              : YUV
Bits/(Pixel*Frame)                       : 0.004
Stream size                              : 1.57 MiB (61%)
Title                                    : ISO Media file produced by Google Inc. Created on: 10/16/2023.
Color range                              : Limited
Color primaries                          : BT.709
Transfer characteristics                 : BT.709
Matrix coefficients                      : BT.709

Audio
ID                                       : 2
Format                                   : AAC LC
Format/Info                              : Advanced Audio Codec Low Complexity
Codec ID                                 : mp4a-40-2
Duration                                 : 1 min 0 s
Bit rate mode                            : Constant
Bit rate                                 : 128 kb/s
Channel(s)                               : 2 channels
Channel layout                           : L R
Sampling rate                            : 44.1 kHz
Frame rate                               : 43.066 FPS (1024 SPF)
Compression mode                         : Lossy
Stream size                              : 938 KiB (36%)
Title                                    : ISO Media file produced by Google Inc.
Default                                  : Yes
Alternate group                          : 1


low-batt@gag youtube-dl$ 

I remember quite a while ago hacking mpv sources to change thread QOS. At the moment I can't remember what the issue was. I vaguely remember it did not seem to change whatever behavior I was investigating.

I recently acquired a used MacBook Pro with an Intel chip to be able to investigate trouble with hardware decoding that only reproduced on Intel Macs. That one is also running macOS 13.5.2. Was planning on upgrading that one to macOS Sonoma. Just haven't had time. I will try and find time to run this test on that Mac.

On the problem I mentioned with the video freezing when IINA has been running for a long time with many windows open and minimized to the dock and one playing, that occurs on my MacBook Pro from 2019 running macOS Catalina 10.15.7. I have not experienced it on my M1 MacBook Pro, but I'm always having to stop and start IINA. I just tried opening a lot of videos at the same time on my M1 Mac. The problem did not reproduce, but this isn't exactly the same scenario as when I experience the problem on my old machine, IINA has been running for a very long time.

I have noticed that on the old MacBook Pro Activity Monitor shows half of IINA's memory as being compressed, whereas in the above test on my M1, no memory was listed as compressed. Both machines have 64 GB. So either macOS has changed to not be as aggressive in compressing memory, or macOS is basing the decision to start compressing memory on the app being idle for a long time. The concern is that execution gets blocked while macOS is uncompressing pages. Possibly something like that is going on.

Given that, it may be a separate problem that is not a factor in the problem at hand.

[krackers]

Does this sound like a valid test?

Yes, that is a wonderfully thorough reproduction. I actually used a smartphone to record at 240fps in a slow-motion capture, because I did not know if using screen recording could impact the results. The 240fps capture also makes dropped or delayed frames stand out more. I additionally used video-sync=display-resample mode instead of video-sync=audio because frame-dropping when playing 60fps video on a 60hz screen with video-sync=audio is not by itself unexpected (although mpv not detecting the frame drop is). display-resample is also more sensitive to the timing of reported page flips, so if that is subtly incorrect it will be more likely to reproduce the problem in this mode. I apologize for not more carefully describing my test conditions.

the video downloaded from YouTube as having a variable frame rate

This is a good point, I did not consider if this would play any role. Let me perhaps try re-running after transcoding to a fixed 60fps.

hacking mpv sources to change thread QoS

For the case of a libmpv client, one would only need to change QoS of the thread the client does rendering on (since the rendering is done on a thread that the client supplies).

Do you know whether Intel macs use the same GL -> Metal translation layer that M1 macs do? (And from which version of macOS this started being used?). Ideally we could examine the following combinations:

• Intel mac (native OpenGL)
• Intel mac (GL -> Metal translation layer)
• Intel mac (vulkan -> metal layer)
• M1 mac (GL -> Metal translation layer)
• M1 mac (vulkan -> metal layer)

To try to determine if this is an Intel vs M1 issue, a symptom caused by use of the translation layer, or whether in fact this issue existed all along but was never noticed (not many people video-tape spinning clocks, so it could easily go unnoticed).

[low-batt]

I was worried screen capture might interfere. At best my old iPhone might be able to do 60 fps. I will have to see what else I have for recording movies.

I downloaded again specifying the following to obtain AVC encoding instead of VP9:

yt-dlp -f 298+bestaudio  https://www.youtube.com/watch?v=Cyxixzi2dgQ

MediaInfo does not report this version as variable:

Frame rate mode                          : Constant
Frame rate                               : 60.000 FPS

Need to move away from VP9 to test on the Intel Mac with hardware decoding enabled.

I have never found any discussion about how Apple is continuing to support OpenGL. So news to me they are using a translation layer.

I will improve my testing methodology and test this on my Intel. Super busy these days. I may not get to this until the weekend.

[low-batt]

This is the DispatchQueue used for rendering:

iina/iina/ViewLayer.swift

Line 17 in 2ec4e36

let mpvGLQueue = DispatchQueue(label: "com.colliderli.iina.mpvgl", qos: .userInteractive)

[krackers]

Good catch, I guess iina is already using highest QoS for the render dispatch queue then. (The native mpv vo=libmpv cocoa backend does not set any priority however).

I'm experimenting with a possible solution that seems to fix the dropped frames, but it requires some breaking changes to the libmpv backend itself so I don't think they will be accepted upstream. Basically the current libmpv backend does not take into account the render time when reporting the last present timestamp, it simply waits until the next vsync and makes the assumption that all rendering was done before then. This works most of the time, but sometimes this assumption is incorrect and you can thus end up doing another draw while the previous one has not finished yet. Normally with opengl the new draw would block until a backbuffer is free, but CAOpenGLLayer is "special" in that it always provides a new buffer to draw into, so it never blocks (instead opting to silently drop frames if needed). In fact I was able to replicate this "silent dropped frame" issue all the way back on 10.8, so this is neither an M1 nor a Sonoma specific issue, it is intrinsic to the (mis)use of layer-backed opengll view.

Edit: Well actually it's probably possible to do it without changes on libmpv side, just modify the displaylink callback to only fire after a flush. It's a bit uglier though, I prefer having all the state on the libmpv side.

Unfortunately even with the above fixed I've been seeing another typed of occasional dropped frame (which also seems to involve audio discontinuity). It's not clear to me yet if this was introduced because of my fix for the above or it coincidentally happened with the upgrade to Sonoma. I will do more investigation here, it happens so rarely that it is difficult to add logging. (I suspect it's somehow related to a scheduling issue, as dropped frames don't normally affect audio. Moreover the logging I added showed that during that period render times were within 1 vsync, but the problematic render cycle happened 10 vsyncs after the last render, which seems to indicate a playloop related issue.