search

CrendKing / avisynth_filter

DirectShow filters that put AviSynth and VapourSynth into video playing
MIT License
108 stars 8 forks source link

Issues when closing a video player #5

Closed chainikdn closed 4 years ago

chainikdn commented 4 years ago

  1. RC destruction often hangs forever: PostQuitMessage() doesn't break the event loop for some reason. If I replace PostQuitMessage with DestroyWindow - it always works as expected.

  2. Right now CAviSynthFilter::Reset() is called THREE (3) times on closing, including one time from the CAviSynthFilterInputPin::Active(). Not a big problem but it looks like a lot of useless work taking 1.5-2.5 secs to finish the player process.

CrendKing commented 4 years ago

  1. DestroyWindow works because there is the "-1" test in the loop, but it is not the recommended way from Microsoft's document, right? Do you know how to reproduce the hang?

  2. In my local test, before closing the player, there is only one EndFlush() from source filter, which will call Reset(). What's the call stack of the other two (especially the Active())? If Active() is called before the player closing, there is some serious bug in either the player or DirectShow base classes, both of which are unlikely. Please tell me the detailed step to reproduce.

chainikdn commented 4 years ago 
T  17744 @     5008: GetFrame at:     62 Queue size: 10 Back:     49 Front:     58 Served(4):     58 maxRequestFrame:     62
T  18880 @     5087: Deliver frameNb:    176 from     49 at   21876951 ~   21995076 frameTime:     118125 Prefetch:    5
---> close player here <----
T  18872 @     5097: Reset
T  18872 @     5097: ReloadAviSynth
T  17844 @     5614: Active
T  17844 @     5614: Source path: <...>
T  17844 @     5614: Visiting filter: <...>
T  17844 @     5614: Reset
T  17844 @     5614: ReloadAviSynth
T  17844 @     6053: Reset
T  17844 @     6053: ReloadAviSynth
T  17844 @     6515: ~RemoteControl
T   4920 @     6519: Remote control stopped
T  17844 @     6606: ~CAviSynthFilterInputPin
chainikdn commented 4 years ago

MPC-HC, open video, wait for SVP to kick-in and show the OSD and close immediately. 50% chance that the player process will hang at "_msgThread.join()". Again, doesn't hang with DestroyWindow().

chainikdn commented 4 years ago 
avisynth_filter_64.ax!AvsFilter::CAviSynthFilterInputPin::Active() Line 80
    at E:\dev\avisynth_filter\avisynth_filter\src\input_pin.cpp(80)
avisynth_filter_64.ax!CBaseFilter::Pause() Line 573
    at E:\dev\avisynth_filter\baseclasses\amfilter.cpp(573)
avisynth_filter_64.ax!CTransformFilter::Pause() Line 525
    at E:\dev\avisynth_filter\baseclasses\transfrm.cpp(525)
[External Code]
chainikdn commented 4 years ago
  1. Another hang situation - not related to RC, more complicated to find the reason. Again, open video, wait for SVP to kick-in BUT close the player even before the script is loaded and SVP's OSD is shown. In this case the last lines in log are: 
    T  10476 @      267: Accept transform: out  4
T  13840 @      909: Source path: <...>
T  13840 @      909: Visiting filter: <...>
T   3276 @      915: Remote control started
T  12188 @     2458: Accept input definition:  4
T  12188 @     2458: Accept transform: out  4
T  12188 @     2458: Accept input definition:  4
T  12188 @     2458: Accept transform: out  4
T  12188 @     2458: update output format using input format: definition 4, width  1920, height   804, codec P010
T  12188 @     2458: Accept transform: out  4
T  12188 @     2458: Accept transform: out  4
T  12188 @     2459: Accept transform: out  4
T  12188 @     2461: Accept input definition:  4
T  12188 @     2461: Accept transform: out  4
T  12188 @     4190: update output format using input format: definition 4, width  1920, height   804, codec P010

    BTW, if you tell your email I could create a license key for you.

CrendKing commented 4 years ago 
T  17744 @     5008: GetFrame at:     62 Queue size: 10 Back:     49 Front:     58 Served(4):     58 maxRequestFrame:     62
T  18880 @     5087: Deliver frameNb:    176 from     49 at   21876951 ~   21995076 frameTime:     118125 Prefetch:    5
---> close player here <----
T  18872 @     5097: Reset
T  18872 @     5097: ReloadAviSynth
T  17844 @     5614: Active
T  17844 @     5614: Source path: <...>
T  17844 @     5614: Visiting filter: <...>
T  17844 @     5614: Reset
T  17844 @     5614: ReloadAviSynth
T  17844 @     6053: Reset
T  17844 @     6053: ReloadAviSynth
T  17844 @     6515: ~RemoteControl
T   4920 @     6519: Remote control stopped
T  17844 @     6606: ~CAviSynthFilterInputPin

I suppose you added some Log statements? Here's what I see (tested like 10 times):

T  19748 @     2319: Popping frame Pre size: 10 Post size:  9
T  19748 @     2330: Deliver frameNb:     72 from     28 at   12027575 ~   12194241 frameTime:     166666 Prefetch:    0
T   8420 @     2331: GetFrame at:     36 Queue size:  9 Back:     28 Front:     36 Served(2):     36 maxRequestFrame:     36
T  14444 @     2332: Reset
T  14444 @     2332: ReloadAviSynth
T  14444 @     2572: ~CAviSynthFilter
T  14380 @     2573: Remote control stopped
T  14444 @     2629: ~CAviSynthFilterInputPin

Could you test without SVP and see if the problem is specific with SVP use case or related to remote control?

avisynth_filter_64.ax!AvsFilter::CAviSynthFilterInputPin::Active() Line 80 at E:\dev\avisynth_filter\avisynth_filter\src\input_pin.cpp(80) avisynth_filter_64.ax!CBaseFilter::Pause() Line 573 at E:\dev\avisynth_filter\baseclasses\amfilter.cpp(573) avisynth_filter_64.ax!CTransformFilter::Pause() Line 525 at E:\dev\avisynth_filter\baseclasses\transfrm.cpp(525) [External Code]

This is the call stack of normal startup Pause(). If this happened at closing, you must have tried to open a new file somehow.

T  10476 @      267: Accept transform: out  4
T  13840 @      909: Source path: <...>
T  13840 @      909: Visiting filter: <...>
T   3276 @      915: Remote control started
T  12188 @     2458: Accept input definition:  4
T  12188 @     2458: Accept transform: out  4
T  12188 @     2458: Accept input definition:  4
T  12188 @     2458: Accept transform: out  4
T  12188 @     2458: update output format using input format: definition 4, width  1920, height   804, codec P010
T  12188 @     2458: Accept transform: out  4
T  12188 @     2458: Accept transform: out  4
T  12188 @     2459: Accept transform: out  4
T  12188 @     2461: Accept input definition:  4
T  12188 @     2461: Accept transform: out  4
T  12188 @     4190: update output format using input format: definition 4, width  1920, height   804, codec P010

The only weird thing I can see is the double update output format. It could be video file specific. But I don't think it's the problem, because then it can't be caused by closing player at specific time. Could be some synchronization issue.

BTW, if you tell your email I could create a license key for you.

I'll send you in Doom9 PM.

chainikdn commented 4 years ago

If this happened at closing, you must have tried to open a new file somehow.

Nope, just pressing the close button...

CrendKing commented 4 years ago

I managed to reproduce one of the problems you mentioned. The two deadlock threads have the following call stack:

1.
    avisynth_filter_64.ax!CCritSec::Lock() Line 501 C++
    avisynth_filter_64.ax!CAutoLock::CAutoLock(CCritSec * plock) Line 98    C++
    avisynth_filter_64.ax!CTransformFilter::Stop() Line 471 C++
    quartz.dll!00007ffad48c7c79()   Unknown
    quartz.dll!00007ffad48db76e()   Unknown
    mpc-be64.exe!CMainFrame::CloseMediaPrivate() Line 14263 C++
    mpc-be64.exe!CGraphThread::OnClose(unsigned __int64 wParam, __int64 lParam) Line 20416  C++

