clsid2 / mpc-hc

Media Player Classic
GNU General Public License v3.0
11.37k stars 499 forks source link

Long delay when skipping to between files in folder #2546

Closed BreakPoints closed 9 months ago

BreakPoints commented 9 months ago

This one I've been trying to reproduce for a while but it's very hard to find what's causing it so apologies for the vague report.

Sometimes when using the skip button/mouse button MPC-HC will take an unusually long amount of time to load the next file or previous file, sometimes up to 8 seconds. This isn't consistent as skipping forward and backward between the same two files will sometimes take a short time and sometimes a very long one. While the long skip is occurring, there's a spike in CPU usage.

This happens on both SSDs and HDDs.

Windows 11 23H2

clsid2 commented 9 months ago

HDDs can go into sleep mode. Since it also happens with SSD, then maybe Windows Defender or some other scanner is causing a delay. Or any Explorer shell extension.

I can't fix a problem based on just a randomly occurring symptom. The cause is likely outside of the player.

Get a tool like Process Monitor and try to reproduce it. Then log might reveal what causes the delay.

BreakPoints commented 9 months ago

I can't find any one process in particular taking a long time but there's over 100,000 registry accesses coming from mpc-hc64.exe just to skip to the next file

clsid2 commented 9 months ago

You only need to look at MPC-HC process. You can filter out everything else.

If you have a log file where delay happened, then ZIP/RAR/7Z it, and attach it here if you want me to take a look.

Usually there is a noticeable gap in the timestamps.

Perhaps you have a huge file history? Test if clearing it makes any difference.

BreakPoints commented 9 months ago

You only need to look at MPC-HC process. You can filter out everything else.

That is what I had done. All 100,000 reg accesses were from the MPC-HC process. Changing the renderer to the default did reduce that to more like 34,000 as seen in the log but the issue persists.

Perhaps you have a huge file history? Test if clearing it makes any difference.

I had cleared the history recently but I did so again for this log.

