AvsTimer 0.5

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 March 7, 2004.

Installation

Beginning with version 0.4.1 the binary package of AvsTimer contains two versions of the plugin. AvsTimer.dll (dynamically linked, hence small) and AvsTimerS.dll (staticly linked, hence big). Try first the small dll and copy it to Avisynth's plugin directory. If it doesn't work, this is probably due to missing msvcr70.dll library. Either you install this library in C:\windows\system32 (but not in each application directory), or you delete AvsTimer.dll and replace it by AvsTimerS.dll. Please do not put both dlls into the plugin directory. If you fill the plugin directory with all kinds of superfluous dlls, then you only slow down the start of any application which uses Avisynth.

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 test were run on a 1.3 GHZ Celeron (Tualatin P3 design) with AvsTimer 0.3 .

AvsTimer and the Avisynth Cache

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 overtakes the cache of MPEG2Source and the second overtakes the cache of  FieldDeinterlace. What is this overtaking 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)

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 appropriate thread in the Doom9 forum. Please do not send me email.

Alternative