AVS clip(s) are not properly deleted/cleared

[chainikdn]

Environment

0.10.0

Describe the bug

AVSF now creates extra clip instances. I put two debug lines into my plugin where "++++" marks construction and "~~~~" marks destruction. 0.9.4:

++++ 7C31C5B0 <--- launch
~~~~ 7C31C5B0 <--- seek
++++ 3313DC70 
~~~~ 3313DC70 <--- close window

0.10.0:

test 1 - start playback, then close window

++++ 6F960150
++++ 6F960F30

test 2 - start playback, seek, close window

++++ D9184590
++++ D9183C50
~~~~ D9184590
++++ D9183EA0

test 3 - start playback, close playback via File -> Close: the same as in "test 1", but the resources (memory, GPU memory) are not freed.

[CrendKing]

OK. Since I can't reproduce your result without having SVP source code, let me show you the result that I can have, and you tell me where the discrepancies come from.

I open a video, let SVP does the injection, then do a few seeks, finally close the video player.

The log file: avisynth_filter.log

The current version has a log line whenever a PClip is created or released, with its address as sort of identity. Here's the extraction of all related lines:

// Graph building phase. All done in checking instance. Clips are immediately released after gathering video information.
T  12784 @       13: ReloadAviSynthScript from checking instance
T  12784 @       13: New script clip: 000001F27B02E4A0
T  12784 @       13: Release script clip: 000001F27B02E4A0
T  12784 @       13: ReloadAviSynthScript from checking instance
T  12784 @       13: New script clip: 000001F27B02E4A0
T  12784 @       13: Release script clip: 000001F27B02E4A0
T  12784 @       13: ReloadAviSynthScript from checking instance
T  12784 @       13: New script clip: 000001F27B02E4A0
T  12784 @       13: Release script clip: 000001F27B02E4A0
T  12784 @       13: ReloadAviSynthScript from checking instance
T  12784 @       13: New script clip: 000001F27B02E4A0
T  12784 @       13: Release script clip: 000001F27B02E4A0
T  12784 @       14: ReloadAviSynthScript from checking instance
T  12784 @       14: New script clip: 000001F27B02E4A0
T  12784 @       14: Release script clip: 000001F27B02E4A0
T  12784 @       14: ReloadAviSynthScript from checking instance
T  12784 @       14: New script clip: 000001F27B02E4A0
T  12784 @       14: Release script clip: 000001F27B02E4A0
T  12784 @       14: ReloadAviSynthScript from checking instance
T  12784 @       14: New script clip: 000001F27B02E4A0
T  12784 @       14: Release script clip: 000001F27B02E4A0
T  12784 @       14: ReloadAviSynthScript from checking instance
T  12784 @       14: New script clip: 000001F27B02E4A0
T  12784 @       14: Release script clip: 000001F27B02E4A0
T  12784 @       14: ReloadAviSynthScript from checking instance
T  12784 @       14: New script clip: 000001F27B02E4A0
T  12784 @       14: Release script clip: 000001F27B02E4A0
T  12784 @       14: ReloadAviSynthScript from checking instance
T  12784 @       14: New script clip: 000001F27B02E4A0
T  12784 @       14: Release script clip: 000001F27B02E4A0

// All pins connected now. First time loading the script to main instance.
T  21896 @      606: ReloadAviSynthScript from main instance
T  21896 @      606: New script clip: 000001F27B02E4A0

// SVP injection. Notice 000001F27B02E4A0 was first relaesed, then new clip 000001F20B49B920 is created. Still only ONE outstanding clip
T  13664 @     1826: ReloadAviSynthScript from main instance
T  13664 @     1826: Release script clip: 000001F27B02E4A0
T  13664 @     1835: New script clip: 000001F20B49B920

// SVP proposes format change. Checking format compatibility in checking instance, while letting main instance serve frames normally
T  13664 @     1836: ReloadAviSynthScript from checking instance
T  13664 @     1842: New script clip: 000001F20BCEEA80
T  13664 @     1842: Release script clip: 000001F20BCEEA80

// First seek
T  21896 @     4285: ReloadAviSynthScript from main instance
T  21896 @     4285: Release script clip: 000001F20B49B920
T  21896 @     4293: New script clip: 000001F20BCF5400

// Second seek
T  21896 @     6314: ReloadAviSynthScript from main instance
T  21896 @     6314: Release script clip: 000001F20BCF5400
T  21896 @     6341: New script clip: 000001F275EC7380

// Close
T  12784 @     8620: Release script clip: 000001F275EC7380

Throughout the whole process, there is only exactly one outstanding PClip from avsf end. All clips from the checking instance are immediately released.

It would nice if you do this simple test and cross check your result, see where the extra SVP instance comes from.

[chainikdn]

