AvsTimer 0.8.1

An Avisynth 2.5x plugin for measuring speed and performance of Avisynth plugins

By Rainer Wittmann gorw@gmx.de

The binary and the source code are subject to the GNU General Public License. Last change September 15, 2005.

Installation

Beginning with version 0.8 AvsTimer uses the recursion DLL AvsRecursion. In particular, Avisynth can only load the AvsTimer plugin, if  AvsRecursion is installed (goto the AvsRecursion web site for more details). Because AvsRecursion.dll requires msvcr71.dll anyway, a statically linked version of this plugin no more makes sense. Question, comments etc. should be addressed to the support forum. Though registration is appreciated, you can post to this forum without registration. Thus there is no need to send me email. Because of enormous spam, you must put somewhere in the title the word "Avisynth", if you want to send me email. However, I only check for such email once every two weeks.

Usage

AvsTimer  is an Avisynth filter (for Avisynth 2.5 or higher), which actually doesnīt make any changes to a clip. In fact, it even doesnīt make a simple bitblt operation. Thus its overhead is virtually zero. Rather it is a utility to measure the performance of various filters, decoders etc. and should be particular useful for filter writers who want to tweak their filters for maximum speed. To use it one needs the debugview utility or any other program which can catch and display debug messages. Debugview is also used by various other Avisynth filters. Thus it is a utility which a serious Avisynth user should have anyway. Letīs begin with a simple Avisynth script:  

LoadPlugin("C:\Programme\avisynth\plugins\MPEG2Dec3.dll") LoadPlugin("C:\Programme\avisynth\plugins\decomb.dll") MPEG2Source("input.d2v") crop(16,4,692,568) FieldDeinterlace()

If we now insert the two lines,

LoadPlugin("C:\Programme\avisynth\plugins\MPEG2Dec3.dll") LoadPlugin("C:\Programme\avisynth\plugins\decomb.dll") LoadPlugin("C:\Programme\avisynth\plugins\AvsTimer.dll") MPEG2Source("input.d2v") AvsTimer() crop(16,4,692,568) FieldDeinterlace()

load the script into VirtualDubMod and start preview, debugview displays the following output:

[1748] AvsTimer 0.3 [1748] AvsTimer 0.3 [1748] AvsTimer 0.3 [1748] [1999] Timer1 = 69 fps [1748] [3999] Timer1 = 67 fps [1748] [5999] Timer1 = 66 fps [1748] [7999] Timer1 = 65 fps [1748] [9999] Timer1 = 69 fps

The first number in brackets is the process number of VirtualDubMod. This number is useful, if more than one program is sending debug messages. The second number in brackets is the frame number, at which AvsTimer displays the information. In our example, AvsTimer displays the timer results every two thousand frames. This is the default. We can change the default by using AvsTimer with the option frames. If we insert AvsTimer(frames= 1000) into the script, then the results are displayed every thousand frames. The larger the number of frames the more accurate are the results. Thus it is not a good idea at all to use AvsTimer(frames=1). Perhaps one may then get the error message "zero or negative ticks", because the time was too short to be measurable. If a number <=0 is specified for the frames variable, then frames is simply set to the number of frames of the entire clip. Thus in this case the frame rate is only displayed once after the entire clip has been processed. The first string "Timer1" is the name of the timer. If AvsTimer is inserted three times into the script, then one gets also results from "Timer2" and "Timer3". Instead of these default names, one my specify arbitrary names as an option. If we replace AvsTimer() by AvsTimer(frames=1000, name="mpeg2dec"), then we get the following output from debugview:

[1864] AvsTimer 0.3 [1864] AvsTimer 0.3 [1864] AvsTimer 0.3 [1864] [999] mpeg2dec = 68 fps [1864] [1999] mpeg2dec = 68 fps [1864] [2999] mpeg2dec = 68 fps [1864] [3999] mpeg2dec = 67 fps [1864] [4999] mpeg2dec = 66 fps [1864] [5999] mpeg2dec = 67 fps

The value after = is the number of frames per seconds which the filter chain before "mpeg2dec" in the Avisynth script would have, if it would run without the filter chain after "mpeg2dec" and VirtualDubMod. All frame rates are averaged over the last 2000 frames (or the the number specified with the option frames ) and are always rounded up or downwards to the next integer. For instance, the script