I have attached an unfiltered log of MPC-HC taking 10 seconds to skip back to a file. (Will remove when we're done). There's about a seconds worth of time processing the reg accesses but the part that's actually taking the majority of time is a lot of ReadFile operations. I assume this is streaming in blocks for the buffer but I have no idea why this sometimes takes 9 seconds and sometimes less than 1.

clsid2 commented 9 months ago

I see start of player and just a piece of loading of first file. Log does not include the file skip part.

BreakPoints commented 9 months ago

I see start of player and just a piece of loading of first file. Log does not include the file skip part.

I does, I cleared the log while MPC-HC was open, then clicked the skip back button, waited until the file loaded then paused and saved the log. Pressed skip at around 10:42:36PM and the file completed loading at 10:42:46PM, all of which the log contains so anything that is taking too long is included in the log.

clsid2 commented 9 months ago

There is no useful log entries during that time gap. Just an entry from your AMD driver.

I don't know what goes wrong.

BreakPoints commented 9 months ago

Yeah, I wasn't able to either. There's a 8.8s long process from SearchIndexer right near the beginning of all the ReadFile operations that take up the processing time. That shouldn't be blocking though, right?

I have a feeling it's a quirk of Windows 11, I've had it happen on 3 different machines with the only thing in common being Windows 11.

clsid2 commented 9 months ago

That could actually be the cause if nothing else is happening during the delay.

BreakPoints commented 9 months ago

It says it's path is C: and my videos are all on the E: drive but that might just be because the SearchIndexer is launched from the OS drive.

Happy to reopen the issue? I think I've done enough to prove this is an issue, even if it's not the fault of MPC-HC. If the issue resides in Windows 11 we're only going to get more reports as more people upgrade.

clsid2 commented 9 months ago

This is a tracker for bugs in the player, not for keeping track of OS quirks.

Closed issues are available for everyone to read.

BreakPoints commented 9 months ago

Working around other software's quirks is an unfortunate reality of software development.

I was hoping this issue would avoid duplicates in the future, from experience people don't really look at closed issues.

Your repository so I won't push any further.

BreakPoints commented 4 months ago

Since the most recent update (2.3.0), now there is a chance that MPC-HC will just close when encountering the long delay when opening the next file in a folder. It happens more often than not and now makes it impossible to skim through video files in a folder.

I believe it is the same root cause so either this issue can be re-opened and renamed or I can open a new issue.

clsid2 commented 4 months ago

If the filter graph can not be closed properly, then the player will terminate.

That is intended behavior and will NOT be changed.

You need to fix whatever is causing the long delays on your system. That is abnormal behavior. https://www.tenforums.com/tutorials/93666-enable-disable-search-indexing-windows.html

clsid2 commented 4 months ago

I can maybe add option to increase the timeout, but you should really try to solve it first.

BreakPoints commented 4 months ago

The folder in which I'm having these issues has search indexing disabled already. I also followed the guide and disabled indexing system wide to no avail. As for needing to fix the issue, with all due respect that is what I am trying to do here.

I have encountered this issue on multiple different machines with different hardware and files and on clean OS installs. I have troubleshooted on and off for months and I have opened an issue with the one piece of software that has this problem: this one. No other media player exibits this.

If you have any other suggestions, I'm all ears.

clsid2 commented 4 months ago

Pause video. Clear process monitor log. Press Ctrl+C to close file. The delay should happen now.

Upload log.

Copy filter list: Menu > Play > Filters

BreakPoints commented 4 months ago

(log removed for privacy's sake)

Found a file that almost always causes MPC-HC to close when the file itself is closed. Attached is an unfiltered log from pressing Ctrl+C, the pause happening and then MPC-HC closing itself completely. Search indexing was turned off for this.

Filters currently loaded:

clsid2 commented 4 months ago

Again, the AMD driver component is active when delay occurs. I found this: https://www.reddit.com/r/AMDHelp/comments/1by7c4l/atieclxxexe_locking_files_and_the_amd_external/

Are all your systems using AMD graphics?

atieclxx.exe is AMD External Events Utility. It does not seem to be an essential process. Just can close it to test if that solves the problem.

And another slowness issue, where starting it helps? https://steamcommunity.com/discussions/forum/1/135511913386005577/?ctp=2#c2149847423921074863

BreakPoints commented 4 months ago

Ended atieclxx.exe - issue still occurs.

Two of the three systems have AMD graphics. My laptop is an AMD APU but my desktop (where the log has come from) has an Nvidia DGPU and AMD IGPU. I have disabled my IGPU in the BIOS (different issue, it sometimes still shows up and so is also disabled in device manager). I haven't installed AMD graphics drivers but I did install chipset drivers and skipped graphics drivers so they may have come from that.

The third system was my old Intel + Nvidia machine which also had the issue with no AMD whatsoever.

clsid2 commented 4 months ago

Options > Internal Filters > Splitter > Queue settings > Maximum queue memory = 64

Does that reduce the delay?

BreakPoints commented 4 months ago

Thanks for sticking with me on this. Here's another log but with the AMD External Events Utility service disabled and stopped.

(log removed)

Edit: Just saw your response, no change with 64MB Max Queue Memory

clsid2 commented 4 months ago

I see thread exists and a closefile action 5 seconds before process exit. So closing seems to work ok, but weird thing is that there are readfile actions continuing after that.

Are you using seekbar preview? Try with that disabled.

BreakPoints commented 4 months ago

I do have the seekbar preview on and intrestingly I can't turn it off.

Is there another setting other than this to disable it?

image

clsid2 commented 4 months ago

Check hover and change to time.

There seems to be a bug. It should not be enabled if hover is unchecked.

BreakPoints commented 4 months ago

That did it! Closing the file is instant, no pause, no MPC-HC itself closing.

clsid2 commented 4 months ago

I still don't understand what goes wrong on your system. Here closing is instantly, no matter what I try.

Does it work properly if you enable preview and hover?

BreakPoints commented 4 months ago

No, the issue comes back if I re-enable video preview on hover. It seems to be something to do with that second video stream/renderer being closed.

Possibly an API implementation was changed in Windows 11 because this is consistent across all my W11 machines. Are you able to spin up a VM?

Edit: The preview shows up and works in that context when enabled, just causes the pause on file close.

BreakPoints commented 4 months ago

Here's the file that I've been using to repo the issue.

Happens pretty consistently with this file but not 100% of the time, seems to be worse the slower the drive it's saved to is. Locks up for longer on my external SATA to USB SSD vs my internal NVMe SSD.

clsid2 commented 4 months ago

Are you able to trigger it with small files?

No issue here with your file. If you remux your file to .mkv with MkvToolNix, does that make any difference?

Here is a debug build and a tool to log the debug output: -removed-

BreakPoints commented 4 months ago

Yeah, happens with all sizes, haven't found a pattern to it but the file I linked is more consistent than others.

Remux of that file to .mkv also has the issue, no change there.

I ran the debug build and when it closes due to the timeout I heard a Windows alert sound. No popup, can't see a dump or log in the mpc-hc folder.

clsid2 commented 4 months ago

Use the DebugView tool

BreakPoints commented 4 months ago

Log of MPC-HC crashing when closing file

Log of MPC-HC pausing when closing file

Let me know if you want a full log of opening the file also

clsid2 commented 4 months ago

That confirms the delay happens when calling IMediaControl::Stop().

Make one full log so I can check if there is anything unusual when constructing the preview graph.

New build that prompts and gives option to wait longer: -removed-

BreakPoints commented 4 months ago

Debug2 build load and pause

Ran DebugView on your second Debug build while: opening mpc-hc -> load file -> play -> pause -> file close -> click "no" on popup to continue waiting -> file closes

clsid2 commented 4 months ago

Preview graph is OK.

Is there any difference in delay if you make sure that seekbar preview was shown at least once before closing?

MPC-HC menu > Help > About > Copy to clipboard paste the hardware section here

BreakPoints commented 4 months ago

No, the pause is an inconsistent length but triggering the preview doesn't change the length or make it more or less likely.

MPC-HC (64-bit) (Debug)

Build information: Version: 2.3.0.18 (38208135c) Build date: Jun 18 2024

LAV Filters: LAV Splitter: 0.79.2.9 LAV Video: 0.79.2.9 LAV Audio: 0.79.2.9 FFmpeg compiler: MinGW-w64 GCC 13.2.0

Operating system: Name: Windows 11 (Build 23H2) Version: 10.0.22631 (64-bit)

Hardware: CPU: AMD Ryzen 7 7800X3D 8-Core Processor GPU: NVIDIA GeForce RTX 4090 (driver version: 32.0.15.5599) Monitor: \.\DISPLAY1 - Generic PnP Monitor [2560x1440 32-bit 96 DPI] - [Current]

Text: Scale Factor: 1.000000 Ansi Codepage: 1252

clsid2 commented 4 months ago

This build uses VMR9 for preview instead of EVR: -removed-

BreakPoints commented 4 months ago

Same issue with Debug3 build. Now it tends to get stuck for long enough for the timeout popup to show twice.

Debug3 Pause on close

clsid2 commented 4 months ago

Last idea: -removed-

BreakPoints commented 4 months ago

Unfortunately much of the same

Debug4 Pause on close

clsid2 commented 4 months ago

In Process Monitor log, does it still keep reading file till offset ~128 million at the moment the delay occurs?

Here is reads less and it reads much faster. In the latest build it should buffer max 20MB.

BreakPoints commented 4 months ago

I'm not sure if that's due to run to run variance or not. The time it takes to close is widly inconsistent on every build. (I've been sending the longer ones as I thought they may be more useful)

ProcMon does show mpc-hc shooting off ReadFile operations the entire time mpc-hc is closing the file, here's a filtered log of just mpc-hc, started from the point of pressing Ctrl + C:

Build4 ReadFile ops on close

clsid2 commented 4 months ago

I have no explanation why it keeps reading so much data. I can not reproduce.

clsid2 commented 4 months ago

-removed-

This should log "getting graph state" lines. Initial one should be stopped, and all after that should say paused.

BreakPoints commented 4 months ago

It logs this:

00000112    2.92062092  [19692] C:\Code\clsid2\mpc-hc\src\SubPic\DX9SubPic.cpp(366) : atlTraceGeneral - CDX9SubPicAllocator::ClearCache 
00000113    2.93025327  [19692] C:\Code\clsid2\mpc-hc\src\mpc-hc\MainFrm.cpp(15495) : atlTraceGeneral - Getting graph state during close    
00000114    2.93029332  [19692] C:\Code\clsid2\mpc-hc\src\mpc-hc\MainFrm.cpp(15501) : atlTraceGeneral - state = paused  
00000115    2.93033719  [19692] C:\Code\clsid2\mpc-hc\src\mpc-hc\MainFrm.cpp(15509) : atlTraceGeneral - Stopping preview graph  
00000116    8.01663494  [19692] C:\Code\clsid2\mpc-hc\src\mpc-hc\MainFrm.cpp(18888) : atlTraceGeneral - Failed to close filter graph thread.    
00000117    14.78451157 [19692] C:\Code\clsid2\mpc-hc\src\mpc-hc\MainFrm.cpp(15513) : atlTraceGeneral - Releasing preview graph 
00000118    15.10105133 [19692] C:\Code\clsid2\mpc-hc\src\mpc-hc\MainFrm.cpp(18924) : atlTraceGeneral - Close media completed

Debug5 Pause on close

clsid2 commented 4 months ago

I give up.

BreakPoints commented 4 months ago

Would you mind if I opened a new issue with the information we have gained here? We now know it's triggered by the video preview, adipose may have some ideas as I believe he originally implemented the feature.

clsid2 commented 4 months ago

The added prompt might result in others reporting same problem. Until then a new issue is pointless.

clsid2 commented 2 months ago

@BreakPoints Please try latest development build. This will trigger a crash when closing preview graph takes more than 10 seconds. In the crash dump that is generated by the crash reporter I can see if there is any third party software that has injected itself into the player process.

Are you using an application called Windhawk to inject mods into Windows? That might be a possible cause.