don't you see that both main memory and GPU memory are NOT cleared after File -> Close with 0.10 ?

Since I can't reproduce your result without having SVP source code

I believe you can take any AVS filter (including a built-in one) and put debug lines into constructor and destructor and you'll see what happens from the clip's point of view.

[chainikdn]

from what I see, AvsHandler is not deleted at the end "~AvsHandler()" is missing in the log

[CrendKing]

Yes, there is a bug that introduced in 0.10.0. I'm considering an optimal approach to fix it.

However, when you said "AVSF now creates extra clip instances." that sounded like a separate issue. Can you confirm that there is no "extra" clip created?

[chainikdn]

Can you confirm that there is no "extra" clip created?

hmmm... but there IS an extra clip in another "script instance" now, right? if it becomes clear that this another instance is creating some issue then there will be a separate issue

I can't tell if there another problem here until nothing is deleted at all.

[CrendKing]

I believe all memory leaks are fixed in https://github.com/CrendKing/avisynth_filter/commit/68cccebe8f52ede0d65dc9860ca84b86014d687f. Please test.

AviSynthFilter_Debug.zip

there IS an extra clip in another "script instance" now, right?

Sure, but it only lives for around one millisecond, so why bother? It's not used for serving frames.

[chainikdn]

but it only lives for around one millisecond, so why bother?