LoadPlugin("C:\Programme\avisynth\plugins\MPEG2Dec3.dll") LoadPlugin("C:\Programme\avisynth\plugins\decomb.dll") LoadPlugin("C:\Programme\avisynth\plugins\AvsTimer.dll") MPEG2Source("input.d2v") AvsTimer(frames=1000, name="mpeg2dec") crop(16,4,692,568) FieldDeinterlace() AvsTimer(frames=1500)

gives the following output:

[1908] AvsTimer 0.3 [1908] AvsTimer 0.3 [1908] AvsTimer 0.3 [1908] [999] mpeg2dec = 68 fps [1908] [1499] Timer2 = 27 fps [1908] [1999] mpeg2dec = 69 fps [1908] [2999] mpeg2dec = 66 fps [1908] [2999] Timer2 = 27 fps [1908] [3999] mpeg2dec = 69 fps [1908] [4499] Timer2 = 27 fps [1908] [4999] mpeg2dec = 67 fps [1908] [5999] mpeg2dec = 65 fps [1908] [5999] Timer2 = 27 fps

Unlike "mpeg2dec" "Timer2" now includes the deinterlacer FieldDeinterlace. Thatīs why the frame rate is now much smaller. One can also measure the frame rate of the filter chain between two calls of AvsTimer. For this purpose we have the "difference" and the "quiet" option. Changing the script as follows: 

LoadPlugin("C:\Programme\avisynth\plugins\MPEG2Dec3.dll") LoadPlugin("C:\Programme\avisynth\plugins\decomb.dll") LoadPlugin("C:\Programme\avisynth\plugins\AvsTimer.dll") MPEG2Source("input.d2v") AvsTimer(frames=1000, name="mpeg2dec", quiet=true) crop(16,4,692,568) FieldDeinterlace() AvsTimer(frames=1500, name="decomb", difference=1)

we get the following output

[1952] AvsTimer 0.3 [1952] AvsTimer 0.3 [1952] AvsTimer 0.3 [1952] [1499] decomb = 45 fps [1952] [2999] decomb = 46 fps [1952] [4499] decomb = 46 fps [1952] [5999] decomb = 45 fps [1952] [7499] decomb = 45 fps [1952] [8999] decomb = 46 fps

The displayed frame rate  is now just the frame rate of the filter chain from crop(...) to FieldDeinterlace() (crop really doesnīt matter as it is a "zero cost" filter). Replacing Decomb with TomsMoComp we get the following results:

[432] AvsTimer 0.3 [432] AvsTimer 0.3 [432] AvsTimer 0.3 [432] [1499] TomsMoComp = 97 fps [432] [2999] TomsMoComp = 98 fps [432] [4499] TomsMoComp = 98 fps [432] [5999] TomsMoComp = 98 fps [432] [7499] TomsMoComp = 98 fps [432] [8999] TomsMoComp = 97 fps

If  difference=k is specified for the m-th timer then the filter chain between the m-th and the (m-k)-th timer is taken. If m-k<= 0 then Avisynth terminates with an error message. In the above example we have suppressed the output of "mpeg2dec" with the option "quiet= true". Without this option we would have gotten the same "mpeg2dec" output as before. Instead of taking the average only over the last 2000 frames or whatever has been specified with the frames option, one may average over all frames, which have been processed so far, by setting the boolean variable accumulate  to true. Thus the script

LoadPlugin("C:\Programme\avisynth\plugins\MPEG2Dec3.dll") LoadPlugin("C:\Programme\avisynth\plugins\TomsMoComp.dll") LoadPlugin("C:\Programme\avisynth\plugins\AvsTimer.dll") MPEG2Source("input.d2v") AvsTimer(frames=1000, name="mpeg2dec", accumulate=true) crop(16,4,692,568) TomsMoComp(1, 5, 0) AvsTimer(frames=1500, name="TomsMoComp" , difference=1)

gives the following results

[652] AvsTimer 0.3 [652] AvsTimer 0.3 [652] AvsTimer 0.3 [652] [999] mpeg2dec = 68 fps [652] [1499] TomsMoComp = 96 fps [652] [1999] mpeg2dec = 69 fps [652] [2999] mpeg2dec = 68 fps [652] [2999] TomsMoComp = 97 fps [652] [3999] mpeg2dec = 68 fps [652] [4499] TomsMoComp = 97 fps [652] [4999] mpeg2dec = 68 fps [652] [5999] mpeg2dec = 68 fps [652] [5999] TomsMoComp = 98 fps [652] [6999] mpeg2dec = 67 fps [652] [7499] TomsMoComp = 98 fps [652] [7999] mpeg2dec = 67 fps [652] [8999] mpeg2dec = 68 fps [652] [8999] TomsMoComp = 98 fps [652] [9999] mpeg2dec = 68 fps [652] [10499] TomsMoComp = 98 fps [652] [10999] mpeg2dec = 68 fps [652] [11999] mpeg2dec = 68 fps [652] [11999] TomsMoComp = 98 fps [652] [12999] mpeg2dec = 68 fps [652] [13499] TomsMoComp = 97 fps [652] [13999] mpeg2dec = 68 fps [652] [14999] mpeg2dec = 68 fps [652] [14999] TomsMoComp = 97 fps

