Increasing Video Speed and holding down seek arrow keys leads to IINA freezing #5403
Comments
|
Thank you very much for reporting this. Good/bad timing to report this. We had been delaying fixing many thread related problems until a major release that includes using beta releases due to the danger of fixes that work fine on developer's Macs, but fail on user's Macs due to it requiring just the right timing to trigger the problem. Thus fixing problems related to threads carries with it the risk of introducing regressions that get past developers. The development version of IINA contains many major changes in the handling of threads to address multiple problems. We have been worried about the exact kind of problem you are reporting. This is good timing for such a report as the beta has not been released. However this is super bad timing for this report in that the beta is on its way out the door. I will be labeling this as high priority. Hopefully we can quickly get to the bottom of what is happening. But this did not reproduce for me. I started a video playing using IINA Nightly @193eee4. Under the I did sometimes see some behavior I didn't like. Not most of the time, but some of the time while holding down the ➝ key the cursor would turn into the spinning beach ball of death. After letting go of the key IINA would recover. That indicates the main thread is overloaded or blocked. Not clear if that is related to the issue at hand or just a performance problem with being bombarded with key press events. With respects to the freeze is IINA permanently frozen? Is it that just playback is frozen? Or is the UI also not responding? Is the spinning beach ball of death cursor being displayed? To investigate what is going on I need a process sample taken when IINA is frozen along with logs. See these FAQs: |
|
Sorry didn't describe the freezing that well, if i hold down the seek key in x2 speed while the video is still playing and release it the video continues to play normally and you can hear audio normally, but i get the macOS beach ball of death and IINA will not respond to key presses or mouse clicks (The window can still be moved though). The long seek becomes succesful once the beach ball of death dissapears, and you can use IINA normally again, but it seems to become easier to trigger a subsequent beach ball freeze in normal use (I may be imagining this). If I keep doing the long held seek I eventually get a really long beachball, and force quit the app. It's posssible that beach ball would dissapear if you're patient enough. I've also now noticed the beach ball behaviour will trigger while setting the video speed to normal, but the beach ball seems to go away quicker and isn't as significant as when you have x2 speed. I tried an old build of IINA 1.3.5 with mpv 0.35 I had, and experienced no freezing/lag when spamming hold seek like this regardless of video speed. I think the issue is related to IINA builds with mpv 0.38 and the commits I mentioned. Hope the above helps in debugging this, I'm running a MacBook Pro Apple M4 Pro (Model Identifier: Mac16,8), hopefully I'm not wasting your time with an issue isolated to me. |
|
Thanks for posting the info. On this:
Do not worry about that at all. I know some projects are rather picky about what constitutes an issue. The IINA project is friendly. Is IINA behaving in an odd way and it is not clear why? Valid issue. Doesn't matter if it is due to something special about your Mac and what is installed on it. In this case with IINA 1.3.5 not exhibiting the problem, this is definitely something that needs to be explained. It sounds like I was reproducing the problem when I triggered the beachball cursor, just not as bad as you are experiencing. I looked at the first sample and it shows the main thread being held up. This gives me something to investigate. I'll have to take a real close look at the log, the samples and the code changes. While you were collecting info I did try reproducing this on my other development machine, a MacBook Pro with the M1 chip running macOS Ventura. No luck triggering a beachball. That is another aspect of this that I'll need to explain. I'm certain this is not related, but are you using a modified key binding file? In the IINA log file there are errors being reported while parsing |
Yeah, I have nonsensical lines in my IINA bindings/input.conf, that i use as notes |
|
Ah. If you prefix text with |
|
You provided two process samples. What was the state of IINA when you took the second sample? Have you enabled Vocal Shortcuts? I can't tell from your profile how much you know about software, so forgive me if you are already familiar with process samples… Imagine a factory. You are on the outside. You want to know what is going on in the factory. There is a window. It is too high for you to see through it. But if you jump up you can get a very quick peek at what the employees are doing. If you jump up and down a lot recording each time where each employee is you sort of get a feeling of the work they are doing. That is what taking a sample of a process does. It records where each thread (think employee) is in the code each time it samples the process. The main thread is special. Think about it as the representative answering the phone at the factory. You never want that employee working on a task that takes a long time to complete as then the phone is not answered and calls are dropped. When macOS displays the spinning beach ball of death it has been more than two seconds since the main thread serviced the event loop. The process sample report has a section for each thread. The start of the entry for a thread looks like this: The Think of the indented list under a thread as the path the employee took through the factory to get to where there were seen. The number will decrease because some of the time the employee was somewhere else. If all the entries show the same number then that employee never moved in all the time we peeked at the factory through the window. Every entry for the main thread in sample 2 is in the same spot. So the main thread was blocked for the entire 7+ seconds while the sample was taken. This definitely triggered the beachball cursor. For apps to be able use macOS features such as windows and menus Apple provides the AppKit Framework. Typically you see IINA code calling into AppKit code. In this case nearly all the code is AppKit code. I have to guess at what is going on from the names of the methods in the code. The method The method The method Then we get to This seems like code in support of Vocal Shortcuts, which is a new feature as of macOS Sequoia. Hence my question about whether you have enabled this feature. If it is not enabled (see instructions in that Apple support article) then it could be that the client is "dumb" and always sends this message. My guess is that the message is going to some macOS daemon, probably one of the Siri related ones and that daemon has failed to respond, or is responding very slowly. The log shows this was run on macOS 15.2. The latest version is macOS 15.3.1. Are you intentionally holding off on installing macOS 15.3 because Apple is rudely opting everyone who installs 15.3 immediately into Apple Intelligence? That would have been a consideration for me, but I am running Sequoia on an Intel Mac and AI requires Apple Silicon. I always hate being opted into stuff. As vocal shortcuts are new as of Sequoia there could be bugs in this area of macOS. Possibly upgrading macOS will help. Hard to tell since the macOS release notes say so little about the update. Vocal shortcuts also require Apple Silicon. If it is playing a role then that would explain why my Macs do not reproduce the problem. There is a lot going on in the first process sample. I'm still analyzing that one. Stay tuned. Main thread: |
|
I think both samples were similar instances of a beach ball occuring when trying to do long held seeks. I have Siri disabled but do turn Accessibility > Voice Control on sometimes, it was off when the samples were taken. I usually avoid upgrading macOS if I can help it, as I find it a hassle for the reasons you described. I I tried the latest nightly build on a 2019 Intel Macbook Pro running Big Sur, and could reproduce the beach ball effect but it happened less frequently and went away quickly and was nowhere near as bad as the M4 Macbook. I'm usually using a seek relative+exact custom keyboard shortcut rather than the default IINA seek. On the M4 Macbook the beachball occurs regardless of the seek type I'm using. In my limited testing on the Intel Macbook I couldn't get a beach ball when using seek relative+exact, only got it when using the default IINA arrow key seek. |
|
Managed to stop the beach balling, by editing ViewLayer.swift: Using either of the below versions stops the beach balling for me, and allows x2 speed videos to seek like x1 videos override func display() {
override func display() {
// displayLock.lock() // removed
defer { displayLock.unlock(); }override func display() {
displayLock.lock(); Logger.log("locking Display")
defer { displayLock.unlock(); Logger.log("unlocking Display") }Still have a slight issue where if I hold down the normal arrow seek key and release it, and then press another key straight away (e.g. pause) it takes a second for the pause to trigger, the effect is amplified if the video is at x2 speed, almost like the timing is off? The IINA playback title in the menubar is still highlighted for a few moments when you release the arrow key, so i think it's doing a few extra seeks after you release the key, hence the delay with the next event being actioned (e.g, pause). The issue doesn't occur if i use "relative+exact seek". Any idea on changes I can make to MPVController.swift or PlayerCore.swift to prevent this issue with default arrow seeking? It may be related to this as the build before it does not have the delay with the next key being actioned once a long seek hold is released. |
Managed to fix this too, just need to remove the below line in PlayerCore.swift: func playbackRestarted() {
log("Playback restarted")
reloadSavedIINAfilters()
// mainWindow.videoView.videoLayer.draw(forced: true) // removed
if RemoteCommandController.useSystemMediaControl {
NowPlayingInfoManager.updateInfo()
}
DispatchQueue.main.asyncAfter(deadline: .now() + 0.2) { self.info.disableOSDForFileLoading = false }
}Thanks for your help! It'll be interesting to see if other people have these issues in the next official release. Hopefully long term, I don't run into any unintended/buggy behaviour, due to the changes I made. |
|
I'm hearing the second sample was taken during the same test run. That is very interesting. The Vocal Shortcuts problem might be a side issue. The quality of macOS updates is a problem. My M1 machine is still running Ventura because I have been having to compare Ventura to Sequoia when investigating Sequoia regressions. Apparently Sequoia is sometimes dropping mouse tracking areas. In one case IINA stopped receiving mouse events. Works fine in Ventura. IINA now has a workaround to re-establish the mouse tracking area. I suspect this might be why hot corners in Sequoia sometimes stopped working. Do you have hardware decoding disabled in IINA's preferences? Not that that is a problem. Just trying to match my configuration with yours. Without Your analysis is correct as to the changes to the code that are involved in the current behavior. Trouble is so far those changes do not appear to be incorrect. And they don't appear to be causing a problem running under macOS Ventura. The locks are required to solve data races between threads. Data races can cause incorrect behavior and crashes. For a program to be reliable you can't tolerate having data races between threads. Because the timing has to be just right for problems to occur, with these locks removed IINA will work most of the time. The first process sample shows the main thread 1513 out of 5579 samples, about 27% of the time, waiting for the display lock: In the process sample I took under Ventura this code did not appear. So the current question is what changed in Sequoia to cause the main thread to wait on this lock. On this: override func display() {
override func display() {
// displayLock.lock() // removed
defer { displayLock.unlock(); }The This post might be a little incoherent. I'm not quite awake yet. Will continue to investigate. |
|
I have hardware decoding disabled. Unfortunately, I have no recollection of if i took the samples during the same IINA session, but both sample launch times are identical, and I think it's likely I did. When i was trying to take the samples I would trigger the beach ball, then run the sample command in terminal and then the beach ball would sometimes go away as soon as I ran the command (maybe a coincedence, maybe not?) or the beach ball just wouldn't last very long after running the sample command. So I would try to trigger a longer beach ball and then take another sample. So the first sample is probably the beach ball going away quickly, and the second sample was me trigerring a longer beach ball and then taking another sample. Again, I can't really remember. When trying to trigger a beachball, sometimes I would hold forward seek for a while, let it go and then hit backward seek straight away, hold it for a while and let it go. Maybe this will help you in triggering it more often? |
|
Thanks for the tips! And yes, one of the problems with investigating performance is that techniques used to inspect the app's behavior may alter the app's behavior. I keep forgetting to thank you again for reporting this and helping with the investigation. I'm currently playing with instrumenting the code to gather more information. |
|
Please try this experiment… Change IINA's settings:
If seeking takes too long then it is more likely that another seek request will arrive before playback can restart. Hardware decoding should speed up seeking. The IINA default key bindings do not use exact seeks which are slower. While seeking we want playback to restart as that exercises locking. Confirm the problem still reproduces with an unmodified IINA. Then in if info.state == .paused {
mainWindow.videoView.videoLayer.draw(forced: true)
}Make no other changes. Do not comment out the code that locks . Try to reproduce the problem. Especially on your M4. If the beachball appears please capture a process sample. I'm expecting you won't see the beachball on your Intel Mac. On the M4 I'm unsure due to that sample that seem to show something is going on with Vocal Shortcuts. I added code to measure how long threads were waiting to acquire the Once the seeking / playback restart cycles start there is contention for the lock and it takes significantly longer to aquire the lock. What I don't understand is why the The DispatchQoS of the Just as an experiment I greatly lowered the QoS of the let mpvGLQueue = DispatchQueue(label: "com.colliderli.iina.mpvgl", qos: .background)With the lowered QoS the wait times were closer: I'm not sure how to interpret this evidence. This is the code I added to VideoLayer with Locking Statistics: private class Stats {
var locked: UInt64 = 0
var elapsed: UInt64 = 0
}
private var threadToTotalElapsed: [String: Stats] = [:]
private var lockCount = 0
private let info: mach_timebase_info = {
var info = mach_timebase_info()
guard mach_timebase_info(&info) == KERN_SUCCESS else {
Logger.fatal("mach_timebase_info failed")
}
return info
}()
override func display() {
let start = mach_absolute_time()
displayLock.lock()
let end = mach_absolute_time()
let queueLabel = String(cString: __dispatch_queue_get_label(nil))
let stats = { [self] in
guard let entry = threadToTotalElapsed[queueLabel] else {
let entry = Stats()
threadToTotalElapsed[queueLabel] = entry
return entry
}
return entry
}()
stats.locked += 1
stats.elapsed += end - start
lockCount += 1
if lockCount == 100 {
lockCount = 0
guard let maxQueueNameLength = threadToTotalElapsed.max(by: { $0.key.count < $1.key.count} ) else{
Logger.fatal("threadToTotalElapsed.max returned nil")
}
var message = "Locking statistics:"
let sorted = threadToTotalElapsed.sorted(by: { $0.0 < $1.0 })
sorted.forEach { queue, stats in
let spacer = String(repeating: " ", count: maxQueueNameLength.key.count - queue.count + 1)
let nanoseconds = stats.elapsed * UInt64(info.numer) / UInt64(info.denom)
message += "\n \(queue)\(spacer)Locked \(String(format: "%2d", stats.locked)) times average wait \(nanoseconds / stats.locked) ns"
}
Logger.log(message)
threadToTotalElapsed = [:]
}
defer { displayLock.unlock() } |
After doing the above on the M4 I can confirm the beach ball problem still reproduces with an unmodified IINA. Setting
After adding the above, with no other changes to the latest nightly build, the beach ball effect is non-existent and long hold seeking at x2 speed is very smooth, and as soon as I release the seek and press another key (e.g. paused or change speed), it's actioned instantly. Switching hardware decoding between auto or off didn't affect anything. I also added your ViewLayer.swift logging code to a default nightly build with no other changes, it seemed to reduce the beachball effect as I could no longer trigger a very long beachball just shorter ones, the beachballs also triggerred less often with the logging code. Haven't done any tests on the Intel MacBook, but I don't imagine it'll have any beach balling if you add the if info.state == .paused { } wrap. Genius solution, would you have figured out Sorry I couldn't test this sooner, had to go to work... |
Not a problem! You help is very much appreciated! Early on I was expecting that change might be needed, but I really resist jumping ahead to a proposed fix until I've investigated and can explain why the fix is needed. I still have to check with the senior developers as to whether that can be used as a fix. I was impressed that you quickly and correctly traced the problem the offending code. It helped me that you had already confirmed with tests that the locking was causing the issue. I had the advantage of having been in this code. But I did not expect the severe contention for the lock. Especially that the main thread was being blocked for so long when things are under heavy load. Those configuration changes were intended to make the problem worse in order to test out the fix. The logging changes were just a temporary hack for debugging to get an idea on what was happening with the lock. One of the downsides of adding code to check on performance issues is that it can alter the behavior you are trying to investigate. I did not explain why mpv did not exhibit this problem. That has to do with IINA issue #5038 and I believe mpv miss-interpreted the role of this tool. It is easy to accidentally create an implicit CATransaction with a thread other than the main thread. So this tool helps you find such possible errors. However it is not wrong or invalid to create implicit transactions on a thread other than the main thread. It is possible to use a secondary threads for drawing. I believe this means that if you are using secondary threads you should be creating explicit transactions as a best practice. But it could be I am misinterpreting this. I wish I could find Apple documentation on this. Because mpv is only using the main thread it avoids the need for the locking IINA is doing. IINA discussed switching to just using the main thread. But IINA has a more complex UI, so there is a concern about overloading the main thread. We held off for now, but at some point we may reconsider as it is desirable to match up with how mpv handles things. We still have the mystery of the freeze shown by the second process sample. My guess on that is that under load an event queue overflowed and the main thread was stuck waiting for a response that never came. A problem with Vocal Shortcuts Apple will have fix. Just a guess. Next step is for me to check in with other IINA developers. |
|
That change to add an @uiryuu Rescued me and educated me on why this code is needed. Apparently it was originally added in commit 82eed2d to
I also found an older commit that attempted to address the problem, commit 9a5530a, by adding this to // force redraw to clear any lingering content in the
// video layer if the view is being recycled
if loaded {
videoView.videoLayer.draw(forced: true)
}I believe these changes attempted to address issues #2402, #2469 and #2197. To see the problem this code addresses comment out this line in mainWindow.videoView.videoLayer.draw(forced: true)Build IINA and then follow these instructions to reproduce the problem:
The expected behavior in this case is that the window is black when the audio file does not contain any picture or video streams and you force IINA to use the main window instead of the music mode mini window. So the forced drawing is required when there isn't a video stream. The code in
As you can see that event is delivered after most seeks causing the performance problem at hand. As the forced draw is only needed once to clear the display I was thinking the forced write could be moved to
That worked and blacked out the window. But album covers are no longer initially displayed. Continuing to investigate… |
This commit will: - Move the call to force drawing from playbackRestarted to fileLoaded in PlayerCore - Add a windowDidChangeOcclusionState method to PlayerWindowController that forces drawing - Add calls to force drawing in windowDidEnterFullScreen and windowDidExitFullScreen in MainWindowController This corrects the performance problem when repeatedly seeking. And restores calls to force drawing removed in commit 0107e9d.
AnalysisA summary of the discussion above as well as some discussion on how the mpv player uses forced drawing. The root cause of the performance regression when holding down the → key to scrub through the video was the addition of the following locking in override func display() {
displayLock.lock()
defer { displayLock.unlock() }This locking is required and corrects data races; it can't be removed. Under load the main thread is spending too much time waiting to acquire the lock. The lock is being taken and released over and over again by the The main thread calls to Although IINA differs some from mpv, the mpv player is the authoritative source for proper use of // Execute a forceful refresh of the VO window. This clears the window from
// the previous video. It also creates/destroys the VO on demand.
// It tries to make the change only in situations where the window is
// definitely needed or not needed, or if the force parameter is set (the
// latter also decides whether to clear an existing window, because there's
// no way to know if this has already been done or not).
int handle_force_window(struct MPContext *mpctx, bool force)That method is called when transitioning to the next file. The drawing required to display album cover art is done by the override func windowDidChangeOcclusionState() {
layer?.update(force: true)
}IINA currently does not force drawing when the occlusion state changes, explaining why moving forced drawing out of |
IINA Version
IINA - latest nightly - 193eee4
Release Channel
Nightly
macOS Version
15.2
Steps to Reproduce
If I set video speed to 2 (the only speed I tested), and hold down the arrow seek key for a while (while the video is unpaused) and release it IINA will freeze most of the time.
Expected Behavior
The video should seek the same way it does when you hold down an arrow key and the video speed is normal, without freezing.
Actual Behavior
IINA will freeze
Crash Report or Process Sample
I believe it may be related to this commit
The commit before it doesn't seem to have this issue. However this commit has a different issue where the video will freeze for a few seconds everytime you change video speed.
Logs
No response
Sample Files
No response
How often can you reproduce the issue
Most of the time
Required Actions
Optional Actions
The text was updated successfully, but these errors were encountered: