Encoding slowdown

[hello_hello]

Is there anything a mere mortal can do to trackdown the cause of a slowdown?

I've been re-encoding a bunch of AVIs I first remuxed as MKV (old TV captures) and every so often I notice one will run at half the usual speed. I'm pretty sure it doesn't slow down. It starts off slow and stays slow. As I'm using slow filtering I'm encoding them two at a time, but I've noticed the same thing happen when only running one encode. If I stop the "slow" encode and start it again, it invariably runs at normal speed. I've only noticed it happen when using QTGMC and LSFMod in the same script. Is there any way to determine if it's a plugin at fault or if it's some odd Avisynth bug? I'm running (sorry) XP and Avisynth 2.6.0.6

I've had odd problems before when combining QTGMC and LSFMod. One batch of files would often encode at half speed if I encoded them from the beginning, but simply putting something like Trim(50,0) at the end of the script would ensure the encoding would run at normal speed. I just don't know if it's possible, or how to find the culprit. Here's today's example:

Same type of source video. The one on the left is running at normal speed, while the one on the right is running at half speed.
http://s3.postimg.org/7p6sqr6rj/2encodes1.jpg (http://postimg.org/image/7p6sqr6rj/)

After aborting the encode on the right and starting it again, it runs at normal speed.
http://s10.postimg.org/dh8lxvw0l/2encodes2.jpg (http://postimg.org/image/dh8lxvw0l/)

After aborting it a second time and adding Trim to the script so it commences from where it left off the first time, it still runs at normal speed.
http://s12.postimg.org/7z6rv29k9/2encodes3.jpg (http://postimg.org/image/7z6rv29k9/)

This is the script:
LoadPlugin("C:\Program Files\MeGUI\tools\ffms\ffms2.dll")
FFVideoSource("E:\video.mkv", cachefile="D:\video.mkv.ffindex", fpsnum=24000, fpsden=1001, threads=1)
QTGMC(InputType=1, Ezdenoise=2)
LSFMod(strength=66)
gradfun3()


The resolution of these files is only 640x480. When this problem occurs while re-encoding HD video, which it does now and then, things get really slow.
Thanks.

[StainlessS]

Hello, Hello Hello.

Sorry dont have a clue about cause of your problem, however

putting something like Trim(50,0) at the end of the script would ensure the encoding would run at normal speed

I pretty much always put a Trim(0,0) in my automated scripts to make sure that any spliced clips dont result in audio sync problems,
all it does is chop off any extra audio that is longer than video, OR, pad (EDIT: with silence) short audio to same length as video.
Might be worth a try seeing if Trim(0,0) at end of your scripts obviates or 'hides' the problem that you are having.
There should be no ill effects.
Good luck.

EDIT: Adding a trim to end of script would insert an extra cache, but no idea why that might prevent the problem.

[johnmeyer]

I don't know of tools or methods to help track down the cause of a slowdown. However, the symptoms you describe can be caused by running out of RAM memory, and the system then switching over to using your disk drive as "virtual memory." This results in a condition known as "thrashing." The next time you do an encode, look at the disk drive light on your computer at the beginning of the encode, when everything is running fast. Then, if you sense a slowdown, look at the disk drive light again and see if it is lit all the time, or is lit a lot more than before. If so, you've got thrashing, and this is most likely your problem. Most AVISynth encodes are not disk bound, and usually the disk light is off more than on.

If you do suspect disk thrashing, a way to sometimes get around memory issues -- although it is not a fix that will always work -- is to use a "SetMemoryMax()" statement at the beginning of the script. The largest number you can use depends on what version of Windows you use. The number is given in kB, so a good number to start with is 768, e.g., SetMemoryMax(768).

[kuchikirukia]

Don't know if it's the same problem, but i had the same symptoms and solution with QTGMC using LSMASH (half-speed encodes solved by trimming off the first few frames.) Something about it would cause LSMASH to keep creating and killing threads.

http://forum.doom9.org/showthread.php?p=1736158#post1736158

Though it will occasionally do it without QTGMC, it seems to be a major trigger.

Set Threads=2 and load up process explorer (with admin access) and see if ffms2 is doing the same thing.
If it is the same bug, your half-speed encodes may have errors.

[hello_hello]

Thanks for the replies guys.

I had a very repeatable QTGMC speed issue at one stage with particular files (but once again, only in combination with LSFMod). I posted about it here, and at VideoHelp (http://forum.videohelp.com/threads/369143-ResizersPack-MasksPack-PlaygroundPack-SmoothContrast-Logo-mod-functions?p=2389299&viewfull=1#post2389299), along with a sample of the video in question. That's when Trim(50,0) stopped the slowdown from happening. In that case, so did using MP_Pipeline. I also discovered if I reverted back to an earlier version of QTGMC the problem went away. Dogway also modified his mod of QTGMC for me (http://forum.videohelp.com/threads/369143-ResizersPack-MasksPack-PlaygroundPack-SmoothContrast-Logo-mod-functions?p=2389468&viewfull=1#post2389468) and that fixed the problem, but I don't think it was ever discovered why.
In that case MP_Pipeline preventing the slowdown seemed to point to a memory issue, but if it was, it makes no sense that something as simple as Trim(50,0) could fix it too, or switching to an older QTGMC version would do likewise.
I'm pretty sure it happened whether I was using ffms or L-Smash for indexing, but I might need to re-test that.

In the above case the problem was 100% repeatable for me, and re-starting the encodes didn't make the problem go away, whereas the files I referred to in the opening post here generally encode at normal speed, only every now and then one doesn't, despite the source files all being the same (640x480, Xvid AVIs). That makes it even harder to track down the cause, because it's so irregular and random.

I don't think it's a memory issue, because it's happened while the PC's been unattended and MeGUI is running through the jobs in the queue two at a time, yet job number 14 (for example) might encode at half speed for no apparent reason, then it's back to full speed for the next job. If it is a memory issue, I've not noticed any disc thrashing as a result. The hard drive light just flashes now and then.
I've not seen any errors in the slow encodes either. I checked one quite thoroughly and it looked fine, even though in that case encoding had slowed to about 1fps.

I'll probably try the sample I linked to again in the next day or so (if anyone else would care to try it, it's attached to the VideoHelp post I linked to along with the scripts I was using) as "hopefully" that'll make the problem 100% repeatable again, and if so I'll try Trim(0,0) to see if that makes a difference. I'd be interested to learn if the sample encodes at normal speed using the same script for someone else (it encoded at a snail's pace using two different PCs here).

Thanks.

[hello_hello]

I think maybe I'll try older versions of QTGMC next time to see if that's the problem. The main reason it's so noticeable for me is I generally run a bunch of encodes with similar scripts one after the other, and often two at a time.

This encode started while I was in bed. Along with a second encode which started around the same time. I was fairly surprised they hadn't completed when I checked. They both ran at the same speed. The pertinent info from MeGUI's log file:

[Information] [20/10/15 9:35:04 AM] Avisynth input script
-[NoImage] LoadPlugin("C:\Program Files\MeGUI\tools\dgindex\DGDecode.dll")
-[NoImage] DGDecode_mpeg2source("D:\078 Genesis Of The Daleks, Part 4.d2v")
-[NoImage] trim(0,712).TFM().ChangeFPS(50,1)\
-[NoImage] ++trim(713,34273).QTGMC(sharpness=0.5)\
-[NoImage] ++trim(34274,0).TFM().ChangeFPS(50,1)
-[NoImage] crop(22, 10, -24, -12)
-[NoImage] Spline36Resize(640,480,0,1,0,0)
-[NoImage] gradfun3()
[Information] [20/10/15 9:35:04 AM] Job command line: "C:\Program Files\MeGUI\tools\x264\x264.exe" --level 4.1 --preset slow --tune film --crf 18.0 --keyint 500 --vbv-bufsize 78125 --vbv-maxrate 62500 --no-fast-pskip --stitchable --colormatrix bt470bg --sar 1:1 --output "D:\078 Genesis Of The Daleks, Part 4.mkv" "D:\078 Genesis Of The Daleks, Part 4.avs"
[Information] [20/10/15 3:55:18 PM] encoded 71102 frames, 3.12 fps, 1606.01 kb/s

Yet the two encodes currently running use this same script, the same encoder settings, with only a slight difference in frame numbers for Trim(), they're both currently 20% complete and both plodding along at 6.9fps. It seems odd that whenever an encode runs slower than it should, it's always around half the speed that it should.

[Information] [20/10/15 5:17:03 PM] Avisynth input script
-[NoImage] LoadPlugin("C:\Program Files\MeGUI\tools\dgindex\DGDecode.dll")
-[NoImage] DGDecode_mpeg2source("D:\078 Genesis Of The Daleks, Part 6.d2v")
-[NoImage] trim(0,733).TFM().ChangeFPS(50,1)\
-[NoImage] ++trim(734,34040).QTGMC(sharpness=0.5)\
-[NoImage] ++trim(34041,0).TFM().ChangeFPS(50,1)
-[NoImage] crop(16, 6, -16, -6)
-[NoImage] Spline36Resize(640,480)
-[NoImage] gradfun3()

[hello_hello]

It's possibly something to do with Trim(). I had two more encodes running simultaneously today and both had two "layers" of Trim() in the script. When I checked, both were running at about one quarter speed rather than the usual half speed. About 1.7fps.

LoadPlugin("C:\Program Files\MeGUI\tools\dgindex\DGDecode.dll")
DGDecode_mpeg2source("D:\video.d2v")
AssumeTFF()
trim(0,733).TFM().ChangeFPS(50,1)\
++trim(734,34040).QTGMC(sharpness=0.5)\
++trim(34041,0).TFM().ChangeFPS(50,1)
crop(16, 6, -16, -6)
Spline36Resize(640,480)
gradfun3()
Trim(0,68079)\
++Trim(68081,68081)\
++Trim(68081,0)

I aborted both encodes, changed the second lot of trims so they resumed encoding where they left off (about 7 minutes from the beginning), restarted both and now they're plodding along at 6.53fps and 6.60fps respectively. It's a mystery.....

[kuchikirukia]

Using your sample with L-SMASH and QTGMC 3.33 I get a lot of MSVCR120 thread destruction/creation causing slowdowns, though it has a period different from what I observed in my encodes (instead of constant Christmas-tree flashing slowing it to half, it does it for a few seconds, then is good for a few seconds.)
Note this is without avstp.dll, which I had disabled for other reasons, though I checked and it does it with.

http://s10.postimg.org/yqpiyc2v9/Untitled.jpg (http://postimg.org/image/yqpiyc2v9/)

Trim(50,0) and it's clear sailing:

http://s24.postimg.org/fu2iqwkkx/Untitled.jpg (http://postimg.org/image/fu2iqwkkx/)

Though your problem was using FFMS2, and I'm not seeing any slowdowns with that. (E: note, I wasn't looking at it from the very start of the clip here. See further down where there is a problem with 3.33 and FFMS2 in the first 150 frames)



E: QTGMC 3.33d, though! Halfway through the encode FFMS2 goes crazy with CPU usage and we slow down significantly.

http://s24.postimg.org/5y1wamvqp/Untitled.jpg (http://postimg.org/image/5y1wamvqp/)
This is with your QTGMC(InputType=1, Preset="medium", EzDenoise=1)

crop(4, 2, -4, -2)
Spline36Resize(1280,720)

LSFMod(strength=75)

We have a few FFMS2 CPU spikes early in the encode, it settles down to ~0.2-0.4% CPU util per thread (where it should be), but around 50% complete it jumps to 2%-6% on each thread and the avs4x264mod thread drops to 4-6% from 12.3%.
Since I have a hyperthreaded quad-core and there was plenty of CPU left, simply having extra CPU util on the FFMS2 threads should not have slowed avs4x264mod down. My guess is it wasn't being fed.
E2: Still does it adding setmemorymax(1200)

E3: Trim(0,0) doesn't help
E4: Trim(1,0) doesn't help

E5: Trim(50,0), and we're good (though we already knew that)
Trim(10,0) is good
Trim(3,0) is good
Trim(2,0) is good
Trim(1,0) (again) bad.
Edit (many moons later): Trim (2,0) was good there, but not always. Just did another round of tests where it took Trim (4,0) for it to settle down.

With Trim(2,0) or greater, FFMS2 is 0.2-0.4% CPU util throughout. With Trim (1,0) or lower, it's high at 1.2% to start, then goes up and down from 0.2 to 5% for a bit before settling at the 0.2-0.4% level, until hitting a spike at 48% of the way through, then pretty much shitting itself at 51%, which it never recovers from.

E6: QTGMC 3.33 without Trim seems to have problems at the start, too. It just doesn't result into it faltering later.
Without trim, the FFMS2 threads are at 1.4% util from the start, dropping down, then spiking to 3% at frame 20, 4% at frame 30, 6% at frame 60. Pretty much settles down after frame 80 except for a spike around 150.
Add Trim(2,0) and it's clean all the way through.

E7: Switching to LSMASH, those frames correspond where it creates and destroys MSVCR120 threads.

E8: And with 3.33d and LSMASH, 55% is where we go full Christmas with thread creation/destruction. Craps out all the way to the end.
FFMS2 has a solid event at 52-53% of 5-6% cpu util that doesn't seem to correspond to anything in LSMASH. From 53% until 55% it's back to 0.2%, and 55% is where it craps out and never recovers.

And for anyone wondering, QTGMC 3.32 also seems to have those initial problems with the first 150 or so frames. Trim(2,0) clears it up.

Even though it takes LSFmod to make 3.33d crap out at 55% here, I have definitely had QTGMC crap out without LSFmod.

Oh: System is Windows 10; Groucho2004's Avisynth 2.6.0.6 ICL10
Same result with regular 2.6.0.6
Same with Avisynth+.
Trim (2,0) seems to fix it with all.
So I'd say QTGMC 3.33d is busted. 3.33 and 3.32 don't seem to destabilize like 3.33d here, but since they also exhibit some problems at the start, it might be possible that a different script will cause them to crap out at some point too.

Ran another test with 3.33d, this time bobbing with:QTGMC()
LSFMod(strength=75)
It craps out at 24%.
So it doesn't seem to be related to anything with a feature of the clip, it's number of frames processed.
Inputtype=1 craps out after around 350 output frames
bobbing craps out after around 350 output frames
Bob with selecteven() and it craps out after around 170 output frames.
And I'm done.

[hello_hello]

Wow.... thanks for all the testing. I only just saw your post and while I've read it, I probably haven't taken it all in properly yet. I'm probably going to have to come back to this later tonight or tomorrow.

After several more half speed encodes today (while encoding scripts two at a time using this PC and also while encoding them one at a time using another PC) I switched back to the QTGMC version dogway modified for me and so far it's been fine. Yesterdays problem encodes used DGDecode for decoding so I'm assuming it's not caused by the decoder as such. Dogway's script download link no longer works, but I've posted here (http://forum.videohelp.com/threads/369143-ResizersPack-MasksPack-PlaygroundPack-SmoothContrast-Logo-mod-functions?p=2415423&viewfull=1#post2415423) asking if he could apply the same mod (http://forum.videohelp.com/threads/369143-ResizersPack-MasksPack-PlaygroundPack-SmoothContrast-Logo-mod-functions?p=2389468&viewfull=1#post2389468) to the latest QTGMC (3.33s) so I could test it (I'm not sure I trust myself to modify QTGMC correctly). If you feel so inclined, could you try again with the attached version of QTGMC. It's 3.33d with "revert to QTGMC_deflate/QTGMC_inflate" applied and I strongly suspect that's got something to do with it. I think 3.33d was the first version to use mt_xxflate.

So far I've been able to confirm that when encoding slows down, CPU usage also drops. When I'm running two normal speed encodes simultaneously using this PC, CPU usage sits on 100%. When two simultaneous encodes are both running at half speed for no apparent reason, CPU usage is more like 60%.

Anyway, thank you very much for your time and testing. Hopefully I might be able to post something more substantial than "QTGMC is sometimes slow" in the QTGMC thread soon so someone can have a look at fixing it. There's two versions of QTGMC included in the following link.

"QTGMC-3.33d (mod) v2.avsi" is version 3.33d with "revert to QTGMC_deflate/QTGMC_inflate" and so far today it's been fine.
"QTGMC 3.33s (mod) v2.avsi" is the version I've been using lately and the one resulting in slowdowns over the last few days. It should be the same as the version labelled 2015 9 10 here (http://forum.doom9.org/showpost.php?p=1732845&postcount=2041). I renamed the avsi files to stop myself becoming too confused over which flavour I was using.

Thanks.

Same zip file, two different links (in case one doesn't work).
http://www.filedropper.com/qtgmc-333d333s
http://www.megafileupload.com/9y7z/QTGMC-3.33d_&_3.33s.zip

I'll return later to read your previous post again.... more thoroughly.

[hello_hello]

kuchikirukia,
I still can't experiment too much yet as I'm wanting to finish the encoding jobs in the queue first, but since switching to the version of QTGMC 3.33d dogway modified for me, neither PC has missed a beat. Both CPUs are running close to 100% and encoding is running at normal speed for these jobs (I know that because they're consistently running at about twice the speed of some identical encodes jobs this afternoon). I'm using QTGMC and LSFMod in these scripts and that still hasn't caused a slowdown with the modified QTGMC.

I tried having a play with Process Explorer, but aside from the fact I've never used it before, I don't seem to be seeing the same info as you. I've not using avs4x264mod so I can only look at x264.exe but i'm not seeing any Avisynth related processes. I don't know if that's normal, or because I don't know what I'm doing, or because I'm using XP (I've put a parts list together for a new PC build and plan on a trip to the local PC shop tomorrow, but it's still XP until next week).

I am curious about one thing though. I thought maybe my not seeing Avisynth related processes might have something to do with avstp.dll. It probably doesn't, but what do I know, so I removed it from the Avisynth plugins folder and started a fresh encode. It still appeared in the threads list. So I thought maybe Avisynth kept it loaded between encodes, if that's even possible, so I rebooted and tried again. It still appeared in the threads list. When I removed QTGMC from the script, it didn't. How can QTGMC appear to be causing a plugin to auto-load when the plugin isn't in the plugins folder? Is it normal? Thanks.

http://s23.postimg.org/yu09wgxzr/avstp.jpg (http://postimg.org/image/yu09wgxzr/)

Edit: Okay I found a partial answer. When I move avstp.dll to the root of my D drive it still manages to get loaded/used. I'm not sure why and it's not what I expected. I tried the root of the C drive and the E drive and it's not loaded from there, but the root of the D drive and it is. I assume that's not inexplicable, but I don't know what the explanation is.

Cheers.

[kuchikirukia]

You have another copy of avstp.dll in some auto-load directory.

Ok, while testing yours just found out that just:
QTGMC(inputtype=1) [and thus preset="slower]
...makes them all crap out from beginning to end. (including 3.32) LSFMod not needed. Trim doesn't fix it. This is a super-duper crap-out not seen before.
Add preset=medium to it and we're good with 3.32. (haven't tested the others)

I'm also now noticing some hiccups with just using QTGMC() using 3.32. Past 25% we definitely have a lot of 2-5% CPU util on FFMS2, and it does slow down a bit, but just not half. Goes from 2.83fps (and rising) to 2.45. This is with just assumetff() and qtgmc() -- nothing else.
Rising indeed: with Trim(50,0) it tops out at 3.1 fps.

This problem doesn't seem to affect it at the preset=slow level. 5.83fps with or without trim. (though a heavier script might)

I'll run a couple tests with your scripts in the next post. Just gonna leave this with 3.32 since it's more important.

[kuchikirukia]

Your 3.33s mod v2 breaks at 350 frames with QTGMC(preset="slow")
3.33d mod v2 doesn't.
At preset= slower, 3.33d mod v2 does the same thing as 3.32 though. It slows down around 250 frames in.
Trim (50,0) fixes it.

[real.finder]

hello_hello change nothing but the below

http://i.imgur.com/NqxLJh5.png

anyway I made it

http://forum.doom9.org/showpost.php?p=1732845&postcount=2041

2016 one

[kuchikirukia]

Ok, that 3.33s just posted reverts to the previous (3.32, 3.33,"3.33d mod v2") behavior: with a call of QTGMC() it slows down after ~300 frames. Though not halving. With FFMS2 showing excessive CPU util:

http://s29.postimg.org/71029fjhv/Untitled.jpg (http://postimg.org/image/71029fjhv/)

Without trim: 2.53 fps
With trim(50,0): 3.10 fps

[hello_hello]

You have another copy of avstp.dll in some auto-load directory.


Because I'm using Avisynth 2.6.0.6 there's only one auto-load directory in the registry.
I did a thorough search though, and there's no avstp.dll in a directory that could be an auto-load directory, plus it only loads when I put it at the root of the D drive. If I put it on another drive it doesn't load (unless it's in the avisynth plugins folder).

I even searched the registry for "PluginDir2_5" and only found one instance, pointing to the usual Avisynth/plugins folder. I'll try again later with some other plugins to see if they all autoload when residing at the root of the D drive, or if avstp.dll is the only one. I'm certain it is loading from there, unless I've lost my mind.

All my current jobs finished without any slowdowns, so I'll give the modified 3.33s a spin shortly with the problem sample (thanks real.finder), although I don't expect the result to be any different to yours kuchikirukia.

One thing I'd be keen to learn, is why that sample? What's different about it that it always causes issues with QTGMC?

[hello_hello]

So far the new QTGMC mod is behaving itself with that sample for me. Even when using preset="slow".

Have I mentioned that for this sample at least (and for me), the other fix, aside from Trim(50,0) was to use MP_Pipeline? It fixed the problem for these particular encodes, but I'm fairly sure there's been a few encodes since where it didn't. Why MP_Pipeline changes things in relation to slowdowns, I have no idea.

I'm copying the numbers from MeGUI's log file, and keep in mind this PC's old so it's slow. I've listed the encoding speed for comparing QTGMC versions.

QTGMC 3.33s (new version) - 3.89fps.
QTGMC 3.33s with Preset="slow" - 3.11fps
QTGMC 3.33s with MP_Pipeline - 4.66fps

QTGMC 3.33d (original version) - around 1fps (I didn't bother running the whole encode)
QTGMC 3.33d with Preset="slow" - around 1fps (I didn't bother running the whole encode)
QTGMC 3.33d with MP_Pipeline - 4.69fps

I'd use MP_Pipeline all the time for HD (with QTGMC and LSFMod), but as I'm still using XP and I tend to run two QTGMC encodes simultaneously, I think I run out of RAM when encoding two at a time because eventually encoding speed slows to a crawl. The individual encodes tend to be a little slower without it, but they run at "normal" speed from start to finish.

kuchikirukia,
I assume I'm not able to see as much info about the various processes as you because I'm running XP? I can't tell what ffms2 is doing. I'm pretty sure I tried using L-Smash instead at the time (for these samples) with no change, but are you using the exact script I posted at VideoHelp for testing? I ask, because I'm using an older version of ffmsindex as it tends to behave itself, but now and then ffmsindex does odd things due to the frame rate conversion MeGUI adds to the script. Mostly I think it's a good idea to include it, but now and then it makes fmsindex behave oddly (it tends to drop/repeat frames when the source is AVI). I mention it in case that's your ffms2 issue. I'm using version 2.21, I think. ffmsindex.exe is dated 21st June 2014.

MP_Pipeline("""
LoadPlugin("C:\Program Files\MeGUI\tools\ffms\ffms2.dll")
FFVideoSource("E:\test.mkv", cachefile="D:\test.mkv.ffindex", fpsnum=24, fpsden=1, threads=1)
QTGMC(InputType=1, Preset="medium", EzDenoise=1)
### prefetch: 16, 0
### ###
""")
crop(4, 2, -4, -2)
Spline36Resize(1280,720)
LSFMod(strength=75)
gradfun3()

[Groucho2004]

Because I'm using Avisynth 2.6.0.6 there's only one auto-load directory in the registry.
I did a thorough search though, and there's no avstp.dll in a directory that could be an auto-load directory, plus it only loads when I put it at the root of the D drive. If I put it on another drive it doesn't load (unless it's in the avisynth plugins folder).
Avstp.dll gets automatically loaded if it's in:
- a Avisynth autoload directory
- the directory where the script resides
- a directory to which the "PATH" environment variable points

If, for example, you or some program you installed added "d:\" to the "PATH" variable, it will be loaded.
I suggest you check that and also run the AVS Info Tool, saving the main and plugin info logs and post them here (pastebin).

[kuchikirukia]

You need to use threads=2 for it to split the FFMS2 and LSMASH threads out for you to see in process explorer.

[real.finder]

Have I mentioned that for this sample at least (and for me), the other fix, aside from Trim(50,0) was to use MP_Pipeline? It fixed the problem for these particular encodes

I don't use MeGUI but as I see it use avs4x264mod, maybe it has some issues with this case

using MP_Pipeline will do something like avs4x264mod but between script blocks

[hello_hello]

I don't use MeGUI but as I see it use avs4x264mod, maybe it has some issues with this case

using MP_Pipeline will do something like avs4x264mod but between script blocks

MeGUI only uses avs4x264mod when the 64 bit version of x264 is being used, but in my case I can't because I'm still running 32 bit XP (just for one more week, hopefully).

I checked the command line and there's definitely no avs4x264mod involved.

[Information] [23/10/15 6:21:24 PM] Job command line: "C:\Program Files\MeGUI\tools\x264\x264.exe" --level 4.1 --preset slow --tune film --crf 18.0 --keyint 240 --vbv-bufsize 50000 --vbv-maxrate 50000 --stitchable --colormatrix bt470bg --sar 1:1 --output "D:\test.mkv.mkv" "D:\test.mkv.avs"

[hello_hello]

Avstp.dll gets automatically loaded if it's in:
- a Avisynth autoload directory
- the directory where the script resides
- a directory to which the "PATH" environment variable points

In my case it would have been option number two. At least that clears up one mystery.
Cheers.

[hello_hello]

You need to use threads=2 for it to split the FFMS2 and LSMASH threads out for you to see in process explorer.

I tried but it didn't make any difference. I'm still not seeing that process. Could not using avs4x264mod have anything to do with it? Maybe ffms2 is ignoring the parameter (I'm using an older version) but later (maybe tomorrow) I'll run those encodes again with threads=2 and also with the latest ffms2 to see if anything changes. I pretty much always use threads=1 so I should check to make sure increasing the thread count doesn't have an adverse effect. I'll report back if anything changes.

[hello_hello]

Interesting.... the ffms2 MeGUI just downloaded for me (v2.22) appears in Process Explorer when threads=2. I repeated the previous encodes with threads=2. I don't really know what I should be looking for with Process Explorer anyway, so here's another list of encoding speeds.

QTGMC 3.33s (new version) - 3.93fps.
QTGMC 3.33s with Preset="slow" - 3.33fps
QTGMC 3.33s with MP_Pipeline - 4.82fps

QTGMC 3.33d (original version) - around 1fps (I didn't bother running the whole encode)
QTGMC 3.33d with Preset="slow" - around 1fps (I didn't bother running the whole encode)
QTGMC 3.33d with MP_Pipeline - 5.01fps

Speed for each encode was marginally faster than last time, probably thanks to the additional ffms2 thread, but the new mod version of QTGMC 3.33s still seems fine with my sample while 3.33d still encodes at a snails pace without MP_Pipeline. In other words, changing ffms2 versions didn't make any difference.

Edit: I just realised I was probably in dumb mode earlier and the reason the old ffms2 wasn't appearing in Process Explorer where I thought it should (when threads=2) was because I'd added MP_Pipeline to the script for testing before changing the thread count.

[real.finder]

MeGUI only uses avs4x264mod when the 64 bit version of x264 is being used, but in my case I can't because I'm still running 32 bit XP (just for one more week, hopefully).

I checked the command line and there's definitely no avs4x264mod involved.

[Information] [23/10/15 6:21:24 PM] Job command line: "C:\Program Files\MeGUI\tools\x264\x264.exe" --level 4.1 --preset slow --tune film --crf 18.0 --keyint 240 --vbv-bufsize 50000 --vbv-maxrate 50000 --stitchable --colormatrix bt470bg --sar 1:1 --output "D:\test.mkv.mkv" "D:\test.mkv.avs"

I didn't face your problem before

I still use https://www.dropbox.com/s/xhqggxamegia420/avisynth_20130309.7z because 2013.09.28 was do some crashes for me and didn't try newer one in actual encoding until now

and use MP_Pipeline most of the time

[hello_hello]

Thanks. I'll keep that version too, just in case, but at the moment the 3.33s you reverted for me seems to be behaving itself.

I'm not sure I can recall a time QTGMC caused a crash for me. Not since I gave up on MT Avisynth. Single threaded QTGMC has been rock solid, except for the "running at half speed" problem.
Of the DVD encodes I ran a couple of days ago with 3.33s (not the reverted version) a significant number started encoding at half speed and stayed that way, but they all ran at normal speed after I aborted them and re-started. For some I used Trim() to resume encoding where the previous encode stopped, but for some I simply aborted and restarted as they hadn't been running long. They still ran at normal speed the second time around though. It's odd....

The sample I attached to the post at VideoHelp always runs slow when using 3.33d. Why it's consistently slow when generally that's not the case, I don't know. Thinking about it though, the sample was from a group of files (TV show episodes) I was re-encoding at the time and most of them encoded at half speed unless I used Trim(). In the end I gave up and split every encode into two sections. A script to re-encode the first minute or so, then a second to re-encode the rest.

[creaothceann]

I don't really know what I should be looking for with Process Explorer anyway

I always activate these: http://i.imgur.com/tu3dxRh.png

Look at "CPU", "Threads", memory, "GPU", I/O and in the statusbar "Physical Usage (of RAM)".

[StainlessS]

I have no idea if this can help at all, BUT ...

Here a plug CacheTest (for want of a better name), not much tested, only started on it an hour or so ago.

CacheTest.cpp

#include <windows.h>
#include <stdio.h>
#include "avisynth.h"

class CacheTest : public GenericVideoFilter {
const char *Text;
const bool Always;
//
int Last;
int Instance;
char printString[2048];
void dprintf(char* fmt, ...);
static int InstCnt;
public:
PVideoFrame __stdcall GetFrame(int n, IScriptEnvironment *env);
CacheTest(PClip _child, const char* _text,bool _always,IScriptEnvironment *env);
~CacheTest(){};
};

int CacheTest::InstCnt = 0;

CacheTest::CacheTest(PClip _child, const char* _text,bool _always, IScriptEnvironment *env) :
GenericVideoFilter(_child),Text(_text),Always(_always),Last(-1) {
Instance = ++InstCnt;
}

PVideoFrame __stdcall CacheTest::GetFrame(int n, IScriptEnvironment *env) {
n = (n<0) ? 0 : (n >= vi.num_frames) ? vi.num_frames-1 : n;
if(n == Last) dprintf("%d] *** REPEATED REQUEST ***",n);
else if(n != Last+1) dprintf("%d] *** OUT OF ORDER REQUEST *** Previous frame requested was %d",n,Last);
else if(Always) dprintf("%d]",n);
Last = n;
PVideoFrame src = child->GetFrame(n, env);
return src;
}

void CacheTest::dprintf(char* fmt, ...) {
char *p=printString;
if(*Text=='\0') sprintf(p,"CacheTest_%04d: ",Instance);
else sprintf(p,"CacheTest_%04d_%s: ",Instance,Text);
while(*p++);
--p; // @ nul term
va_list argp;
va_start(argp, fmt);
vsprintf(p, fmt, argp);
va_end(argp);
while(*p++);
--p; // @ nul term
if(printString == p || p[-1] != '\n') {
p[0]='\n'; // append n/l if not there already
p[1]='\0';
}
OutputDebugString(printString);
}

AVSValue __cdecl Create_CacheTest(AVSValue args, void* user_data, IScriptEnvironment* env) {
return new CacheTest(args[0].AsClip(),args[1].AsString(""),args[2].AsBool(false),env);
}

extern "C" __declspec(dllexport) const char* __stdcall AvisynthPluginInit2(IScriptEnvironment* env) {
env->AddFunction("CacheTest", "c[text]s[Always]b",Create_CacheTest, 0);
return "`CacheTest' CacheTest plugin";
}


CacheRequestTwice.avs

# CacheRequestTwice.avs
#
# CacheTest(clip c, text="",Always=False)
# Sends text message to DebugView when frame requested is not previous frame + 1.
# Text allows add some kind of text label, Always==true = always output to debugview at each frame.
# Returns original frame, un-alterered.


TWICE = True
#TWICE = False

ALWAYS= False
TXT_A = "Porridge"
TXT_B = "Ham&Eggs"

AVISource("E:\V\StarWars.avi")
ORG=Last

A=((TWICE) ? Last.Invert : Last).CacheTest(Text=TXT_A,Always=ALWAYS)
B=((TWICE) ? Last.Invert : Last).CacheTest(Text=TXT_B,Always=ALWAYS)

D=Subtract(A,B)
# Return D # On about 7300 frames does not request any frame twice
L=Stackvertical(ORG,D)
# Return L # On about 7300 frames does not request any frame twice
R=StackVertical(A,B)
# Return R # On about 7300 frames does not request any frame twice (D and L play no part in output clip)
StackHorizontal(L,R) # Request frame twice every 30 frames (when TWICE=True)
return Last # Trim(2,0) here makes little difference


Output of script

00000002 2.03807402 [2496] CacheTest_0001_Porridge: 0] *** REPEATED REQUEST *** ???
00000003 2.07498646 [2496] CacheTest_0001_Porridge: 1] *** REPEATED REQUEST *** ???
00000004 3.19154382 [2496] CacheTest_0001_Porridge: 29] *** REPEATED REQUEST ***
00000005 4.38426638 [2496] CacheTest_0001_Porridge: 59] *** REPEATED REQUEST ***
00000006 5.58689880 [2496] CacheTest_0001_Porridge: 89] *** REPEATED REQUEST ***
00000007 6.78673887 [2496] CacheTest_0001_Porridge: 119] *** REPEATED REQUEST ***
00000008 7.98776102 [2496] CacheTest_0001_Porridge: 149] *** REPEATED REQUEST ***
00000009 9.18688488 [2496] CacheTest_0001_Porridge: 179] *** REPEATED REQUEST ***
00000010 10.38794994 [2496] CacheTest_0001_Porridge: 209] *** REPEATED REQUEST ***
00000011 11.58447838 [2496] CacheTest_0001_Porridge: 239] *** REPEATED REQUEST ***
00000012 12.78538609 [2496] CacheTest_0001_Porridge: 269] *** REPEATED REQUEST ***
00000013 13.98657513 [2496] CacheTest_0001_Porridge: 299] *** REPEATED REQUEST ***
00000014 15.18677521 [2496] CacheTest_0001_Porridge: 329] *** REPEATED REQUEST ***
00000015 16.38424683 [2496] CacheTest_0001_Porridge: 359] *** REPEATED REQUEST ***
00000016 17.58536720 [2496] CacheTest_0001_Porridge: 389] *** REPEATED REQUEST ***
00000017 18.78520393 [2496] CacheTest_0001_Porridge: 419] *** REPEATED REQUEST ***
00000018 19.98438835 [2496] CacheTest_0001_Porridge: 449] *** REPEATED REQUEST ***
00000019 21.18526459 [2496] CacheTest_0001_Porridge: 479] *** REPEATED REQUEST ***
00000020 22.38645744 [2496] CacheTest_0001_Porridge: 509] *** REPEATED REQUEST ***
00000021 23.58498955 [2496] CacheTest_0001_Porridge: 539] *** REPEATED REQUEST ***
00000022 24.78506088 [2496] CacheTest_0001_Porridge: 569] *** REPEATED REQUEST ***
00000023 25.98512840 [2496] CacheTest_0001_Porridge: 599] *** REPEATED REQUEST ***
00000024 27.18493271 [2496] CacheTest_0001_Porridge: 629] *** REPEATED REQUEST ***
00000025 28.38457108 [2496] CacheTest_0001_Porridge: 659] *** REPEATED REQUEST ***
00000026 29.58569908 [2496] CacheTest_0001_Porridge: 689] *** REPEATED REQUEST ***
00000027 30.78671837 [2496] CacheTest_0001_Porridge: 719] *** REPEATED REQUEST ***
00000028 31.98684120 [2496] CacheTest_0001_Porridge: 749] *** REPEATED REQUEST ***
00000029 33.18586731 [2496] CacheTest_0001_Porridge: 779] *** REPEATED REQUEST ***
00000030 34.38511658 [2496] CacheTest_0001_Porridge: 809] *** REPEATED REQUEST ***
00000031 35.58439636 [2496] CacheTest_0001_Porridge: 839] *** REPEATED REQUEST ***
00000032 36.78484726 [2496] CacheTest_0001_Porridge: 869] *** REPEATED REQUEST ***
00000033 37.98514175 [2496] CacheTest_0001_Porridge: 899] *** REPEATED REQUEST ***
00000034 39.18694305 [2496] CacheTest_0001_Porridge: 929] *** REPEATED REQUEST ***
00000035 40.38560486 [2496] CacheTest_0001_Porridge: 959] *** REPEATED REQUEST ***
00000036 41.58621597 [2496] CacheTest_0001_Porridge: 989] *** REPEATED REQUEST ***


You problem still tastes a little like this cache thing to me:- http://forum.doom9.org/showthread.php?p=1682827#post1682827

Anyways, here temp link (27KB dll + CacheTest.cpp only):- LINK REMOVED, See Here:- https://forum.doom9.org/showthread.php?t=184920

Hope I'm not sending you on a wild goose chase.

EDIT: The number after CacheTest_ is plugin instance number.

[hello_hello]

I have no idea if this can help at all, BUT ...

Here a plug CacheTest (for want of a better name), not much tested, only started on it an hour or so ago.

At the moment I'm running short on time, my brain's stubbornly refusing to engage for the day (I think I'm getting sick) and I'm using DebugView for the first time, so I did what I thought seemed correct..... added your CacheRequest script to my script, the cachetest.dll to the plugins folder, opened DebugView and ran the encode. Hopfully that's what I should be doing......

Is there a logical explanation as to why QTGMC 3.33d and 3.33s (reverted) run at different speeds without the CacheRequest stuff in the script, but when it's included they do?
They managed 2.8fps, which isn't as fast as without CacheRequest included, but I assume that's due to the increased resolution and it'd be "normal" speed. I ran those encodes twice to make sure I hadn't made a mistake, but they ran at the same speed again.

Am I doing it vaguely right? Here's the script I used:

LoadPlugin("C:\Program Files\MeGUI\tools\ffms\ffms2.dll")
FFVideoSource("E:\test.mkv", cachefile="D:\test.mkv.ffindex", fpsnum=24, fpsden=1, threads=1)

TWICE = True
#TWICE = False

ALWAYS= False
TXT_A = "Porridge"
TXT_B = "Ham&Eggs"

QTGMC(InputType=1, Preset="slow", EzDenoise=1)
crop(4, 2, -4, -2)
Spline36Resize(1280,720)
LSFMod(strength=75)
gradfun3()

ORG=Last
A=((TWICE) ? Last.Invert : Last).CacheTest(Text=TXT_A,Always=ALWAYS)
B=((TWICE) ? Last.Invert : Last).CacheTest(Text=TXT_B,Always=ALWAYS)

D=Subtract(A,B)
# Return D # On about 7300 frames does not request any frame twice
L=Stackvertical(ORG,D)
# Return L # On about 7300 frames does not request any frame twice
R=StackVertical(A,B)
# Return R # On about 7300 frames does not request any frame twice (D and L play no part in output clip)
StackHorizontal(L,R) # Request frame twice every 30 frames (when TWICE=True)
return Last # Trim(2,0) here makes little difference


And here's the DebugView log files. I don't understand why RemoveDirt and SSETools make an appearance, but I've got to spend some time in the real world at the moment.....

Thanks.

QTGMC 3.33s (revert)
00000001 0.00000000 [2416] RemoveDirt 0.9
00000002 0.01150656 [2416] SSETools 0.1
00000003 1.24683654 [2808] RemoveDirt 0.9
00000004 1.25846589 [2808] SSETools 0.1
00000005 3.63619494 [2808] CacheTest_0001_Porridge: 0] *** REPEATED REQUEST ***
00000006 4.03579569 [2808] CacheTest_0001_Porridge: 1] *** REPEATED REQUEST ***
00000007 12.31108665 [2808] CacheTest_0001_Porridge: 29] *** REPEATED REQUEST ***
00000008 28.28722191 [2808] CacheTest_0001_Porridge: 59] *** REPEATED REQUEST ***
00000009 52.34462738 [2808] CacheTest_0001_Porridge: 89] *** REPEATED REQUEST ***
00000010 71.32291412 [2808] CacheTest_0001_Porridge: 119] *** REPEATED REQUEST ***
00000011 80.03551483 [2808] CacheTest_0001_Porridge: 149] *** REPEATED REQUEST ***
00000012 88.79595947 [2808] CacheTest_0001_Porridge: 179] *** REPEATED REQUEST ***
00000013 97.56908417 [2808] CacheTest_0001_Porridge: 209] *** REPEATED REQUEST ***
00000014 106.45343781 [2808] CacheTest_0001_Porridge: 239] *** REPEATED REQUEST ***
00000015 115.41027069 [2808] CacheTest_0001_Porridge: 269] *** REPEATED REQUEST ***
00000016 124.43800354 [2808] CacheTest_0001_Porridge: 299] *** REPEATED REQUEST ***
00000017 133.76379395 [2808] CacheTest_0001_Porridge: 329] *** REPEATED REQUEST ***
00000018 143.15376282 [2808] CacheTest_0001_Porridge: 359] *** REPEATED REQUEST ***
00000019 152.19247437 [2808] CacheTest_0001_Porridge: 389] *** REPEATED REQUEST ***
00000020 161.25598145 [2808] CacheTest_0001_Porridge: 419] *** REPEATED REQUEST ***
00000021 170.26434326 [2808] CacheTest_0001_Porridge: 449] *** REPEATED REQUEST ***
00000022 179.31782532 [2808] CacheTest_0001_Porridge: 479] *** REPEATED REQUEST ***
00000023 188.51396179 [2808] CacheTest_0001_Porridge: 509] *** REPEATED REQUEST ***
00000024 197.82969666 [2808] CacheTest_0001_Porridge: 539] *** REPEATED REQUEST ***
00000025 207.34350586 [2808] CacheTest_0001_Porridge: 569] *** REPEATED REQUEST ***
00000026 217.89701843 [2808] CacheTest_0001_Porridge: 599] *** REPEATED REQUEST ***
00000027 227.41085815 [2808] CacheTest_0001_Porridge: 629] *** REPEATED REQUEST ***
00000028 236.44493103 [2808] CacheTest_0001_Porridge: 659] *** REPEATED REQUEST ***
00000029 245.54722595 [2808] CacheTest_0001_Porridge: 689] *** REPEATED REQUEST ***
00000030 262.36642456 [2416] RemoveDirt 0.9
00000031 262.37792969 [2416] SSETools 0.1


QTGMC 3.33d
00000001 0.00000000 [2416] RemoveDirt 0.9
00000002 0.01142434 [2416] SSETools 0.1
00000003 7.82843876 [2416] RemoveDirt 0.9
00000004 7.84005737 [2416] SSETools 0.1
00000005 9.08288383 [2344] RemoveDirt 0.9
00000006 9.09452724 [2344] SSETools 0.1
00000007 11.57814884 [2344] CacheTest_0001_Porridge: 0] *** REPEATED REQUEST ***
00000008 12.07485294 [2344] CacheTest_0001_Porridge: 1] *** REPEATED REQUEST ***
00000009 24.30343246 [2344] CacheTest_0001_Porridge: 29] *** REPEATED REQUEST ***
00000010 36.43482590 [2344] CacheTest_0001_Porridge: 59] *** REPEATED REQUEST ***
00000011 46.81768036 [2344] CacheTest_0001_Porridge: 89] *** REPEATED REQUEST ***
00000012 56.76725769 [2344] CacheTest_0001_Porridge: 119] *** REPEATED REQUEST ***
00000013 66.44585419 [2344] CacheTest_0001_Porridge: 149] *** REPEATED REQUEST ***
00000014 76.06328583 [2344] CacheTest_0001_Porridge: 179] *** REPEATED REQUEST ***
00000015 85.59259796 [2344] CacheTest_0001_Porridge: 209] *** REPEATED REQUEST ***
00000016 95.26169586 [2344] CacheTest_0001_Porridge: 239] *** REPEATED REQUEST ***
00000017 105.05858612 [2344] CacheTest_0001_Porridge: 269] *** REPEATED REQUEST ***
00000018 114.89687347 [2344] CacheTest_0001_Porridge: 299] *** REPEATED REQUEST ***
00000019 124.96822357 [2344] CacheTest_0001_Porridge: 329] *** REPEATED REQUEST ***
00000020 134.88223267 [2344] CacheTest_0001_Porridge: 359] *** REPEATED REQUEST ***
00000021 144.54713440 [2344] CacheTest_0001_Porridge: 389] *** REPEATED REQUEST ***
00000022 154.18771362 [2344] CacheTest_0001_Porridge: 419] *** REPEATED REQUEST ***
00000023 163.82351685 [2344] CacheTest_0001_Porridge: 449] *** REPEATED REQUEST ***
00000024 173.55781555 [2344] CacheTest_0001_Porridge: 479] *** REPEATED REQUEST ***
00000025 183.33503723 [2344] CacheTest_0001_Porridge: 509] *** REPEATED REQUEST ***
00000026 193.13240051 [2344] CacheTest_0001_Porridge: 539] *** REPEATED REQUEST ***
00000027 203.16264343 [2344] CacheTest_0001_Porridge: 569] *** REPEATED REQUEST ***
00000028 213.75897217 [2344] CacheTest_0001_Porridge: 599] *** REPEATED REQUEST ***
00000029 223.78259277 [2344] CacheTest_0001_Porridge: 629] *** REPEATED REQUEST ***
00000030 233.47032166 [2344] CacheTest_0001_Porridge: 659] *** REPEATED REQUEST ***
00000031 243.13763428 [2344] CacheTest_0001_Porridge: 689] *** REPEATED REQUEST ***
00000032 260.11117554 [2416] RemoveDirt 0.9
00000033 260.12280273 [2416] SSETools 0.1

[StainlessS]

Sorry, I should have explained a little better.

The script given was just a demo, shows that with that particular script that every 30 frames the cache 'dont work'.
(dont ask me why it dont work, 'its a mysterwy' [as Toyah Wilcox used to pronounce it]).
Dont use given script, use your own labels if required eg 'Node_A1", or whatever (Porridge etc was just demo hehe :) ).

Intention is that an instance of plug be inserted between some number of clips (between filters) to see what is happening.
If you eg inserted an instance of the plug between ALL filters then if cache failure is responsible at a particular location,
then you should be able to find it and might be able to play around with the script and try to make it go away.
You might have to be somewhat determined to track it down. Anyway, the idea occurred to me that it might be handy to have
a plug that does this, and so I did it and hoped that it might be of use, if not then I'm sure that I might one day have use of it
(or a modification thereof to pin point other anomalous behaviour).

By the way, the plug should have little effect on speed (provided it dont find gazillions of out of order frame requests
which might suggest that a plug or script aint playing nice).

EDIT: This GetFrame func, does not take much time unless it has to print to DebugView window (fast anyway),
The actual request for a frame just passes a pointer to a cached frame.

PVideoFrame __stdcall CacheTest::GetFrame(int n, IScriptEnvironment *env) {
n = (n<0) ? 0 : (n >= vi.num_frames) ? vi.num_frames-1 : n; // range limit frame n to legal values
if(n == Last) dprintf("%d] *** REPEATED REQUEST ***",n);
else if(n != Last+1) dprintf("%d] *** OUT OF ORDER REQUEST *** Previous frame requested was %d",n,Last);
else if(Always) dprintf("%d]",n);
Last = n; // remember last frame for next time around
PVideoFrame src = child->GetFrame(n, env); // get pointer to current frame and pass on to next filter. (almost no time)
return src;
}


EDIT: I guess I should say that I assumed best place to scatter some instances would be inside QTGMC(),
perhaps best done by script author.

that every 30 frames the cache 'dont work'.
See the frame numbers in DebugView log as in "Porridge: 29] *** ".

EDIT: Its 03:00 AM right now and I've gotta get some shut eye. I'll take a look at the scripts tomorrow and see if I can
find some good places to insert a few instances of the cache plug thing. I will be unlikely to be able to test,
I'm on lowly duel core Core Duo 2.4Ghz XP32 and dont usually have the patience to deal with QTGMC.

[hello_hello]

Thanks. I'll await your suggestion before I do any more testing.

Mind you I'm starting to think I'm losing my mind. I ran the encode on my test sample again using QTGMC 3.33d today it ran at normal speed. I tested it twice. Then I reverted back to the previous ffms2, tested it again and it still ran at normal speed. Suddenly my 100% repeatable problem can't be repeated.

Okay.... the penny dropped..... I couldn't think of a single thing that'd changed in the last few days. Same programs running, I hadn't rebooted.....
Then I realised, the one change I did make was to put CacheTest.dll in the Avisynth plugins folder, so I deleted it and tested again. Encoding speed dropped from 3.27fps to 1.28fps. There's nothing CacheTest related in the script (it's the original script I've been using for testing), but with CacheTest.dll in the plugins folder QTGMC 3.33d runs at normal speed. Without CacheTest.dll there it runs at half speed. I've heard fact is often stranger than fiction, but that's a true story. I've tested it twice.

[StainlessS]

Can you empty out your plugins folder with exception of plugs in-use, and for luck do a reboot.
I know all you out there believe that you can run a machine without reboot forever and it always gonna be hunky dory,
but, I dont have as much faith in MS as you-all do.

The CacheTest thing (inserted between two filters) will insert an extra instance of an avisynth cache, so when it says
"repeated request", it means repeated request on the cache nearer to output than the CacheTest thing, there is still a
cache on the nearer to input side, so that could actually help things where repeat requests are flagged.
If you added two instances of CacheTest between two filters and only one of them issues messages, then the first instance
extra cache is beneficial and the additional cache provided by second instance Cachetest is not of use.
I think I'll add a "Silent" arg to the Cachetest thing which will allow switching off the messages, so you can just leave in-situ
to keep permanent extra cache without messages.

I've only just woken up, I must have slept for at least 18 hours, I knew I was a bit knackered, but more so than I had thought.
Gonna have something to eat and a coffee, I'll make mod to CacheTest and up soon.

[Groucho2004]

Can you empty out you plugins folder with exception of plugs in-use
I asked him/her to run the AVS Info tool and post the logs (http://forum.doom9.org/showthread.php?p=1744020#post1744020) to see if there's anything fishy in the plugin directory but he/she didn't seem to think it would be useful.

[StainlessS]

He/she/it, should do as Groucho suggests. :)

Here update to CacheTest() with added Bool Silent arg (default false).


#include <windows.h>
#include <stdio.h>
#include "avisynth.h" // Avisynth VERSION 3 HEADER (Avisynth v2.58, OK for v2.6 too)

class CacheTest : public GenericVideoFilter {
// args
const char *Text;
const bool Always;
const bool Silent;
// vars
int PrevFrm;
int Instance;
char printString[2048];
static int InstCnt; // Single unique variable, common to all instances of the plugin.
// private member funcs
void dprintf(char* fmt, ...);
public:
PVideoFrame __stdcall GetFrame(int n, IScriptEnvironment *env);
CacheTest(PClip _child, const char* _text,bool _always,bool _silent,IScriptEnvironment *env);
~CacheTest(){};
};

int CacheTest::InstCnt = 0; // Initialise single instance variable on dll load.

CacheTest::CacheTest(PClip _child, const char* _text,bool _always,bool _silent, IScriptEnvironment *env) :
GenericVideoFilter(_child),Text(_text),Always(_always),Silent(_silent),PrevFrm(-1) {
Instance = ++InstCnt; // Instance identifier number of this instance of the plugin.
}

PVideoFrame __stdcall CacheTest::GetFrame(int n, IScriptEnvironment *env) {
n = (n<0) ? 0 : (n >= vi.num_frames) ? vi.num_frames-1 : n; // Range limit frame number n
if(!Silent) { // Messages permitted ?
if(n == PrevFrm) dprintf("%4d] *** REPEAT REQUEST",n);
else if(n != PrevFrm+1) dprintf("%4d] *** OUT OF ORDER REQUEST, Previous [%d]",n,PrevFrm);
else if(Always) dprintf("%4d]",n);
PrevFrm = n; // Remember frame requested for next iteration.
}
PVideoFrame src = child->GetFrame(n, env); // Get pointer to cached frame (un-altered frame)
return src; // Pass pointer to next filter in chain.
}

void CacheTest::dprintf(char* fmt, ...) {
char *p=printString; // address of buffer in class
if(*Text=='\0') sprintf(p,"CacheTest_%04d: ",Instance); // Prepend desired identifier string
else sprintf(p,"CacheTest_%04d_%s: ",Instance,Text); //
while(*p++); // Find end of identifier string, End @ nul + 1
--p; // @ nul term (back up 1 to point at nul)
va_list argp;
va_start(argp, fmt);
vsprintf(p, fmt, argp); // Add the message to the prepended identifier string
va_end(argp);
while(*p++); // Find end of message string, End @ nul + 1
--p; // @ nul term (back up 1 to point at nul)
if(printString == p || p[-1] != '\n') {
p[0]='\n'; // append n/l if not there already
p[1]='\0';
}
OutputDebugString(printString); // Write to DebugView window (google)
}

AVSValue __cdecl Create_CacheTest(AVSValue args, void* user_data, IScriptEnvironment* env) {
return new CacheTest(args[0].AsClip(),args[1].AsString(""),args[2].AsBool(false),args[3].AsBool(false),env);
}

extern "C" __declspec(dllexport) const char* __stdcall AvisynthPluginInit2(IScriptEnvironment* env) {
env->AddFunction("CacheTest", "c[text]s[Always]b[Silent]b",Create_CacheTest, 0);
return "`CacheTest' CacheTest plugin";
}


and DEMO test script CacheRequestTwice.avs

### CacheRequestTwice.avs
#
# CacheTest(clip c,String "text"="",Bool "Always"=False,Bool "Silent"=False)
#
# Sends text message to DebugView when frame requested is not previous frame + 1.
# Text allows add some kind of text label, Always==true = always output to debugview at each frame.
# Silent==True switches off ALL messages (overrides ALWAYS).
# Returns original frame, un-alterered.
# Insert between filters to see if there are any repeat requests for frame, or out of order frame requests.
# With Silent==True, Leaves an additional Cache between filters, without writing messages to DebugView.
#
# Shows messages as in "CacheTest_0005_Node_A1: 1001] *** REPEAT REQUEST" for plugin instance 5 where text = "Node_A1" and
# there is a repeat request for frame 1001.
###

TWICE = True # Causes repeat requests for some reason ("it's a mysterwy")
#TWICE = False # No repeat requests

TXT_A = "Porridge"
TXT_B = "Ham&Eggs"
ALWAYS= False
SILENT=False

AVISource("E:\V\StarWars.avi")
ORG=Last

A=((TWICE) ? Last.Invert : Last).CacheTest(Text=TXT_A,Always=ALWAYS,Silent=SILENT)
B=((TWICE) ? Last.Invert : Last).CacheTest(Text=TXT_B,Always=ALWAYS,Silent=SILENT)

D=Subtract(A,B)
# Return D # On about 7300 frames does not request any frame twice
L=Stackvertical(ORG,D)
# Return L # On about 7300 frames does not request any frame twice
R=StackVertical(A,B)
# Return R # On about 7300 frames does not request any frame twice (D and L play no part in output clip)
StackHorizontal(L,R) # Request frame twice every 30 frames (when TWICE=True)
return Last


Temp link here (28kb):- LINK REMOVED see here:- https://forum.doom9.org/showthread.php?t=184920


CacheTest.cpp + dll + CacheRequestTwice.avs ONLY.
Need Avisynth.h VERSION 3 (for v2.58), compile with any compiler.

EDIT: Note, you can add a filter to DebugView to only show messages with eg ":" in them (CacheTest puts a ':' in every message).
Also note, any process can send stuff to DebugView, not just CacheTest, the filter helps reduce number of messages to inspect.

EDIT: NOTE, from original issue posted here:- http://forum.doom9.org/showthread.php?p=1682827#post1682827
Affects:- Avisynth v2.6Alpha4, Avisynth v2.6Alpha5, Avisynth v2.6+r1576
Not Affected:- Avisynth v2.57, Avisynth v2.58, Avisynth v2.6Alpha3
I assume that it is also valid for the above DEMO script, but not gonna test it all out again.

[kuchikirukia]

I asked him/her to run the AVS Info tool and post the logs (http://forum.doom9.org/showthread.php?p=1744020#post1744020) to see if there's anything fishy in the plugin directory but he/she didn't seem to think it would be useful.

I don't even have an auto-load directory and not only have I been repeating his findings, I noticed them first.

This is repeatable. Why would you try to troubleshoot it on his machine when you can watch it in action on yours?

Anyway, just checked masktools2 vs mt_masktools-26. Same on both.
rgtools vs repairsse2 and removegrainsse2 in the qtgmc plugins pack. Same on both. (Not a comprehensive test of speeds and with all the qtgmc versions, just ran a preset=slower run and noticed both still caused ffms2 to act up past 25%.)
Considering it does this with inputtype=1 and deinterlacing, and I don't see in process explorer that nnedi3 is being called in inputtype=1, that shouldn't have anything to do with it.

[real.finder]

after seeing the replies, I think it cache bug as StainlessS said

[Groucho2004]

I don't even have an auto-load directory and not only have I been repeating his findings, I noticed them first.

This is repeatable. Why would you try to troubleshoot it on his machine when you can watch it in action on yours?
Mainly because of these findings which seem odd:
Then I realised, the one change I did make was to put CacheTest.dll in the Avisynth plugins folder, so I deleted it and tested again. Encoding speed dropped from 3.27fps to 1.28fps. There's nothing CacheTest related in the script (it's the original script I've been using for testing), but with CacheTest.dll in the plugins folder QTGMC 3.33d runs at normal speed. Without CacheTest.dll there it runs at half speed. I've heard fact is often stranger than fiction, but that's a true story. I've tested it twice.
Avisynth, particularly in combination with several plugins, is a highly complex and rather buggy system that can produce different results on different hardware/OS.

Stainless' suggestion to start with a clean slate in the plugin directory makes sense and removes some of the complexity.

[hello_hello]

I've been sick which is why I haven't posted for a bit.

When I first noticed the problem I tried testing a few different versions of QTGMC with various flavours of the plugins it uses, and the only thing that fixed the problem (aside from Trim(50,0) and MP_Pipeline), was using a version of QTGMC prior to 3.33d. I also tried emptying out the plugins folder (aside from those required) but that didn't help. I tried the "starting with a clean slate" test weeks ago.

I tested again today using a second PC after emptying the auto-loading plugins folder of everything but the plugins listed below. The PC in question had a hard drive die a little while ago and I restored an XP image with no software. All I've installed on it since is MeGUI, Avisynth and the various runtimes required for plugins. Adding CacheTest.dll to the Avisynth plugins folder didn't cause QTGMC 3.33d to encode at normal speed (which was disappointing in a way).

LoadPlugin("C:\Program Files\MeGUI\tools\ffms\ffms2.dll")
FFVideoSource("E:\test.mkv", cachefile="E:\test.mkv.ffindex", fpsnum=24, fpsden=1, threads=1)
QTGMC(InputType=1, Preset="medium", EzDenoise=1)
crop(4, 2, -4, -2)
Spline36Resize(1280,720)
LSFMod(strength=75)
gradfun3()

QTGMC 3.33d ran at 1.17fps
QTGMC 3.33e (reverted) ran at 3.09fps

dither.avsi
dither.dll
FFT3DFilter.dll
LSFmod.avsi
masktools2.dll
mt_xxpand_multi.avsi
mvtools2.dll
nnedi3.dll
QTGMC.avsi (3.33d or 3.33s reverted)
RgTools.dll

AvisynthPluginInfo
C:\Program Files\AviSynth\plugins\dither.dll
Timestamp: July 16, 2015, 19:46:00
MD5 Hash: FB53AB5DFB051297B353B90767C4D060
DLL Dependencies: KERNEL32.dll
Plugin version: AVS 2.5 Plugin
No VersionInfo available

C:\Program Files\AviSynth\plugins\FFT3DFilter.dll
Timestamp: February 20, 2007, 22:43:00
MD5 Hash: 2DDD22752BBAF5943A4B208AEFCD9E93
DLL Dependencies: USER32.dll, KERNEL32.dll
Plugin version: AVS 2.5 Plugin
FILEVERSION: 2.1.1.0
PRODUCTVERSION: 2.1.1.0
Language: Language Neutral
Comments: Frequency Domain filter. Uses external FFTW3.DLL library.
CompanyName: A.G.Balakhnin aka Fizick, bag@hotmail.ru, http://avisynth.org.ru
FileDescription: FFT3DFilter plugin for Avisynth 2.5
FileVersion: 2, 1, 1, 0
ProductVersion: 2, 1, 1, 0
InternalName: FFT3DFilter
LegalCopyright: Copyright © 2004-2006 A.G.Balakhnin
LegalTrademarks:
OriginalFilename: FFT3DFilter.dll
PrivateBuild:
ProductName: FFT3DFilter
SpecialBuild:

C:\Program Files\AviSynth\plugins\masktools2.dll
Timestamp: December 20, 2013, 20:02:00
MD5 Hash: 05370E2F53AA48DFCED0E54B0C0F458E
DLL Dependencies: KERNEL32.dll, MSVCP110.dll, MSVCR110.dll
Plugin version: AVS 2.6 Plugin
FILEVERSION: 2.1.0.0
PRODUCTVERSION: 2.1.0.0
Language: English (United States)
Comments:
CompanyName:
FileDescription: Masktools Dynamic Link Library
FileVersion: 2.1.0.0
ProductVersion: 2.1.0.0
InternalName: Masktools 2.0
LegalCopyright: Copyright (C) 2013
LegalTrademarks:
OriginalFilename: masktools2.dll
PrivateBuild:
ProductName: Masktools Dynamic Link Library
SpecialBuild:

C:\Program Files\AviSynth\plugins\mvtools2.dll
Timestamp: July 17, 2012, 21:37:00
MD5 Hash: 9AFD5E0AC0E329761DFCC6F98FF04566
DLL Dependencies: KERNEL32.dll
Plugin version: AVS 2.5 Plugin
FILEVERSION: 2.6.0.5
PRODUCTVERSION: 2.6.0.5
Language: Process Default Language
Comments: Motion estimation and compensation
CompanyName: A.G.Balakhnin aka Fizick, fizick@avisynth.org.ru
FileDescription: MVTools plugin for AviSynth
FileVersion: 2.6.0.5
ProductVersion: 2, 6, 0, 5
InternalName: mvtools
LegalCopyright: ©2004 Manao, ©2005 Fizick, ©2008 TSchniede under GNU GPL v2
LegalTrademarks:
OriginalFilename: mvtools.dll
PrivateBuild:
ProductName: mvtools
SpecialBuild:

C:\Program Files\AviSynth\plugins\nnedi3.dll
Timestamp: May 27, 2015, 04:17:14
MD5 Hash: 3B72B24C7DD548ED1FA9CC04B3221AA0
DLL Dependencies: KERNEL32.dll
Plugin version: AVS 2.6 Plugin
FILEVERSION: 0.9.4.10
PRODUCTVERSION: 0.9.4.10
Language: English (United States)
Comments:
CompanyName:
FileDescription: nnedi3 v0.9.4.10 for Avisynth 2.6.x
FileVersion: 0.9.4.10
ProductVersion: 0.9.4.10
InternalName:
LegalCopyright: Copyright (C) 2010-2011 Kevin Stone
LegalTrademarks:
OriginalFilename: nnedi3.dll
PrivateBuild:
ProductName:
SpecialBuild:

C:\Program Files\AviSynth\plugins\RgTools.dll
Timestamp: February 12, 2014, 21:18:00
MD5 Hash: 92BA2165C2DB0E3694B0213024F12C52
DLL Dependencies: MSVCR110.dll, KERNEL32.dll
Plugin version: AVS 2.6 Plugin
No VersionInfo available

Now I've got a setup where I know trying to find the problem doesn't fix the problem, therefore making it impossible to find (ie putting CacheTest.dll in the plugins folder doesn't change anything on it's own), I'll go through StainlessS's cachetest instructions and try some more testing, but it'll have to be later on today, or maybe tomorrow.

Cheers.

PS One thing I don't think I have tried is reverting back to Avisynth 2.5.8. I'm not sure if the above plugins are 2.5.8 compatible though.
I'm reasonably sure, when I first discovered the problem, I tested both Avisynth and Avisynth+ (probably Avisynth 2.6.0.5 or 2.6.0.6, but I'm not 100% sure about the Avisynth+ version) with the same result, which made me think it's most likely a plugin issue and not an Avisynth one. Maybe that was a bad assumption, and it's a problem Avisynth and Avisynth+ have in common?
Anyone got a setup where they can easily switch between Avisynth versions for testing? Maybe I need to start paying attention to the thread on that subject.

[kuchikirukia]

Versions prior to 3.33d aren't good, they're just not as broken. As I said, I found slowdowns in 3.32 and 3.33 while using preset=slower. They just don't drop to half.

[LouieChuckyMerry]

I hope your crud is clearing up, hello_hello :) . Maybe this would help your testing: Conveniently switching Avisynth versions (https://www.doom9.org/showthread.php?p=1720988#post1720988). I can barely use a single version of AviSynth, ha ha, but I thought it was a pretty cool concept and had it set up quite quickly so it must be foolproof ;) .

[hello_hello]

Versions prior to 3.33d aren't good, they're just not as broken. As I said, I found slowdowns in 3.32 and 3.33 while using preset=slower. They just don't drop to half.

Yeah.... I ran some DVD encodes today and was disappointed to discover that seems to be the case. I experienced slowdowns again. Well... I was using the reverted version of 3.33s so that's not the fix I hoped it'd be.

The first two DVD encodes I ran simultaneously encoded at an average of 7.21fps and 3.10fps, so one ran at full speed while the other ran at half speed.

I didn't realise real.finder had posted a link to an earlier Avisynth version a while back. I thought it was an earlier QTGMC and I hadn't got around to testing it yet. So I replaced avisynth.dll with that version (2.6.0.3) and tested the problem sample/script with QTGMC 3.33d. It encoded at normal speed. Actually, it encoded at 4.00fps, which is just a fraction faster than normal speed for Avisynth 2.6.0.6 using this PC. That seems quite promising.

I've switched to QTGMC 3.33s (not the reverted version) with Avisynth 2.6.0.3 and gone back to the DVD encodes I was running. When I aborted the last two, they were both sitting on a steady 2.10fps. I've restarted them both and the one I restarted from the middle (using Trim) has settled down to a steady 6.91fps. The second one restarted from scratch and it's dropping slowly but steadily. It's down to 3.85fps and falling. &^*%!!!!!!!!!!!

This is starting to do my head in. The DVD encodes I'm running look like this (with DGDecode).

AssumeTFF()
Trim(0,724).TFM().ChangeFPS(50,1)\
++Trim(725,34993).QTGMC(sharpness=0.7)\
++Trim(34994,0).TFM().ChangeFPS(50,1)
crop(20, 8, -18, -8)
Spline36Resize(640,480)
gradfun3()

I've tried QTGMC 3.32, 3.33, and 3.33d and the result is the same (with Avisynth 2.6.0.3). As soon as the encode hits frame 725 it slows down (naturally) but continues to gradually slow. I'm watching QTGMC 3.33 slow down to 3.76fps at frame 3000 and still falling (that'd be frame 1500 in the source video as the output has double the frame rate).
If I remove the first trim from the script and start encoding at frame 725, encoding speed settles down to a steady 7.90fps by the 3000th frame.

I guess getting lucky isn't going to happen. The fact Avisynth 2.6.0.3 and 2.6.0.6 produce different results with my problem sample seems to indicate it's an Avisynth issue, but QTGMC makes them both misbehave with other encodes.
I want to go back to finishing my current encoding jobs, then I guess I'll look at experimenting with cachetest.

[hello_hello]

Maybe this would help your testing: Conveniently switching Avisynth versions (https://www.doom9.org/showthread.php?p=1720988#post1720988). I can barely use a single version of AviSynth, ha ha, but I thought it was a pretty cool concept and had it set up quite quickly so it must be foolproof ;) .

I'll definitely have a look. For the moment I'm going to finish these encodes by splitting the scripts to prevent any slowdowns (hopefully) then I'll try to find the motivation to start testing again.

Cheers.

[hello_hello]

I'm starting to think this problem's been around for quite a while. Back in July 2013 (that's the file dates of the scripts) I encoded some DVDs while de-interlacing with QTGMC. I also used a whole bunch of trims to do colour adjustments. I then used that script as the source for another script with a whole bunch of different trims for cropping and resizing. In the end I gave up because each and every time the encodes would start off fine but gradually slow to almost nothing. My way around it was to do the encoding in two steps using a lossless intermediate but it seemed like the kind of thing that should have worked fine. I was probably still using QTGMC 3.32 and Avisynth 2.5.8 back than. Maybe it's completely unrelated....

[real.finder]

I'm starting to think this problem's been around for quite a while. Back in July 2013 (that's the file dates of the scripts) I encoded some DVDs while de-interlacing with QTGMC. I also used a whole bunch of trims to do colour adjustments. I then used that script as the source for another script with a whole bunch of different trims for cropping and resizing. In the end I gave up because each and every time the encodes would start off fine but gradually slow to almost nothing. My way around it was to do the encoding in two steps using a lossless intermediate but it seemed like the kind of thing that should have worked fine. I was probably still using QTGMC 3.32 and Avisynth 2.5.8 back than. Maybe it's completely unrelated....

try 2012.03.31 and 2012.04.03 and 2012.05.16 from http://forum.doom9.org/showthread.php?t=148782

it should work with last avs 2.6 plugins and in the same time it should hasn't avs 2.6 cache issues

If it work or not then try a newer one (2012.08.28 and up) until face the one that has these issues and tell us the results

[hello_hello]

real.finder,

I'll give them a try but it's not an easy thing to test as it's not always possible to find a sample that reproduces the problem every time with different Aviynth versions.

The versions you linked to are MT Avisynth. I'm running in single threaded mode. I assume that doesn't matter?
If I make any interesting discoveries I'll report back, but it mightn't be overly quickly given QTGMC is slow which makes testing slow and tedious.

Cheers.

[real.finder]

real.finder,

I'll give them a try but it's not an easy thing to test as it's not always possible to find a sample that reproduces the problem every time with different Aviynth versions.

The versions you linked to are MT Avisynth. I'm running in single threaded mode. I assume that doesn't matter?
If I make any interesting discoveries I'll report back, but it mightn't be overly quickly given QTGMC is slow which makes testing slow and tedious.

Cheers.

if you didn't use (setmtmode) it will be like normal avs

you can test with official alpha 3 but you will need old avs 2.6 plugins (Avisynth VERSION 4 HEADER) and the one that must you have for this is http://manao4.free.fr/masktools-v2.0a48.zip (or from Modded Plugins Package by -Vit- in QTGMC thread) you will need it for mt (2012.03.31 and 2012.04.03 and 2012.05.16) too to avoid access violation errors

[hello_hello]

Yeah.... I've just been through an access violation error frenzy while trying those older versions. I've tried both mt_masktools-25.dll and mt_masktools-26.dll from the zip file you linked to but still all I'm getting are access violation errors. That's sapped my enthusiasm for testing pretty substantially at the moment. I was going to switch Avisynth versions between encoding jobs and try to test while I encode, but it looks like it's not going to be anywhere near that simple.

[real.finder]

Yeah.... I've just been through an access violation error frenzy while trying those older versions. I've tried both mt_masktools-25.dll and mt_masktools-26.dll from the zip file you linked to but still all I'm getting are access violation errors. That's sapped my enthusiasm for testing pretty substantially at the moment. I was going to switch Avisynth versions between encoding jobs and try to test while I encode, but it looks like it's not going to be anywhere near that simple.

use the 2.5 plugins (for all plugins that QTGMC need) except for masktools

[hello_hello]

I'm fairly sure I've had enough for a while. I can go back to testing at some stage soon but I need a break for now. The video I was trying to encode today gave me so much grief I finished up converting it to lossless AVIs in sections, appended the AVIs together and re-encoding that. If I tried to combine multiple scripts using Import (I was taking sections from two different sources) encoding speed slowed to a crawl.

I've run a few quick tests using the second PC and it's not looking promising. I used avisynth 2012.03.31 and the plugins from the original QTGMC plugins package, mvtools 2.6.0.5 (originally supplied as part of the dither package), the dither 1.24 plugin and QTGMC 3.33d (not reverted). I tried a script and DVD source that was giving me trouble earlier, and it seemed to behave itself when I ran an encode using MeGUI/x264 (although maybe not when I converted it to lossless AVI with VirtualDub, but I only tried that once).
The big let-down was my original test sample. Using an older version of Avisynth with older plugins seems a little slower anyway (hard to know for sure given I was using a different PC) but the first encode I ran with the test sample/script managed 1.17fps according to MeGUI's log file. When I put Trim(50,0) at the end and tried again, it averaged 3.09fps. Bummer.

[hello_hello]

One last try for the moment. Replaced avisynth.dll with version 2.5.8.5. Replaced mt_masktools-26.dll with mt_masktools-25.dll from the original QTGMC plugins package. Tested QTGMC 3.33d (not reverted).

Test sample/script without Trim - 1.17fps

Test sample/script with Trim(50,0) - 3.08fps

I don't mind coming back to this some time in the near future. I can play around with cachetest if there's a chance it might provide some sort of insight, but for now I've definitely had enough. At least it seems certain if it's an Avisynth problem it's not something new to version 2.6, and it appears unlikely to be a plugin given I've reverted to the original QTGMC plugins package. Could it be a problem with the QTGMC script itself?

[sneaker_ger]

I'm fairly sure I've had enough for a while. I can go back to testing at some stage soon but I need a break for now. The video I was trying to encode today gave me so much grief I finished up converting it to lossless AVIs in sections, appended the AVIs together and re-encoding that. If I tried to combine multiple scripts using Import (I was taking sections from two different sources) encoding speed slowed to a crawl.
Try VapourSynth's QTGMC if you need to do "productive" work and cannot wait for a fix.