In this example the "mpeg2dec" timer averages over all previous frames while "TomsMoComp" timer averages only over the last 1500 frames. Consequently the frame rates for "mpeg2dec" stabilise with more and more frames processed, while the frame rates for "TomsMoComp" continue to fluctuate. AvsTimer comes with four methods for measuring time. The default method type=2 is based on the windows functions GetThreadTimes, which measures the time the filter chain spends within the thread, by which is it is called. This is the most accurate method as long as no other threads are used by the filter chain. Currently I know of no example which violates this assumption. However, as hyperthreading becomes more and more fashionable times may change. If one uses the option type=1, then time is measured with GetProcessTimes. Then the time of the process, which runs the Avisynth script, is measured, while the process is executing the filter chain. However, some threads of this process, which have nothing to do with the filters, but run parallel may artificially reduce the frame rate. If type=0 or type=3 is used, then instead of process or thread time the absolute time is taken. Then also other processes may influence the frame rates to the downside. If  type=0 then the function QueryPerformaceCounter is used, if type=3 then the cpu instruction RDTSC is used. type=3 has certainly the smallest overhead, but during initialisation 1 second is necessary to determine the cpu frequency and on some notebooks the cpu frequency may change over time obliterating all the results. To avoid the delay one may also specify the cpu frequency with the frequency option. This must happen with the first type=3 timer or any other timer befor the first type=3 timer otherwise the frequency option is ignored. Thus AvsTimer(type=3, frequency= 1300) defines a type= 3 timer for a cpu with 1300 MHZ. One can get the exact cpu frequency by running a type= 3 timer without the frequency option. Then the exact cpu frequency is displayed in the debugview window. Timers, which are paired together by the difference option, shouldbe of the same type, otherwise the results do not make sense and may even yield negative frame rates. Timers of type!= 2 have an additional advantage. With such timers the frame rate of the entire process running the script  - we call this the total frame rate - can be measured and is displayed by default. Thus the script

LoadPlugin("C:\Programme\avisynth\plugins\MPEG2Dec3.dll") LoadPlugin("C:\Programme\avisynth\plugins\decomb.dll") LoadPlugin("C:\Programme\avisynth\plugins\AvsTimer.dll") MPEG2Source("input.d2v") AvsTimer(frames=1000, name="mpeg2dec", type=3) crop(16,4,692,568) FieldDeinterlace() AvsTimer(frames=1500, name="decomb", type=3, difference=1)

gives following output

[1252] AvsTimer 0.3 [1252] AvsTimer 0.3 [1252] AvsTimer 0.3 [1252] CPU frequency = 1312 MHZ [1252] [999] mpeg2dec = 68 fps, total = 17 fps [1252] [1499] decomb = 45 fps, total = 19 fps [1252] [1999] mpeg2dec = 68 fps, total = 26 fps [1252] [2999] mpeg2dec = 67 fps, total = 26 fps [1252] [2999] decomb = 46 fps, total = 25 fps [1252] [3999] mpeg2dec = 67 fps, total = 26 fps [1252] [4499] decomb = 46 fps, total = 25 fps [1252] [4999] mpeg2dec = 67 fps, total = 25 fps [1252] [5999] mpeg2dec = 65 fps, total = 25 fps [1252] [5999] decomb = 45 fps, total = 25 fps [1252] [6999] mpeg2dec = 66 fps, total = 25 fps [1252] [7499] decomb = 46 fps, total = 25 fps

The output of the total frame rate can be disabled by using the total= false option. It is notable from the above output, that the first total frame rate of each timer is substantially lower than the subsequent ones. This is because the "total" clock of each timer is started, when the filter is created by Avisynth. Because the timers are of type=3 even the time until preview is started in VirtualDubMod is counted. Thus the first total frame rates should be ignored if timers of type=0 or 3 are used or one should use GetAll, which is described below. From the above tests we see that TomsMoComp with 98 fps is much faster than FieldDeinterlace with 45 fps which  is even significantly slower than the hard working mpeg2dec3 with 66 fps. All the above tests were run on a 1.3 GHZ Celeron (Tualatin P3 design) with AvsTimer 0.3 .

