Way to accurately measure processing time of filters

[WyldeF1r3]

Sorry, didn't know where to put this, but it relates to another thread in this forum, so I put it here.

Inspired by this thread http://forum.doom9.org/showthread.php?s=&threadid=51181 I wanted to conduct some tests of my own (fairly comprehansive and exhaustive) but I couldn't find a way to accurately measure time. After lengthly discussions with Kurosu, I pointed out to him that his kronos filter wasn't outputting reliable results, and he also emparted on me all the factors that can elongate processing (such as file name address and virtualdub considerations). So with his measuring tool down, I'm left to wonder if there is anything else I can do to be "as accurate as possible" with my values. I understand that a great deal of time depends on the system configuration, but I can't help but think that there must be SOME factors which are constant in all things. I'd like to be able to conduct texts which produced useful and relible results, it'd be awful to do so much work and have all the data be useless ^_^

If anyone can shed some light on this for me I'd really appreciate it.

[DDogg]

I think a combination of the latest call.dll and nicecho.exe will do the trick if you want to capture a time at frame 0 and another time at frame last. This type of reportage was one of the driving reasons behind the creation of the call command but did not garner much support and was not completed. The script below was just a rough and ugly effort. Somebody that actually knows what they are doing could create something much more elegant than I.

From this thread http://forum.doom9.org/showthread.php?s=&threadid=46506&perpage=30&highlight=call&pagenumber=2
code:--------------------------------------------------------------------------------
#loadplugin("call_25.dll") load not needed if in plugin dir
#loadplugin("chr.dll") from WarpEnterprises Website, used for date but does a whole lot more
hdr="'"
avifname="test_MC.avi"
v=avisource(avifname)
FmCt= "\nFramecount = " +string(v.framecount)
FmRt="\nFramerate = "+ string(v.framerate)
W="\nWidth = "+ string(v.width)
H="\nHeight = "+ string(v.height)
A="\nAudiorate = "+ string(v.audiorate)
StTime="\nStart Time \t" # < \t outputs the current time
FinTime="\nFinish Time \t"
Dte=(Time("Date: %A %x Time: %I:%M:%S %p")) #this from chr.dll
RptHdr="REPORT: "+dte +"\nFilename: "+avifname+ StTime
stuff=RptHdr+Fmct+FmRt+w+h+a
Call(v,"nicecho2.exe report.txt " +hdr + stuff + hdr, "-2") #runs before video
Call(v,"nicecho2.exe @report.txt " +hdr+fintime+hdr, "-1") # after video
#The @report.txt above appends to previous report.txt
--------------------------------------------------------------------------------

Outputs Report.txt to disk

code:--------------------------------------------------------------------------------
REPORT: Date: Thursday 03/27/03 Time: 08:12:16 PM
Filename: test_MC.avi
Start Time 20:12:16
Framecount = 758
Framerate = 29.970030
Width = 720
Height = 480
Audiorate = 48000
Finish Time 20:12:42
--------------------------------------------------------------------------------

[N_F]

If you check the last ~10 posts in the thread you linked to you can also find some information you might find useful by WarpEnterprises and High Speed Dub. Though perhaps you have already read it.

[Prettz]

It would be very easy (I *think*) to make a new filter that simply calls the Win32 "::QueryPerformanceCounter()" before and after passing the frame to the next filter. Please correct me if I'm wrong...

[sh0dan]

Sounds like it's worth a shot. What's the resolution - anything above 5ms is pretty useless.

It should however still be a bit advanced in the reporting to be useful. Average time in millis. A "filtered" average that filters out spikes (threaded interuptions), but still is able to time non-linear filters (where some frames take longer to return than others).

If someone has the time to write the basic timer filter, I'd be happy to put it into the core (with full credits of course). I haven't looked at the kronos filter yet, but it still sounds like a place to start.

(Moved thread to development forum).

[Prettz]

You have to call "QueryPerformanceFrequency()" beforehand to find out how many times it updates per second, as it apparently can be different depending on your system.
I have a 1.7GHz P4 and Win98SE, and it tells me approximately 838 nanoseconds. From what I gathered from the online version of the MSDN, it might be a little better under XP.

[Kurosu]

Kronos uses QueryPerformanceCounter (and *Frequency), but I've stopped when I've found that in the script avisource("file.avi").Start().bilinearresize(640,480).stop(), stop() for frame 2 was invoked *before* frame 2 for Start(). The exact order:
- start() loaded
stop() loaded
- stop() called on frame 0
start() called on frame 0
- stop() called on frame 1
start() called on frame 1
...
- stop() called on frame n
start() called on frame n
- start() unloaded
stop() unloaded

Therefore, the filter (start=request frame then set start time; stop=set stop time, make timing calculations then request frame) is measuring the filter chain from stop to start, ie including the time you may take to seek to the next frame in Vdub. Considering my new attitude towards programming avisynth filter, I dropped the project there.

[Guest]

Considering my new attitude towards programming avisynth filter OK, I give up. What is your new attitude?

[sh0dan]

@Kurosu: You fail to realize that a basic thing about AviSynth it that frames are not pushed downwards, but requested upwards.

Consider a script like this:avisource("file.avi")
bilinearresize(640,480)
limiter()

When vdub requests any given frame from AviSynth, AviSynth will start by requesting the frame from limiter(). Limiter will then need a frame from BilinearResize, and requests this frame by sending off a GetFrame request to the BilinearResize filter. Like this the process goes on until a source is able to deliver the frame.

So you really only need to swap the meaning of Start and Stop.

For filters requesting several frames you could run into problems. If you use the following script:
avisource("file.avi")
start()
temporalsoften(5,3,3)
stop()
The problem here is, that "start()" will sometimes be reached several times per frame (if all the frames TS needs isn't cached). So what your filter needs to do.

"Stop()" filter should measure the time passed within the GetFrame call (that means measure the time GetFrame takes).
"Start()" should accumulate all time used by filters above itself (time spend by GetFrame). The actual time is then calculated by:

FilterTime = Stop_millis - Accumulated_Start_millis

"Stop()" should of course reset the accumulated time for Start before calling GetFrame.

Do I make any sense?

[Kurosu]

@Neuron2
My 'new' attitude is to spend less time on avisynth filters, and only if it serves a purpose for myself: other users are my least concern.
Anyway, what are you giving up? Was there some point to criticize over my post (not clear enough,...) ?

@Sh0dan
I tried to handle this by storing the last frame requested by start(), check it at stop() level (and if it doesn't match, throw an error like "missing start() or random acces filter chain"). I did invert the calls (ie replace start() by stop() and viceversa). I don't recall well what changes I made (the source code is now 600km away from me, and I won't have access to it untill quite some time) in addition to fit the new order, but at that time, I had the feeling of a total nonsense (ie, it didn't look symetric in spite of the changes I had made). I therefore dropped the subject untill I regain more interest in it.

Anyway, there was nothing more in my filter than the 2 QueryPerformance... functions, so a simple look at the MSDN and 5 minutes of coding would bring anyone to the point where I stopped. Sh0dan has in fact made the greatest part of the work by providing the design of the filter, which seem to solve the problems I encountered.

[WarpEnterprises]

It sounds to me that it is impossible for an external plugin filter in the chain to measure anything as the filter doesn't get what's going on.

The timing filter must invoke the tested filter itself.

Much cleaner would be to put this timer before and after AviSynth calls the GetFrame.

(can't that be added to Cache::GetFrame or are there other places where a frame can be generated?)

[Guest]

Originally posted by Kurosu
Was there some point to criticize over my post (not clear enough,...) ? I wasn't criticizing you! I was just sincerely curious about your intriguing but cryptic comment about a new attitude.

I have maintained a policy like that as well. Mine is I will do some work if it is a) needed by me personally, or b) needed by a large section of the community. I suppose the part b) stems as much from vanity as from philanthropy. :D

EDIT: "needed by me personally" also subsumes doing things for my good friends here, like manono. Who else is going to "decimate 79 frames out of every 249, and don't mangle the static scenes"? The old canard about back scratching applies.

[sh0dan]

Originally posted by WarpEnterprises
It sounds to me that it is impossible for an external plugin filter in the chain to measure anything as the filter doesn't get what's going on.

:confused: Why would it be that?
Could you explain?

All filters can use env->SetVar / GetVar to have access to some variables.


Much cleaner would be to put this timer before and after AviSynth calls the GetFrame.

No - because this would also include the time spend by the filters before the one you are measuring.


The timing filter must invoke the tested filter itself.

... but you would still need to insert a filter above the one you're testing, and you loose the posibility of testing several filters in combination. A 15 minute modification of Krono should do quite well - is the source included?

[WarpEnterprises]

1. I meant that a filter does not know what comes before or after in the chain.

2. how does AviSynth call the filter in the chain? If this is done explicitly for each filter can't there be a point where the timer can be but in between? But I see, then you can't tell which filter is to be examined.

3.sadly no source, would be of general interest :(

[sh0dan]

2. how does AviSynth call the filter in the chain? If this is done explicitly for each filter can't there be a point where the timer can be but in between? But I see, then you can't tell which filter is to be examined.

Actually it is much simpler than you might expect. AviSynth actually mostly doesn't touch the filter chain. Try re-reading my reply to Kurosu above.

Each filter _directly_ calls the filter above (don't think about cache for a while). Your filter calls GetFrame (from your own filters GetFrame) of the filter before your own. This is the way it works all the way up to the source. Brilliant and clean.

AviSynth is not doing anything between your filter and the one above. Caching is a "simple" filter that is simply inserted between your own and the one above. Caching either takes no time, or calls the filter above.
This is why an external filter is as good as an internal.

[WarpEnterprises]

I already feared that it is so "simple"...

What about pulling(requesting) many (e.g. 1000 to avoid caching) frames with a timing filter before and after the filter to be tested without sending them down?
(GetFrame (0 ... 1000) )
The difference for these two should give the time or am I wrong?

[Kurosu]

WarpEnterprises reminded me it could be worth updating that thread, even though there are unresolved (but does a solution exist?) issues with Kronos (http://kurosu.inforezo.org/avs/Kronos/Kronos.zip). More precisely: the option full=true both forced display onto video and a messagebox to appear at the script's closing. For some reason (yet I guess is normal and seems unfixable), this messagebox either crashed the app processing the script, or wouldn't show. I provided two quick fixes:
- if you really want to display the message box, it shouldn't crash anymore; however, it might not "block" the proper window (though cliking on OK button should solve the problem :) )
- an option mb=true not controls whether the mbox should be displayed

Another neat feature (well, I use it) is the possibility to log (append) into a file (with job start time and end time) the results from Kronos. Very usefull for benchmarking with joblist in Vdub (tips: mb=false,full=false - those options are useless in that case).

All in all, you may prefer using AvsTimer (http://forum.doom9.org/showthread.php?s=&threadid=56090) by Kassandro. Please tell us what is good or bad in our plugins, so that we update our plugin(s).