2.
    avisynth_filter_64.ax!CCritSec::Lock() Line 501 C++
    avisynth_filter_64.ax!CAutoLock::CAutoLock(CCritSec * plock) Line 98    C++
    avisynth_filter_64.ax!CBasePin::ConnectionMediaType(_AMMediaType * pmt) Line 2219   C++
    madVR64.ax!000000004a46296a()   Unknown
    madVR64.ax!000000004a473bb5()   Unknown
    madVR64.ax!000000004a471670()   Unknown
    madVR64.ax!000000004a579724()   Unknown
    avisynth_filter_64.ax!AvsFilter::CAviSynthFilter::UpdateOutputFormat() Line 627 C++
    avisynth_filter_64.ax!AvsFilter::CAviSynthFilter::Receive(IMediaSample * pSample) Line 282  C++
    avisynth_filter_64.ax!CTransformInputPin::Receive(IMediaSample * pSample) Line 763  C++

For thread 1, CTransformFilter::Stop() holds m_csFilter at beginning, and then tries to acquire m_csReceive after Inactive(). For thread 2, CTransformInputPin::Receive() holds m_csReceive, then CBasePin::ConnectionMediaType() tries to acquire m_pLock, which is the same as m_csFilter.

To break the deadlock, all we need is to m_csReceive.Unlock() before UpdateOutputFormat() and m_csReceive.Lock() immediately after. No need to change anything else.

        Reset(true);
        _reloadAvsSource = false;

+       m_csReceive.Unlock();
        hr = UpdateOutputFormat();
+       m_csReceive.Lock();

        if (FAILED(hr)) {

This could be the only one problem we have. Please try this and see if all of them are solved.

chainikdn commented 4 years ago

this fixes issue # 3

CrendKing commented 4 years ago

I managed to reproduce #2. I'd fairly certain it is a bug of MPC-HC. I can't trigger it even once in MPC-BE. The call stack of the second Active() is exactly the same as the first time when player just started:

    avisynth_filter_64.ax!AvsFilter::CAviSynthFilterInputPin::Active() Line 85  C++
    avisynth_filter_64.ax!CBaseFilter::Pause() Line 573 C++
    avisynth_filter_64.ax!CTransformFilter::Pause() Line 525    C++
    quartz.dll!CFilterGraph::Pause(void)    Unknown
    quartz.dll!CFGControl::Cue(void)    Unknown
    quartz.dll!CFGControl::CImplMediaControl::StepPause(void)   Unknown
    quartz.dll!CFGControl::CImplMediaControl::Pause(void)   Unknown
    madVR64.ax!000000004a43a2cd()   Unknown
    madVR64.ax!000000004a5243bd()   Unknown
    madVR64.ax!000000004a57d4c9()   Unknown
    user32.dll!UserCallWinProcCheckWow()    Unknown
    user32.dll!DispatchMessageWorker()  Unknown
    mpc-hc64.exe!00007ff65e43e366() Unknown
    mpc-hc64.exe!00007ff65e43ebd9() Unknown
    mpc-hc64.exe!00007ff65e43edf0() Unknown
    mpc-hc64.exe!00007ff65e5df89d() Unknown

I don't have MPC-HC's pdb so I don't know what are those 4 function names. We can ask clsid in Doom9 see if he can provide me one. But ultimately we need him to fix this.

As for #1, I tried at least 20 times each on both players. Not one time hang.

CrendKing commented 4 years ago

Interesting. I switched to EVR, and can't trigger it anymore. Call stack of the first time (the only time):

    avisynth_filter_64.ax!AvsFilter::CAviSynthFilterInputPin::Active() Line 85  C++
    avisynth_filter_64.ax!CBaseFilter::Pause() Line 573 C++
    avisynth_filter_64.ax!CTransformFilter::Pause() Line 525    C++
    quartz.dll!CFilterGraph::Pause(void)    Unknown
    quartz.dll!CFGControl::Cue(void)    Unknown
    quartz.dll!CFGControl::CueThenRun(void) Unknown
    quartz.dll!CFGControl::CImplMediaControl::StepRun(void) Unknown
    quartz.dll!CFGControl::CImplMediaControl::Run(void) Unknown
    mpc-hc64.exe!00007ff65e12a9a0() Unknown
    mpc-hc64.exe!00007ff65e117d27() Unknown
    mpc-hc64.exe!00007ff65e423089() Unknown
    mpc-hc64.exe!00007ff65e424573() Unknown
    mpc-hc64.exe!00007ff65e154598() Unknown
    mpc-hc64.exe!00007ff65e41e0f6() Unknown
    mpc-hc64.exe!00007ff65e41eba0() Unknown
    user32.dll!UserCallWinProcCheckWow()    Unknown
    user32.dll!DispatchMessageWorker()  Unknown
    mpc-hc64.exe!00007ff65e43e366() Unknown
    mpc-hc64.exe!00007ff65e43ebd9() Unknown
    mpc-hc64.exe!00007ff65e61c203() Unknown
    mpc-hc64.exe!00007ff65e5c4706() Unknown

Can you confirm? Is this actually related to madVR? But then why madVR in MPC-BE is fine? It's the same 3 functions in MPC-BE call stack.

chainikdn commented 4 years ago

As for #1, I tried at least 20 times each on both players. Not one time hang.

Still happens on my rig.

Can you confirm? Is this actually related to madVR?

Yep, doesn't happen on EVR. I guess we can leave it then...

CrendKing commented 4 years ago

Still happens on my rig.

Are you saying even with EVR, you still hang, but not the double Active()? Or is it only with madVR? Which player? If so, do you see a slightly difference log when it hangs vs not hang?

chainikdn commented 4 years ago

1 is not related to active(), evr/madvr etc. cause it's only about RC. "Which player" - MPC-HC.

CrendKing commented 4 years ago

"Do you see a slightly difference log when it hangs vs not hang?" I was hoping the hang only happens if double Active() happened, which messes with some lock and message handling. And since EVR never hang, also hoping EVR never hang. Log could be useful.

Also, am I doing it right: close MPC-HC immediately after SVP OSD shows up?

chainikdn commented 4 years ago

MPC-BE hangs in this situation too, so - "hang only happens if double Active() happened" - nope.

close MPC-HC immediately after SVP OSD shows up?

this's exactly what I'm doing...

CrendKing commented 4 years ago

Well, last resort. I need your

  1. Test video
  2. SVP config
  3. AVSF input formats

so I can test with exactly the same env you have. Does it happen on every video you tried? Is SVP on the default profile?

chainikdn commented 4 years ago

ok, I know the reason :D PostQuitMessage() post a quit message to the thread's queue, but you only GetMessage() messages related to _hWnd GetMessage(&msg, nullptr, 0, 0)

CrendKing commented 4 years ago

Found this: https://stackoverflow.com/questions/32768924/wm-quit-only-posts-for-thread-and-not-the-window

chainikdn commented 4 years ago

"GetMessage(&msg, _hWnd, 0, 0)" only gets messages related to _hWnd. PostQuitMessage() posts a message NOT related to _hWnd.

CrendKing commented 4 years ago

Well, since I can't trigger that problem, if you are sure once the hwnd is replaced with nullptr the problem no longer happens, I'll change it. And thanks for letting me know. I blame the ambiguous MSDN documents.

chainikdn commented 4 years ago

BTW they say DefWindowProc() handles WM_CLOSE by calling DestroyWindow() :)

CrendKing commented 4 years ago

What do you mean? I know DefWindowProc turns WM_CLOSE into a WM_DESTROY. But if we GetMessage with nullptr, WM_DESTROY does nothing to the message loop.

chainikdn commented 4 years ago

I just mean destroying the window is the most Microsoft's recommended way as the default handler does exactly this.

not the recommended way from Microsoft's document

CrendKing commented 4 years ago

When I said that, I mean you should not use WM_DESTROY to get out of the message loop. GetMessage literally says it only specially returns 0 for WM_QUIT, not WM_DESTROY.

So are we done with this ticket? Can I close now?

chainikdn commented 4 years ago

yep