Benchmarking filters with two or three input clips

To measure the performance of a filter with one input clip, two instances of AvsTimer are neccessary. One immediately after the filter and the input clip should be created by  an earlier instance of AvsTimer, i.e.

AvsTimer(filter(AvsTimer(input, quiet=true)), difference=1, frames=1000)

measures the performance of filter(clip input). If the filter to be benchmarked requires two input clips, three instances of AvsTimer are necessary. One for the filter itself and the other two for the two input clips.

AvsTimer(filter(AvsTimer(input1, quiet=true), AvsTimer(input2, quiet=true)), difference=1, difference2=2, frames=1000)

measures the performance of filter(clip input1, clip input2).

AvsTimer(filter(AvsTimer(input1, quiet=true), AvsTimer(input2, quiet=true)), difference=2, difference2=1, frames=1000)

works equally well. Similarily filter(clip input1, clip input2, clip input3) can be benchmarked with

AvsTimer(filter(AvsTimer(input1, quiet=true), AvsTimer(input2, quiet=true), AvsTimer(input3, quiet=true)) \ , difference=1, difference2=2, difference3=3, frames=1000)

AvsTimer and the Avisynth Cache and the SetCache function

In order to avoid reprocessing of frames, Avisynth has a cache for each instance of a filter in a script. This cache clearly enhances performance, if time consuming filters which operate on multiple frames are used. AvsTimer allows you to monitor the efficiency of these caches. In fact, in most cases, is able to replace the  cache of the filter immediately before AvsTimer and replaces it by its own cache without any measurable performance penalty. For instance in the script

LoadPlugin("C:\Programme\avisynth\plugins\MPEG2Dec3.dll") LoadPlugin("C:\Programme\avisynth\plugins\decomb.dll") LoadPlugin("C:\Programme\avisynth\plugins\AvsTimer.dll") MPEG2Source("input.d2v") AvsTimer(frames=1000, name="mpeg2dec", type=3) crop(16,4,692,568) FieldDeinterlace() AvsTimer(frames=1500, name="decomb", type=3, difference=1)

the first AvsTimer instance takes over the cache of MPEG2Source and the second instance takes over the cache of  FieldDeinterlace. What is this taking over good for? If the frame difference between two output lines of an AvsTimer instance is exactly the value of the frames variable, then there was no cache miss for the filter taken over by this instance of AvsTimer. More precisely we have the formula

number of cache misses = frames - (frame difference of two subsequent output lines)

To be more concrete we look at the output of this script in the previous section. The frame counts of the instant of AvsTimer with name "mpeg2dec" are 999,1999,2999, 3999,4999,5999,6999. Thus the frame difference is always 1000, which is exactly the value of the frames variable. Thus there was no cache miss for the important clip generator MPEG2Source. Similarily, The frame counts of the instant of AvsTimer with name "decomb" are 1499,2999,4499,5999,7499. Thus the frame difference is always 1500, which is exactly the value of the frames variable of this AvsTimer instance. Hence there was also no cache miss for the filter FieldDeinterlace. Though the cache resources are quite limited (they depend on the resolution and the color space of the frame) and the Avisynth is far from optimal it works perfectly for small scripts like the above. However, in scripts with many sophisticated filters substantial cache misses are inevitable and AvsTimer should measure these accurately. To get optimal throughput of scripts with many filter, each filter should have an option to disable its cache. In this way caching could be restricted to the most important filters in order to maximise performance, which can be monitored by AvsTimers. Unfortunately the Avisynth filter API does not provide such a function. Fortunately James D. Lin invented a trick to manipulate the cache of a clip. This trick is embodied in the function SetCache of this plugin. SetCache(input, value) sets the cache of the clip input to value. If value < 0 then the cache of this clip is simply disabled. If value > 50 then the cache is set to CACHE_ALL and if 0 <= value <= 50, then the range of the cache is set to value.

The Delay Filter and AssignRecursionClip

The delay filter is the first filter at all, which features script recursion. It is used as follows:

