Video freezes with audio playing,again

ssssssbbb commented 3 years ago

Environment

Filter version: 1.0.0
AviSynth+ version: 3.5.1
OS: Win10 x64 1909
AviSynth script: SVP 4.5.206
Log file 1.log

Describe the bug

Video freezes with audio playing after serveral minutes.

To Reproduce

What's difference after last normal state: I replaced my Vega56 graphics card with a 6700XT 1.Potplayer(serveral versions):LAV+madVR+SVP:freezes 2.Potplayer(serveral versions):LAV+EVR+SVP:freezes 3.Potplayer(serveral versions):built in decoder+EVR+SVP:freezes 4.Potplayer(serveral versions):built in decoder+madVR+SVP:freezes 5.Potplayer(serveral versions)：ffdshow raw filter+LAV+madVR+SVP: normal 6.Potplayer(serveral versions)：ffdshow raw filter+LAV+EVR+SVP: normal 7.MPC-HC 1.7.3：Avisynth filter+LAV+madVR/EVR+SVP: normal 8.MPC-HC 1.7.3：ffdshow raw filter+LAV+madVR/EVR+SVP: normal

CrendKing commented 3 years ago

I can't reproduce the issue, and the log file looks perfectly fine. I see the session ended at 160s, so I assume this issue happens randomly after quite a while?

1) Does this happen in every video file or only specific video files? 2) Does this happen immediately after SVP injection? 3) Does this happen if you don't use SVP?

If only specific video file, I may need it to repro.

ssssssbbb commented 3 years ago

Tried and found that the problem was only existed in these files "Fear.the.Walking.Dead.S06E08-14...1080p.AMZN.WEBRip.DDP5.1.x264-NTb[rarbg]".
It's random, as you said, after quite a while.
Since SVP was OK with MPC-HC, I ignored this, but it turned out to be normal without SVP.

CrendKing commented 3 years ago

I played for 7 minutes with PotPlayer + SVP multiple times and can't reproduce the issue. Since PotPlayer and/or SVP are the deciding factors, you might want to tweak their settings to find what causes that problem (e.g. The tracking mode black bars detection caused https://github.com/CrendKing/avisynth_filter/issues/41).

Alternatively, you could grab one of the commit build, put in the debug version, wait for a freeze, then capture a process dump, upload somewhere and post link here.

ssssssbbb commented 3 years ago

I didn't mention it but actually I tried serveral settings including the default one, black bars detection is always disabled. I'll try more.

There's one more detial, I'm used to playing at 1.3x speed, and I tried to repro by speeding up to 2.0x in both Potplayer and MPC-HC. 1.0x in PotPlayer was not tested...I'll do the test. Could it be the cause?

Detail 2: MadVR reported the video as 24fps when using ffdshow raw filter or built-in avisynth script, while it became 75fps with AVSF. Is this related?

I think I can't handle VisualStudio...

CrendKing commented 3 years ago

Playing at 1.3x doesn't trigger for me.
If madVR says it's 24fps, then SVP is not working there. If you config SVP to do 75fps, then madVR should show 75. That could explain why ffdshow is not showing symptom.

I think I can't handle VisualStudio...

Fair. However, there are easier ways to take captures. I think I should probably write a wiki page for the tutorial.

Anyways, if you'd like to help, download ProcDump and extract. Then load the debug version of the filter into PotPlayer64, wait for the freeze. Once frozen, run one of these commands:

procdump64 -ma PotPlayerMini64
procdump64 -mp PotPlayerMini64
procdump64 PotPlayerMini64

The difference of these commands is the output file size and its content. -ma could produce a 1.5G dmp file, but contains lots of information to help debugging. In contrast, the last command produces a 100M dmp, but only with minimum information.

So depending on your upload speed, choose the biggest one you can tolerate. Remember to also include the log file for that run.

ssssssbbb commented 3 years ago

But it's visually smoother, and SVP tray shows it's working.

ssssssbbb commented 3 years ago

Log and dump here. 0602.log https://mega.nz/file/clByEDYD#rdmPlABKxozcl3DGnnZA3NbZC8mBLnjyfJLBrVMgJ28