are you sure? because I can see that both filter instances (i.e. AVS's GenericVideoFilter) live forever (*) at least they are deleted at the end now

(*) one lives forever and another lives between seeks

[chainikdn]

in the meantime, RC is not starting after File->Close and then Open again

[CrendKing]

are you sure? because I can see that both filter instances (i.e. AVS's GenericVideoFilter) live forever (*)

I modified avisynth.h to add the logging you suggested earlier. Then I play video that requires dynamic format change. All I see is that the filter from main instance "lives between seeks". The temporary filter are destroyed immediately as expected.

// temporary filters
T  18620 @        0: Create 0000019A8A721D80
T  18620 @        0: Destroy 0000019A8A721D80
T  18620 @        0: Create 0000019A8A720580
T  18620 @       15: Destroy 0000019A8A720580
T  18620 @       15: Create 0000019A8A720280
T  18620 @       15: Destroy 0000019A8A720280
T  18620 @       15: Create 0000019A8A721D80
T  18620 @       31: Destroy 0000019A8A721D80
T  18620 @       31: Create 0000019A8A720980
T  18620 @       31: Destroy 0000019A8A720980
T  18620 @       31: Create 0000019A8A721280
T  18620 @       47: Destroy 0000019A8A721280
T  18620 @       47: Create 0000019A8A721D80
T  18620 @       47: Destroy 0000019A8A721D80
T  18620 @       62: Create 0000019A8A721D80
T  18620 @       62: Destroy 0000019A8A721D80
T  18620 @       62: Create 0000019A8A720B80
T  18620 @       62: Destroy 0000019A8A720B80
T  18620 @       78: Create 0000019A8A721D80
T  18620 @       78: Destroy 0000019A8A721D80
T  16336 @      625: Create 0000019A99756620
T  10436 @      640: Create 0000019A99755620
T  10436 @      640: Destroy 0000019A99755620
T  10436 @      640: Create 0000019A99756D20
T  10436 @      656: Destroy 0000019A99756D20
T  10436 @      656: Create 0000019A99755820
T  10436 @      656: Destroy 0000019A99755820
T   8236 @      734: Destroy 0000019A99756620
// stream starts
T   8236 @      734: Create 0000019A99756E20  <- main filter
T   8236 @      734: Create 0000019A99755620  <- temporary filter
T   8236 @      750: Destroy 0000019A99755620
T  10436 @      875: Create 0000019A99A652E0
T  10436 @      875: Destroy 0000019A99A652E0
T  10436 @      875: Create 0000019A99A65EE0
T  10436 @      890: Destroy 0000019A99A65EE0
T  10436 @      890: Create 0000019A99A65CE0
T  10436 @      890: Destroy 0000019A99A65CE0
T   8236 @      922: Destroy 0000019A99756E20  <- main filter
T   8236 @      937: Create 0000019A99A65AE0  <- main filter
T   8236 @      937: Create 0000019A99A65FE0  <- temporary filter
T   8236 @      953: Destroy 0000019A99A65FE0
T  18620 @     3640: Destroy 0000019A99A65AE0

RC is not starting after File->Close and then Open again

When you say "RC" you mean GC? I can observe after File->Close, the memory usage may take a few seconds to be freed. But eventually all memory are freed. The delay varies between different players. In fact, the whole avsf and avisynth.dll modules are unloaded after File->Close.

---

Closing this because you confirmed the issue is fixed. Feel free to reopen if you have new discovery.

[chainikdn]

When you say "RC" you mean GC?

I mean Remote Control

[CrendKing]

That's an entirely different issue, but a bug indeed. https://github.com/CrendKing/avisynth_filter/actions/runs/774168646 should fix it and feel free to try it when the CI is done.

[chainikdn]

All I see is that the filter from main instance "lives between seeks". The temporary filter are destroyed immediately as expected.

Add Prefetch() to the script.

[chainikdn]

ok... the null filter:

#include "windows.h"
#include "avisynth.h"

#include "stdio.h"
#pragma warning(suppress : 4996)
static FILE* flog = fopen("d:\\simple.log", "wt");

class SimpleSample : public GenericVideoFilter {
public:
    SimpleSample(PClip _child, IScriptEnvironment* env) : GenericVideoFilter(_child) {
        fprintf(flog, "+++++ %p, env %p\n", _child.operator->(), env); fflush(flog);
    }
    ~SimpleSample() {
        fprintf(flog, "~~~~~ %p\n", child.operator->()); fflush(flog);
    }

    PVideoFrame __stdcall GetFrame(int n, IScriptEnvironment* env) {
        return child->GetFrame(n, env);
    }
};

AVSValue __cdecl Create_SimpleSample(AVSValue args, void* user_data, IScriptEnvironment* env) {
    return new SimpleSample(args[0].AsClip(), env);
}

const AVS_Linkage* AVS_linkage = 0;
extern "C" __declspec(dllexport) const char* __stdcall AvisynthPluginInit3(IScriptEnvironment * env, const AVS_Linkage* const vectors) {
    AVS_linkage = vectors;
    env->AddFunction("SimpleSample", "c", Create_SimpleSample, 0);
    return "na";
}

the script:

LoadPlugin("d:\SimpleSample.dll")
SetFilterMTMode("SimpleSample",1)
AvsFilterSource()
SimpleSample()
Prefetch(2)

playback pattern: open, seek one time, close output (w/o Prefetch):

+++++ 000002AE0DEF6060, env 000002AE0DE65C20
~~~~~ 000002AE0DEF6060
+++++ 000002AE0DEF2D90, env 000002AE0DE65C20
~~~~~ 000002AE0DEF2D90
+++++ 000002AE0DEF2CD0, env 000002AE0DE65C20
~~~~~ 000002AE0DEF2CD0
+++++ 000002AE0DEF2EB0, env 000002AE0DE65C20
~~~~~ 000002AE0DEF2EB0
+++++ 000002AE0DEF3240, env 000002AE0DE65C20
~~~~~ 000002AE0DEF3240
+++++ 000002AE0DEF2C70, env 000002AE0DE65C20
~~~~~ 000002AE0DEF2C70
+++++ 000002AE0DEF2B80, env 000002AE0DE65C20
~~~~~ 000002AE0DEF2B80
+++++ 000002AE109E26C0, env 000002AE092775D0 <--- main filter
~~~~~ 000002AE109E26C0 <--- seek
+++++ 000002AE10AD9150, env 000002AE092775D0
~~~~~ 000002AE10AD9150 <--- close

output (with Prefetch):

+++++ 0000023764DB0AF0, env 0000023764CF6FC0
~~~~~ 0000023764DB0AF0
+++++ 0000023764DACAA0, env 0000023764CF6FC0
~~~~~ 0000023764DACAA0
+++++ 0000023764DB3F40, env 0000023764CF6FC0
~~~~~ 0000023764DB3F40
+++++ 0000023764DAC7D0, env 0000023764CF6FC0
~~~~~ 0000023764DAC7D0
+++++ 0000023764DB40B0, env 0000023764CF6FC0
~~~~~ 0000023764DB40B0
+++++ 0000023764DAC8F0, env 0000023764CF6FC0
~~~~~ 0000023764DAC8F0
+++++ 0000023764DB4350, env 0000023764CF6FC0 <--- !!!
+++++ 00000237676A9840, env 000002375F84FD40 <--- main filter
~~~~~ 00000237676A9840 <--- seek
+++++ 0000023764DB2450, env 000002375F84FD40
~~~~~ 0000023764DB4350 <--- !!!
~~~~~ 0000023764DB2450 <--- destroy main filter

0.9.4. for the reference (with Prefetch):

+++++ 00000200A9196310, env 00000200A441E250
+++++ 00000200A91A9AB0, env 00000200A441E250
~~~~~ 00000200A91A9AB0
~~~~~ 00000200A9196310
+++++ 00000200A91A9BA0, env 00000200A441E250
+++++ 00000200A91963D0, env 00000200A441E250
~~~~~ 00000200A91A9BA0
+++++ 00000200A9196940, env 00000200A441E250
~~~~~ 00000200A91963D0
+++++ 00000200A91A9C00, env 00000200A441E250
~~~~~ 00000200A9196940
+++++ 00000200A9196400, env 00000200A441E250
~~~~~ 00000200A91A9C00
+++++ 00000200A91A9A80, env 00000200A441E250
~~~~~ 00000200A9196400
+++++ 00000200A9196550, env 00000200A441E250
~~~~~ 00000200A91A9A80
+++++ 00000200A91A3E90, env 00000200A441E250
~~~~~ 00000200A9196550
+++++ 00000200A91A9C90, env 00000200A441E250
~~~~~ 00000200A91A3E90
+++++ 00000200A91A3C20, env 00000200A441E250
~~~~~ 00000200A91A9C90
+++++ 00000200A91A97E0, env 00000200A441E250
~~~~~ 00000200A91A3C20
+++++ 00000200A91961C0, env 00000200A441E250
~~~~~ 00000200A91A97E0
+++++ 00000200ADE9EF20, env 00000200A441E250 <--- playback starts
~~~~~ 00000200A91961C0
~~~~~ 00000200ADE9EF20 <--- seek
+++++ 00000200ADE59910, env 00000200A441E250
~~~~~ 00000200ADE59910 <--- close

[CrendKing]

Turns out that Avs+ prefetchers are only destroyed when the whole environment is deleted. Stopping the clip is not enough. https://github.com/CrendKing/avisynth_filter/actions/runs/781375215 should fix this.

Man, how would anyone know these without trial and error, since there is almost no documentation at all?

[chainikdn]

looks good now :)

[chainikdn]

Don't you want to make a release now, please?

[CrendKing]

Patience. Something big is coming.

[chainikdn]

I wonder if this issue is still possible for the main instance, in ReloadScript()? You only added DeleteScriptEnvironment() in the checking instance, right? Because I'm almost 90% sure I can see a problem under some conditions.

Run SVP with NVOF turned on, open a video, then switch to 3D mode (*), and then switch it back to 2D. Then strange things happen, cause SVP's filter instance is not actually deleted after 3D-to-2D switch.

(*) "3D mode" is splitting the frame into two halves and processing them separately, thus creating two instances of SmoothFps filter.

[CrendKing]

The earlier issue was that there are two sets of prefetchers, one from the main and the other from aux (used to be called "checking"). The ones from aux aren't supposed to exist beyond the few data gathering calls. But the ones from main should exist until the whole stream shuts down. The previous fix used DeleteScriptEnvironment() to delete the prefetchers from aux immediately after the calls.

Are you suggesting that we delete the whole avs environment in the main's ReloadScript()? It's possible but I don't see the benefit of doing that. The prefetchers will be recreated immediately anyways. Sure, if the script is changed in a way like you mentioned that reduces number of filters, the old prefetchers would still hold reference to them, but are you willing to introduce hundreds of milliseconds lag for every single seek just to save this one unused filter in rare 3D-2D switch scenario? Remember, to delete the environment from the main, it's not as simple as a DeleteScriptEnvironment(). We need to coordinate the frame_handler to first delete all cached frames, stop all async request of frames, stop worker thread, then delete environment, which could take noticeable amount of time. And this will happen on every single seek, every single SVP inject. We could do that on aux easily because aux doesn't serve any frame.

I remember one of my initial design goal of this project was to beat ffdshow in performance, which is not only slow but also having ghosting for every seek. Implementing this would likely a going backward.

[chainikdn]

Sure, if the script is changed in a way like you mentioned that reduces number of filters, the old prefetchers would still hold reference to them

is it so by AVS+ design? cause this really sounds like a bug, not feature there's another not-so-rare case when filters number is changed - turning NVOF on/off

Are you suggesting that we delete the whole avs environment in the main's ReloadScript()?

dunno, I'm not suggesting anything now I just mentioned that in some cases old filters are still not deleted after script change which lead to undefined behavior at various points (*). Probably this's not good, right?

(*) mainly because several objects (GPU-related at the first place) are singletons that really must be re-created after major script change

[CrendKing]

is it so by AVS+ design? cause this really sounds like a bug, not feature

I don't know the answer, but it is what it is. Maybe ask Avs+ about this. You could argue either way (stopping script should or should not delete prefetchers), but I think the real problem is why to have prefetchers in the first place. I know, it is to get frames in multithreaded manner to gain performance. But VapourSynth API doesn't need prefetcher because it has async get frame. So maybe one day Avs+ would add async and no longer need the prefetchers. But the chance is extreme slim.

BTW, if you use VapourSynth version, do you observe resource leak? You can see I don't have DeleteEnvironment even for aux.

Maybe, if you could verify VapourSynth version being functional and equivalent in terms of performance against the Avs version, you could switch the default mode of SVP to VapourSynth?