function DR(clip input, int "repmode")
{
	repmode = default(repmode, 16)
	delayed = Delay(input, recursive=0)
	setcache(delayed, -1) # the cache of zero cost filters should always be disabled
	rep = Repair(delayed, input, mode=repmode)
	AssignRecursionClip(rep, 0)
	return rep
}

function DR(clip input, int "repmode")
{
	repmode = default(repmode, 16)
	rep = Repair(trim(rep,1,0), input, mode=repmode)
	AssignRecursionClip(rep, 0)
	return rep
}

function DR(clip input, int "repmode")
{
	repmode = default(repmode, 16)
	delayed = Delay(input, recursive=7, recdelay=-n)
	setcache(delayed, -1) # the cache of zero cost filters should always be disabled
	rep = Repair(delayed, input, mode=repmode)
	AssignRecursionClip(rep, 7)
	return rep
}

function DR(clip input, int "repmode")
{
	repmode = default(repmode, 16)
	rep = Repair(trim(rep,n,0), input, mode=repmode)
	AssignRecursionClip(rep, 0)
	return rep
}

The GetAll Filter

As already  mentioned in the preceding section other programs or threads may influence the results if type!= 2.  Thus for performance tests a simple program, which would only request one frame after the other from Avisynth and do nothing else, would be ideal. It would even be better as far as accuracy is concerned to have a filter with such a property. Thatīs what GetAll is all about.  If VirtualDubMod or any other program running the Avisynth script is requesting the trigger frame (by default this is the first frame and has the frame number 0) from Avisynth and GetAll is in the filter chain, then GetAll request all other frames before it returns the trigger frame to the calling program which then has to wait for quite a while. All frames may be a little to much. With GetAll(frames=10000) GetAll will only request the first 10000 frames. Modifying our example script as follows

LoadPlugin("C:\Programme\avisynth\plugins\MPEG2Dec3.dll") LoadPlugin("C:\Programme\avisynth\plugins\decomb.dll") LoadPlugin("C:\Programme\avisynth\plugins\AvsTimer.dll") MPEG2Source("input.d2v") AvsTimer(frames=1000, name="mpeg2dec", type=0) crop(16,4,692,568) FieldDeinterlace() AvsTimer(frames=1500, name="decomb", difference=1, type=0) GetAll(frames=10000)

we get the following output

[2000] AvsTimer 0.3 [2000] AvsTimer 0.3 [2000] AvsTimer 0.3 [2000] [999] mpeg2dec = 66 fps, total = 25 fps [2000] [1499] decomb = 44 fps, total = 26 fps [2000] [1999] mpeg2dec = 67 fps, total = 27 fps [2000] [2999] mpeg2dec = 66 fps, total = 27 fps [2000] [2999] decomb = 46 fps, total = 27 fps [2000] [3999] mpeg2dec = 63 fps, total = 26 fps [2000] [4499] decomb = 45 fps, total = 26 fps [2000] [4999] mpeg2dec = 65 fps, total = 26 fps [2000] [5999] mpeg2dec = 64 fps, total = 26 fps [2000] [5999] decomb = 45 fps, total = 26 fps [2000] [6999] mpeg2dec = 65 fps, total = 26 fps [2000] [7499] decomb = 45 fps, total = 26 fps [2000] [7999] mpeg2dec = 65 fps, total = 27 fps [2000] [8999] mpeg2dec = 68 fps, total = 27 fps [2000] [8999] decomb = 46 fps, total = 27 fps [2000] [9999] mpeg2dec = 67 fps, total = 27 fps

Now it is no more necessary to start preview, because by requesting frame 0, VirtualDubMod triggers GetAll to request the first 10000 frames. Only after it has completed these 10000 frames the frame 0 is delivered to VirtualDubMod. The disadvantage of GetAll, of course, is that it cannot be used during a normal encoding process.  To get trustworthy frame rates with timers of type!=2 insert GetAll immediately after the last AvsTimer call, shut down all cpu intensive processes and run the script in VirtualDubMod to trigger GetAll.

The Shutdown Filter

Known Problems

• The "total =" results are a tiny little bit incorrect (tiny is depending how large frames is), because the clock is stopped just before the last frame is returned to subsequent filters or the program running the script. The entire program may be even more than one frame behind. However, if frames is large or accumulate=true then this inaccuracy should not matter. Even if frames is small it should matter only for the first "total=" result (yielding higher frame rates). For the subsequent results, because the effect is negative at the beginning and positive at the end, error cancellation should correct the results.
• All bug reports, suggestions etc should be posted to the support forum. Please do not send me email.

Alternative