CrendKing commented 3 years ago

Thanks for the dump and log. There's some interesting finding. In dump, I see the filter created output frame #26890, and delivers to madVR, which is stuck at waiting for some resource/event to happen. However, in log I see at line 88413 that the frame #26890 was successfully delivered, and a whole bunch of upcoming frames. There's about 20 second between the dump time and the end of log.

I also noticed that delivering #26890 took exceptionally long time. Comparing that "@ xxxx" between line 88412 and 88413, it took around 1.8s, when it should usually take milliseconds. So something was fishy. However, the fact that the log continued tells me that madVR accepted that frame and all upcoming ones. And you also mentioned the audio was playing. So did you notice the hang stop? If not, then there might be some problem in madVR that causes it to receive frames from upstream but fail to render.

Back in https://github.com/CrendKing/avisynth_filter/issues/41, I fixed some code that caused hangs. There was one hang I still couldn't figure out why, and it was tied to madVR. I think the next steps could be:

1) Back in #41, PhantomGamers confirmed that EVR no longer hangs. But you stated EVR hangs for you. So could you please repro with EVR and upload a dump? If you gonna do this, please use the ax file from "Debug x64" zip. Debug version contains more information. Release version has better performance for daily use, but not suitable for debugging. Thanks.

2) If we can verify EVR doesn't hang, and only madVR does, then you could open a ticket for madish to look at. Stuff he could find useful:

Dump: the link you posted
pdb: https://github.com/CrendKing/avisynth_filter/suites/2877501196/artifacts/64339589 (note that these links expires after 7 days, so you might want to download them)
Source code: https://github.com/CrendKing/avisynth_filter/tree/469e8663c4fdb9da5a04c5b1cf0f8833c3b0924b, or use git to rebase
Likely hang thread ID: 1968

Call stack:

win32u.dll!NtUserMsgWaitForMultipleObjectsEx()
user32.dll!RealMsgWaitForMultipleObjectsEx()
user32.dll!MsgWaitForMultipleObjects()
madVR64.ax!000000004a42c39b()
madVR64.ax!000000004a45037a()
madVR64.ax!000000004a47a8e5()
madVR64.ax!000000004a411617()
avisynth_filter_64.ax!SynthFilter::FrameHandler::WorkerProc() Line 386
at D:\a\avisynth_filter\avisynth_filter\avisynth_filter\src\frame_handler.cpp(386)
[Inline Frame] avisynth_filter_64.ax!std::invoke(void(SynthFilter::RemoteControl::*)() &&) Line 1601
at C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\VC\Tools\MSVC\14.29.30037\include\type_traits(1601)
avisynth_filter_64.ax!std::thread::_Invoke<std::tuple<void (__cdecl SynthFilter::RemoteControl::*)(void),SynthFilter::RemoteControl *>,0,1>(void * _RawVals) Line 56
at C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\VC\Tools\MSVC\14.29.30037\include\thread(56)
avisynth_filter_64.ax!thread_start<unsigned int (__cdecl*)(void *),1>(void * const parameter) Line 97
at minkernel\crts\ucrt\src\appcrt\startup\thread.cpp(97)

ssssssbbb commented 3 years ago

That 20s between dump and log was man made. I did search the video and it worked, then exited Potplayer, not sure if the searching can always unfreeze. Potplayer was not hang this time, while the GUI died in last issue.

Here are the log and dump, generated by the newest debug x64 version under EVR, madvr is not fixed, if you still need the madvr dump, leave me a message and I will do that tomorrow. EVRlog.log https://mega.nz/file/Qk4l3SKS#AOFuzZlx4QpHeuClAGmNOzeBEVvX8BG72g8-ilQR5yg

CrendKing commented 3 years ago

When you say "search the video", do you mean "seek the video"? Every time you do a seek, the log will show that action. I don't see any seek event until the very end of the log (line 93575). That's strange.

