iina
iina copied to clipboard
CarterLi
Closing and opening files leads to Iina to crash and not respond
When files are opened and closed successively, Iina freezes on opening a file and then doesn't respond.
System and IINA version:
- macOS 12.1
- IINA v1.2.0-21
Expected behavior: Doesn't crash/freeze
Actual behavior:
Iina crashes and freezes on quickly opening and closing files.
Crash report:
Sample of IINA.txt Spindump.txt Spindump2.txt
Steps to reproduce:
Keep opening and closing a file (doesn't require much but 3 cycles for me)
- [x] MPV does not have this problem.
How often does this happen? Always
PS : File responsible hxxps://nyaa<.>si/view/1390968
IINA v1.2.0-21 is from 6 days ago and is missing the fix for my fix from 4 days ago. This report got me to look at the fix again and I've just pushed another commit that tweaks it some more to hopefully make really sure the hang is fixed.
@CarterLi Please create a new build when you get a chance.
IINA v1.2.0-21 is from 6 days ago and is missing the fix for my fix from 4 days ago. This report got me to look at the fix again and I've just pushed another commit that tweaks it some more to hopefully make really sure the hang is fixed.
@CarterLi Please create a new build when you get a chance.
I'd like to use Github Actions building M1 versions when supported. Ref: https://github.com/actions/virtual-environments/issues/2187
Spindump.txt @low-batt still crashes with the file linked above (would rec downloading it if possible)
@ViRo3, @CarterLi New plan. Stablize IINA-Plus:
- low-batt abandons attempts to fix iina#3601
- low-batt backs out faulty fix
- CarterLi creates a new build
- ViRo3, CarterLi, low-batt validate new build does not hang
I've just pushed a commit that backs out the changes made to fix iina#3601. Need a new build.
The issue iina#3601 is about wasting a minor amount of energy. Desirable to eventually fix, but not critical to fix it right now with the "fix" causing so much trouble. Unfortunately the timing on my Mac is such that so far I've not been able to reproduce these hangs. So I've been taking a "stab in the dark" as to what is going wrong and how to fix it. Clearly that is not working. More important to focus on other issues. I alway hate to give up on fixing an issue but that seems like the right decision on this one for now.
I did leave in one change made as a part of this fix which was to add guarding that videoPosition is available in PlaybackInfo.constrainVideoPosition:
guard let duration = videoDuration, let position = videoPosition else { return }
That seems like a safe useful change. The change that was triggering the problem is the attempt to stop and start the timer that synchronizes the OSC based on whether the OSC is visible or not. Backing out the change puts IINA back to updating the OSC even though it is not visible to the user. This wastes some energy, but the vast majority of CPU time consumed is in the code that displays the video.
By the way, there is an IINA hang out there lurking, the issue "Main thread hang in mpv_render_context_create during startup". So if IINA hangs during startup don't assume it was one of these recent issues. Always need a sample of IINA to have a chance of knowing what the issue is. I hit that hang once with the released version of IINA. I also hit it once with a development version of IINA using mpv 0.34.0. I made a concerted effort to reproduce it, running a test designed to trigger it thousands of times. No luck. Whatever that problem is, it is rare.
Yes, its a very specific file that completely freezes Iina. (Have link it above) so as such it isn't really a major issue
So It's not caused by fixing iina#3601.
Please test this version: https://github.com/iina-plus/iina/releases/tag/v1.2.0-25
I'm currently tired and may not be thinking straight...
From a quick look I am stunned and confused. The process sample shows the same main thread lockup with mpv_get_property waiting for a lock when called by PlayerCore.syncUI. I was expecting that was somehow due to my "fix" that changed how that method was used. I quickly checked MainWindowController on GitHub and it looked like I correctly backed out that fix.
This movie plays fine with the released verion of IINA? The hang only occurs with IINA Plus?
There is one other change in IINA Plus that has to do with PlayerCore.syncUI. The timer that runs this method to keep the UI in sync is now paused and restarted as you pause and restart the video. IINA Plus also has the changes related to the OpenGL context. I was not thinking this was related to that change as it is obvious in the spin dump when a thread is stuck waiting to lock the context. Of course the big change is that IINA Plus is using the latest mpv release, 0.34.1.
When exactly is this hang triggered? When it hangs what is the video doing? Just freezes?
I will be taking a closer at the other threads in the spin dump to see if I can spot something that looks wrong. Might have to pull some of these other fixes and see what effect that has on the problem. I guess we first see if the new build makes any sort of difference.
I encountered freezing after using DispatchQueue.main.async once and I did add a DispatchQueue.main.async block recently.
I just removed it. Let's see what's happening next
@ViRo3 Are you able to play the video using mpv without problems?
I'm thinking we should take a look at the IINA and mpv log files. Usually log files don't help that much with hangs. But if there is trouble with playback we might find some clues in the mpv log.
The sample shows the main thread completely locked up:
+ 2257 __NSFireTimer (in Foundation) + 104 [0x18a23e29c]
+ 2257 @objc PlayerCore.syncUITime() (in IINA) + 28 [0x1004595d4]
+ 2257 PlayerCore.syncUITime() (in IINA) + 56 [0x1004594e4]
+ 2257 PlayerCore.syncUI(_:) (in IINA) + 584 [0x10045982c]
+ 2257 mpv_get_property (in libmpv.1.dylib) + 92 [0x103664bec]
+ 2257 mp_dispatch_lock (in libmpv.1.dylib) + 188 [0x1036433cc]
+ 2257 _pthread_cond_wait (in libsystem_pthread.dylib) + 1228 [0x18925d808]
+ 2257 __psynch_cvwait (in libsystem_kernel.dylib) + 8 [0x1892250c0]
As I had just added a change involving PlayerCore.syncUI I assumed that was triggering the problem. Since backing that out didn't work I've been digging into mpv code.
This is the mpv method that is being called by IINA code:
int mpv_get_property(mpv_handle *ctx, const char *name, mpv_format format,
void *data)
{
if (!ctx->mpctx->initialized)
return MPV_ERROR_UNINITIALIZED;
if (!data)
return MPV_ERROR_INVALID_PARAMETER;
if (!get_mp_type_get(format))
return MPV_ERROR_PROPERTY_FORMAT;
struct getproperty_request req = {
.mpctx = ctx->mpctx,
.name = name,
.format = format,
.data = data,
};
run_locked(ctx, getproperty_fn, &req);
return req.status;
}
That method is stopped calling run_locked:
// Run a command in the playback thread.
static void run_locked(mpv_handle *ctx, void (*fn)(void *fn_data), void *fn_data)
{
mp_dispatch_lock(ctx->mpctx->dispatch);
fn(fn_data);
mp_dispatch_unlock(ctx->mpctx->dispatch);
}
That method is stopped calling mp_dispatch_lock:
// Grant exclusive access to the target thread's state. While this is active,
// no other thread can return from mp_dispatch_lock() (i.e. it behaves like
// a pthread mutex), and no other thread can get dispatch items completed.
// Other threads can still queue asynchronous dispatch items without waiting,
// and the mutex behavior applies to this function and dispatch callbacks only.
// The lock is non-recursive, and dispatch callback functions can be thought of
// already holding the dispatch lock.
void mp_dispatch_lock(struct mp_dispatch_queue *queue)
{
pthread_mutex_lock(&queue->lock);
So the main thread is blocked trying to run a get property request on the playback thread. Maybe this particular video is causing trouble for the playback thread.
@CarterLi I submitted a PR for IINA that has a simple workaround for iina#3211. Was not sure if we are currently holding off adding changes to IINA+ until we sort this issue? Or do you want me to add that fix?
By the way Daniel on Telegram said nice things about IINA+ HDR support.
@ViRo3 I've been hoping you would have time to see if you can reproduce the same problem in the mpv player. If mpv plays it without issues we focus more on how we are configuring mpv and interacting with it. If mpv has trouble that would explain our trouble trying to track down the problem.
@CarterLi I submitted a PR for IINA that has a simple workaround for iina#3211. Was not sure if we are currently holding off adding changes to IINA+ until we sort this issue? Or do you want me to add that fix?
Like I said before, this repo is built for experimenting latest features / bug fixes that may not be very stable. You may just push your changes. We can revert the change if it causes serious issues.
I was nervous due to the issues with my previous fix. This fix is small and should be safe. Just finished pushing it.
I was nervous due to the issues with my previous fix. This fix is small and should be safe. Just finished pushing it.
I'm very sorry that I removed your commit with a force-push by accident. Can you push it again?
Can you build iina-plus yourself now? You may make a new release if necessary @low-batt
It is painful for me to build the dependencies part as I operate under a limited account that does not have the access needed for brew, so I have to build that part under an admin account. I just tried and the build worked up to the very end which failed because it could not find create-dmg. I see some shell scripts with that name on GitHub. Where did you get it?
https://github.com/Homebrew/homebrew-core/blob/master/Formula/create-dmg.rb
brew install create-dmg
The problem is still reproducible right now.
Tested on version 1.2.0-22, 1.2.0-28 and 1.2.0-29. It's okay on IINA 1.2.0.
Unfortunately freezes can be very senstive to the specific timing of hardware and configuration and the like. So far I've not been able to reproduce this hang which makes it much harder to debug.
There is a ton of differences between IINA 1.2.0 and IINA+ builds. One major difference is that IINA+ uses the latest mpv. There are some known hangs in mpv. We are hoping someone can test and see if mpv is working fine on the same files or not just to confirm that it is something IINA is doing rather than something in the new mpv.
Hangs are hard to debug. With a hang we always need a process sample. To take a process sample bring up the Activity Monitor while IINA is frozen. Select IINA in the Activity Monitor. Then under the View menu select Sample Process. That should create a report like you see above. From that we should be able to tell if you are hitting the same freeze or not. It might or might not provide an additional clue to the problem.
I made more tests. It seems to be 100% reproducible for my environment, which is MBP M1 Pro.
Testing clip is LG Earth Dolby Vision Demo, but it actually freezes on many of my clips, if not all.
I tested mpv 0.34.1 prebuilt from here. It successfully quits without hangs or freezes. It's an x86_64 build. Sorry but I'm not able to find an arm64 binary distribution.
I made a process sample and pasted the text to this gist.
Config file used:
profile=gpu-hq
icc-profile-auto=yes
gamma-auto=yes
sub-auto=fuzzy
sub-codepage=utf8:gb18030
osd-font='PingFangSC-Light'
sub-font='PingFangSC-Light'
autofit-larger=90%x80%
hwdec=auto
Disable loading mpv config file doesn't help.
@John-He-928 Thank you so much for running these tests. Very helpful.
From the process sample this looks like my bad, not a mpv issue. It does not look like the same problem in the samples provided by ViRo3.
I'm trying to fix a crash that sometimes happens when you quit IINA. The problem occurs because IINA was telling mpv to quit, but not waiting for it to finish shutting down. Depending upon the timing of things that can cause IINA to crash out. When I changed IINA to wait for mpv that brought out some other shutdown problems.
This seems like something has gone wrong with waiting for mpv to finish. I just looked at this, so I'm going to have to think on what could be going wrong.
I've tried to obtain files from 4kmedia.org before. I'm seeing the same error I've seen in the past. Google Drive says:
Sorry, you can't view or download this file at this time.
Too many users have viewed or downloaded this file recently. Please try accessing the file again later. If the file you are trying to access is particularly large or is shared with many people, it may take up to 24 hours to be able to view or download the file. If you still can't access a file after 24 hours, contact your domain administrator.
I should be able to figure out this one without the video file. Stay tuned.
The code in AppDelegate used to look like this:
func applicationShouldTerminate(_ sender: NSApplication) -> NSApplication.TerminateReply {
Logger.log("App should terminate")
for pc in PlayerCore.playerCores {
pc.terminateMPV()
}
return .terminateNow
}
What was wrong with that is that terminateMPV did not actually terminate mpv. It started mpv terminating asynchronously in the background. This creates a race condition between background threads and the main thread. This would sometimes result in crashes.
That method now looks like:
func applicationShouldTerminate(_ sender: NSApplication) -> NSApplication.TerminateReply {
Logger.log("App should terminate")
for pc in PlayerCore.playerCores {
pc.terminateMPV()
}
// The call to terminateMPV instructed mpv to quit, but that is happening asynchronously in the
// background. Must wait for mpv to finish terminating before allowing Cocoa to terminate the
// application. This must be done in another thread to avoid blocking the main thread.
terminateQueue.async {
// Normally mpv will quickly terminate, but we will impose a time limit to insure termination
// of the application is not blocked.
Logger.log("Waiting for mpv termination")
let timeout = DispatchTime.now() + DispatchTimeInterval.milliseconds(500)
for pc in PlayerCore.playerCores {
let result = pc.waitForTermination(timeout: timeout)
if result == .timedOut {
Logger.log("Timeout waiting for termination of player core", level: .warning)
}
}
// Tell Cocoa to proceed with termination. This has to be done on the main thread.
DispatchQueue.main.async {
Logger.log("Proceeding with termination")
NSApp.reply(toApplicationShouldTerminate: true)
}
}
// Tell Cocoa that it is ok to proceed with termination, but wait for our reply.
return .terminateLater
}
It now submits a background task that waits for mpv to finish terminating. When that is done it submits a main thread task to inform the framework it can continue with termination.
The Apple documentation for the method applicationShouldTerminate discusses using terminateLater and then invoking reply(toApplicationShouldTerminate:) when the application is ready to terminate.
The IINA log shows the timeout kicked in while waiting for mpv to terminate and is missing the "Proceeding with termination" message:
03:15:45.197 [thumbcache][d] Finished reading thumbnail cache, 69 in total
03:15:45.274 [player0][d] Track list changed
03:15:47.075 [iina][d] App should terminate
03:15:47.076 [player0][d] Write watch later config
03:15:47.089 [iina][d] Waiting for mpv termination
03:15:47.594 [iina][w] Timeout waiting for termination of player core
Not sure why the mpv log has two entries mentioning running the quit command. That is unexpected. Maybe related to why termination timed out?:
[ 6.796][d][cplayer] Run command: quit, flags=73, args=[code="0"]
[ 6.797][d][global] config path: '/Users/user/Library/Application Support/com.colliderli.iina/watch_later' -> '/Users/user/Library/Application Support/com.colliderli.iina/watch_later'
[ 6.797][i][cplayer] Saving state.
[ 6.798][v][cplayer] EOF code: 5
[ 6.823][d][ad] Uninit decoder.
[ 6.823][d][vd] Uninit decoder.
[ 6.838][d][cplayer] Terminating demuxers...
[ 6.841][d][cplayer] Done terminating demuxers.
[ 6.841][v][cplayer] finished playback, success (reason 3)
[ 6.841][i][cplayer]
[ 6.841][d][ytdl_hook] Exiting...
[ 6.841][d][console] Exiting...
[ 6.841][d][stats] Exiting...
[ 6.842][d][cplayer] Run command: write-watch-later-config, flags=64, args=[]
[ 6.854][d][libmpv_render] flushing shader cache
[ 6.855][d][cplayer] Run command: quit, flags=64, args=[code="0"]
The process sample shows the main thread just waiting around:
+ 2515 -[NSApplication terminate:] (in AppKit) + 756 [0x1ab8027d8]
+ 2515 -[NSApplication _shouldTerminate] (in AppKit) + 1024 [0x1ab81206c]
+ 2515 -[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] (in AppKit) + 1332 [0x1ab57b584]
+ 2515 _DPSNextEvent (in AppKit) + 844 [0x1ab57cce0]
+ 2515 _BlockUntilNextEventMatchingListInModeWithFilter (in HIToolbox) + 72 [0x1b15b8a9c]
+ 2515 ReceiveNextEventCommon (in HIToolbox) + 552 [0x1b15b8cdc]
+ 2515 RunCurrentEventLoopInMode (in HIToolbox) + 292 [0x1b15b8f68]
+ 2515 CFRunLoopRunSpecific (in CoreFoundation) + 600 [0x1a8a26734]
+ 2515 __CFRunLoopRun (in CoreFoundation) + 1212 [0x1a8a27390]
+ 2515 __CFRunLoopServiceMachPort (in CoreFoundation) + 372 [0x1a8a28ed8]
+ 2515 mach_msg (in libsystem_kernel.dylib) + 76 [0x1a8921d00]
+ 2515 mach_msg_trap (in libsystem_kernel.dylib) + 8 [0x1a8921954]
It is as if IINA failed to tell Cocoa to proceed with termination.
I looked around the Internet for examples of delaying termination. I found some that followed the same pattern in the above code.
The only thing I don't like in the new code is that the array PlayerCore.playerCores is being accessed by the background thread. I don't think it is being modified, but the background thread probably should be operating on its own copy to be certain no other thread is messing with the array. I have made that change and added some log messages for debugging.
I'm a bit stumped by this one. Once we have a new build lets see if the debug messages tell us anything.
@low-batt I tried the file with mpv; doesn't freeze.I have also provided link to the file above for replicating crash/freeze. (Iina just cannot run it) Attached additional logs Sample of IINA.txt Spindump.txt Spindump2.txt
@ViRo3 Thanks for checking mpv. Very helpful to know it does not reproduce with mpv. There are other changes we can pull out to see if that changes the behavior. Tuesday is the day of the week that I'm really busy so might not get to that today. I have not tried out the file you posted a link to as that is the kind of site my ISP is unhappy with customers visiting.
The hang @John-He-928 has reported is a completely different issue. As of this morning I have a new working theory on that one. Need to dig into the code and see if that theory pans out.
While trying to reproduce these problems I instead managed to reproduce a 3rd hang. This one looks to be a mpv problem in their logger. I hit it when I raised the mpv logging level. I still need to see if I can reproduce it directly in mpv. This seems like the problem I mentioned a while back regarding mpv_render_context_create. I've gotten as far as finding that mpv did make some changes in 2020 related to locking in their logger.
Thank you both for helping with debugging these issues. It is very much appreciated.
@low-batt Thank you for the fix, but no luck, it seems not fixing the problem. IINA is freezing when exit. Tested on version 1.2.0-30
IINA sample.txt iina.log mpv.log