Hmm, the EVR hang is puzzling. I can't think of any reason why would it hang there. The cause is different to madVR. I can give you a modified version to try, but no guarantee to fix anything: https://github.com/CrendKing/avisynth_filter/actions/runs/901217750. Let me know the result.

ssssssbbb commented 3 years ago

Yes, I meant "seak", I did that fast after freezing and exited immediately, maybe there's not enough time for avsf to write the log?

I'll try the modified version later today.

CrendKing commented 3 years ago

If you got time, please capture a madVR dump with the modified version, without seeking afterwards, so I can take look at the "ground zero".

ssssssbbb commented 3 years ago

Log and dump here. madvr0603.log https://mega.nz/file/hk5UnTbK#UluIBkb9Uo31i1012JVZkdoVO4GuiCwlRpsAMN_ha1k

CrendKing commented 3 years ago

This one is exactly the same as before. So basically no new information.

However, I did notice a pattern. It seems all 3 logs hang around 3 minute mark. I wonder could it be some memory leak or in general some resource leak in constant rate, which is drained at 3 minutes? For example, it's possible you enabled hardware acceleration in SVP, and your GPU driver has a bug. Then when madVR needs GPU memory to render something, it can't get that. Try disabling hardware acceleration in SVP and see if anything change.

Also, if you use EVR with the modified version, does it hang any more?

ssssssbbb commented 3 years ago

I remember I've tried CPU rendering and got same result, I'll do the confirmation. But…MPC-HC is OK and other video files are OK, that's strange.

I'll try EVR.

ssssssbbb commented 3 years ago

EVR log and dump here. evrlog.log https://mega.nz/file/VwpBhKTA#0XMgiAyhntXlY5iXtbw0LVAclAy2jcLb2NdLzC58yJA

CPU rendering test is not passed.

I also found that seeking can unfreeze but pause/play can't.

CrendKing commented 3 years ago

OK. I figured out something. Turns out this freeze is not random at all. All 4 of the log files shows that after source frame #8395 is read from AviSynth, the frame server not longer requests more frames (Get source frame: frameNb 8395 is the always the last Get source frame line). And if the frame server does not request more frame, AVSF will no longer process more frame for performance reason.

Now, I don't know why this frame #8395 is so special, but I suspect it has something with the video file you have. My "Fear.the.Walking.Dead.S06E08.The.Door.1080p.AMZN.WEB-DL.DDP5.1.H.264-NTb.mkv" does not reproduce the issue. It could be related to how these files are encoded, or even damaged. And you also mentioned the problem only happens to this file.

Maybe you could procure a different encoded version of the video? Or maybe you could share your file so I try to repro the issue?

BTW, I noticed that you might have ExtraSourceBuffer config in your settings. I suggest you remove that setting unless you know exactly what you are doing.

ssssssbbb commented 3 years ago

S06E08-S06E14 cause freezing. We can check the md5/sha-1, I'll do that later today.

I don't remember if I've changed "ExtrasourceBuffer" config. I'll check that.

ssssssbbb commented 3 years ago

Fear.the.Walking.Dead.S06E08.The.Door.1080p.AMZN.WEB-DL.DDP5.1.H.264-NTb.MKV MD5: F047634555E1F654814194E43A3519C2 SHA1: 0F224E942721AE35565B6182A77F13A898DB7801 CRC32: 9C631A2D

If that frame is special, it should cause freezing everytime but it didn't. And if I start playing from the middle of the video, it freezes at another inconstant frame.

As for "ExtrasourceBuffer", I can't find any setting in GUI nor registry. How to set it?

v1.10 doesn't help.

CrendKing commented 3 years ago

We have the same file. Also, if starting from random position in the middle and freeze, do it 2-3 times and can you check if it is still #8395 being problematic (see if Get source frame: frameNb 8395 is the always the last Get source frame: line). If you are not sure, just post the log. In the meanwhile, I'll think about other possibilities.

If you can't find ExtraSourceBuffer, just forget about it.

Also, have you tried resetting PotPlayer, re-add the filter and reproduce? Since MPC-HC works, this could be related to PotPlayer.

ssssssbbb commented 3 years ago

I started playing from after 8395 and still freezed. Yes, the last "Get source frame " is always 8395.

Resetting was tried before, nothing happened. Also, LAV with CPU decoding was tried.

Actually I realized Potplayer could be most suspicious at first, but updating did nothing.

Since the problem isn't from the video (normal in your test), should we ignore it unless you dig out something?

CrendKing commented 3 years ago

Since I can't repro, and you might not be able to debug this yourself, I'd say ignore until further evidence shows up. This problem might be something related to your hardware, or PotPlayer, or something that specific to your setup. Like how they describe bugs: "where there is one, there are many". This weird 8395 magic number is bound to show up again.

ssssssbbb commented 3 years ago

It shows up now!!

This video "Fear.The.Walking.Dead.S06E15.1080p.WEB.h264-GOSSIP[rarbg]" is also from rarbg but not made by Group NTB. Freezes again at frame 8395! Same frame number in different videos??

log of starting from random position in the middle june6.1.log log of starting from another position june6.2.log

CrendKing commented 3 years ago

That's weird, isn't it? But you said not every time does it freeze at 8395? Like you could sometimes play past 8395? And why only this "Fear The Walking Dead" show has the problem, if any frame 8395 would suffice? Maybe if you play something else long enough to 8395 you can observe freeze as well?

Does it freeze if you disable SVP completely?

ssssssbbb commented 3 years ago

I said "not every time" means that I started from near the end and still freezed, and the log of that run showed the last number of outputed frame is larger than 8395, such as "Processing output frame 26343 for source frame 8429".

So I thought since I played from after 8395 and it still freezed, it's not the cause this time, did I misunderstand?

Also, I've finished playing a video which is much longer than those two. So that's really wierd.

Since SVP was OK with MPC-HC, I ignored this, but it turned out to be normal without SVP.

I tried before, but "without SVP" means that I quited the application, is it different from disabling?

CrendKing commented 3 years ago

So I thought since I played from after 8395 and it still freezed, it's not the cause this time, did I misunderstand?

In AVSF, what happens internally is

1) LAV Filters (upstream) send source frames to AVSF 2) AVSF tells AviSynth to process the source frames, and produce output frames 3) Once output frames are ready, AVSF delivers them to downstream (most likely EVR or madVR)

The 8395 happens in step 2. LAV Filters kept sending source frames beyond 8395, but somehow AviSynth stopped processing further. What's weird is, AVSF still sees that output frames generated from 8396, 8397 etc. were coming out of AviSynth, as if nothing was wrong. Of course, those output frames could all be duplicate out of AviSynth's cache. That's why you think it's frozen but in fact it is running (as well as the audio).

So why would AviSynth stops at 8395? Without debugging into its internal it's hard to know.

I tried before, but "without SVP" means that I quited the application, is it different from disabling?

Right, you said without SVP it's normal. Basically everything in AviSynth script would contribute to the problem, including SVP. If the problem comes from SVP, we might need @chainikdn's help.

ssssssbbb commented 3 years ago

Tried more videos and there are still some freezing ones (not FearTheWalkingDead anymore) which were stucked at frame 8395. I don't think they are similar in some way. So what I can do is waiting for the new driver but it's long.

CrendKing commented 3 years ago

It's either SVP, PotPlayer, AVSF, or your OS/hardware. We don't have any other report of the same problem with the first 3, so it's probably something else in your system.

ssssssbbb commented 3 years ago

Finally found the key!!!

It's SVP related but I'm not sure where the problem is. Choosing different options in SVP FPS conversion lead to different result, as below: 1.To screen: my monitor is 75Hz so SVP tray shows 75fps[22/8](mistake, it should be 25/8), video freezes after a while 2. 2x: the tested video is 24fps so SVP tray shows 48fps[2x], doesn't freeze 3. fixed 75fps: that's wierd, SVP tray shows 75.4289fps[22/7], doesn't freeze, it's not always 75.4289fps according to different videos but it's always 22/7 multipled.

It seems that the 75.00fps is somehow related to frame 8395?

CrendKing commented 3 years ago

I noticed the relatively unusual 75Hz you had from the log. Since I don't have (native) 75Hz monitor, I used "Fixed 75 fps" to test the video and had no issue.

If the video is 24fps, 22/8 is 66fps, definitely not 75fps. But it could be just a bug in SVP UI, but I doubt it. 22/7 is correct with 75.4289. Of course if the video is 30fps, it will have to be simply 5/2, which is exactly 75fps.

Generally if the interpolated fps is not exactly an integer, there will be frame time drift (you can see that in the log file), but AVSF is designed to handle those. I haven't experienced freeze issue with drift.

To confirm, can you provide log for case 1 and 3 (the freezing 24fps video), where 1 eventually freeze at 8395 and 3 doesn't? Comparing them could reveal something interesting.

EDIT: Just used CRU to add a 75Hz refresh rate to my monitor and repeat the "To screen" experiment. SVP says 22/7, and I don't get the freeze. Source goes beyond 8395.

ssssssbbb commented 3 years ago

Sorry, it's 25/8 not 22/8, all logs above are type 1. I'll provide both type of logs from the same video later.

Maybe you can try the "exact number" option and set it to 75.00?

ssssssbbb commented 3 years ago

24×25/8=75.0fps, played 6min56s before freeze. 1.log

24×22/7=75.4289fps, played 10min before manual stop. 3.log

CrendKing commented 3 years ago

I can repro now. Turns out 25/8 is the magic number. Now I can test something from my side.

The only problem is that we need 6 minutes to just repro once... There might be other magic numbers, but I don't know how to find them (just like you never know what's the 1000000000th prime number :))

BTW, I think the reason why only you can trigger this before is that your monitor refresh rate is probably slightly lower than 75Hz. If it's exactly 75, somehow SVP will use 22/7, which results 75.4289. Only if I force my refresh rate to something like 74.8Hz it will use 25/8. So from now on, I suggest you use fixed at 75Hz instead of To screen. Maybe ask chainikdn why does he choose 22/7 over the better 25/8 (24 * 25 / 8 = 75).

ssssssbbb commented 3 years ago

Play at 2x speed will repro faster, I tried again with 2x speed and it takes 3min to freeze. Faster than 2x may cause video/audio sync problem, so I don't know whether high speed is the interference.

CrendKing commented 3 years ago

OK. Found out the cause.

So the first thing I try is check if VapourSynth variant shows the same symptom. It does. Luckily, the log files directly shows the problem:

T 13000 @ 184838: Failed to generate output frame 26233 with message: Invalid frame number 26233 requested, clip only has 26233 frames

Both AviSynth and VapourSynth are not designed to handle infinite, real-time use cases. They expect a finite video stream. So source filters must specify the number of frames for each source clip. Filters that change fps could alter the number for intermediate clips. Even though AVSF uses a extremely large number 10810800 (same as ffdshow) for source, somehow if FRC is 25/8, SVP changes that number to 26333. Since AviSynth/VapourSynth thinks there is no more frame exist, they stop requesting more. Turns out, 26333 is always mapped to source frame 8395. Thus 8395 is always the last requested source frame.

We need to ask chainikdn about two things (https://www.svp-team.com/forum/viewtopic.php?pid=78574#p78574):

Why 22/7 for 75Hz monitors.
Why shrink the number of frames for script clips. It looks like an overflow to me.

chainikdn commented 3 years ago

SVP changes that number to 26333

I'll check.

chainikdn commented 3 years ago

turns out even uint64_t can overflow in some cases :D update SVP now, this issue should be fixed

ssssssbbb commented 3 years ago

turns out even uint64_t can overflow in some cases :D update SVP now, this issue should be fixed

Fixed, thanks.

CrendKing commented 3 years ago

@chainikdn, Thanks for the fix. However, I don't understand how does 10810800 overflow uint64_t? Maybe there are some crazy math inside SVP, but if you use some variant of MulDiv, it shouldn't overflow, right?

And the choice of FRC ratio question (why FRCing a 24FPS to 75 uses 22/7 instead of 25/8)?

CrendKing / avisynth_filter