Profiling and optimizing code

[Uten]

From time to time a thread pops up in the forum to measure the time (or how many iterations can be done in a given time) a block of code takes to execute.

most solutions use TimeInit and TimeDiff to do the measures. This is not a accurate way to measure the time spent by the code block. The reason is that TimeDiff measure the time spent by all processes on the system and not just the one we want to measure.

So, a better approach in AutoIt is to use GetProcessTimes in kernel32.dll.

I have created two udfs to resemble TimerInit and TimerDiff. They are called ProfileInit and ProfileDiff. They operate on the running process. ProfileDiff will return an array containing the time in 100 nanoseconds intervals since ProfileInit was called.

Usage:

Local $foo
   Local $i, $j, $k
   
   Local $time, $ts, $pi[1]
   $pi = ProfileInit()
   ;ArrayDump($pi, "Profile Inint:")
   $ts = Timerinit()
   For $i = 0 to 3
      For $j = 1 to 100000
         $k += Random(-5, 5, 1)
      next 
      
      Local $pd = ProfileDiff($pi)
      $time = TimerDiff($ts)
      ;K=kernel-time, U=User-time spendt by the process identified by @AutoItPID
      ;Dividing by 10000 to get ms
      ConsoleWrite(StringFormat( "SUM:=%d\tT:%.6d, K:%d, U:%d, K+U:%d ms", $k, $time, $pd[1], $pd[2], Round(($pd[1]+$pd[2])/10000, 0)) & @LF) 
      $k = 0
   next
   $Process = 0oÝ÷ Ù

Enjoy, Uten..

EDIT: Forgot some globals.

Edited January 2, 2007 by Uten

[SmOke_N]

SUM:=1267 T:001021, K:0, U:9531250, K+U:953 ms

SUM:=-766 T:002043, K:0, U:19531250, K+U:1953 ms

SUM:=1673 T:003046, K:0, U:29218750, K+U:2922 ms

SUM:=-293 T:004058, K:0, U:39218750, K+U:3922 ms

Windows XP Pro SP2

AMD Athlon 64

3700+

2.40 GHz, 2.00 GB of RAM

Edit:

Killed 2 processes and then got this:

SUM:=-729 T:001011, K:0, U:9687500, K+U:969 ms

SUM:=-1555 T:001982, K:0, U:18906250, K+U:1891 ms

SUM:=278 T:002933, K:0, U:28125000, K+U:2813 ms

SUM:=1171 T:003916, K:0, U:37343750, K+U:3734 ms

SUM:=-324 T:000986, K:0, U:9375000, K+U:938 ms

SUM:=-425 T:001968, K:0, U:19062500, K+U:1906 ms

SUM:=387 T:002949, K:0, U:28593750, K+U:2859 ms

SUM:=-638 T:003915, K:0, U:37968750, K+U:3797 ms

(Ran it twice)

Edit2:

Probably as fast as I'm going to get it:

SUM:=-11 T:000928, K:0, U:9375000, K+U:938 ms

SUM:=2029 T:001836, K:156250, U:18281250, K+U:1844 ms

SUM:=582 T:002730, K:156250, U:27187500, K+U:2734 ms

SUM:=-903 T:003795, K:156250, U:36093750, K+U:3625 ms

Edited January 3, 2007 by SmOke_N

[llamnuds]

I'm a noob at AutoIt, but when I get more into it, I think this'll be really handy.

Thanks,

llamnuds

[Uten]

Outch, why don't I get mail notifications from this thread?

Nice to know you have tested it a bit @SmOke_N. Maybe it can help you out when you try to improve your EnCodeIt code. I know you constantly improve that nice application of yours.

Hope you to can benefit from it to @llamnuds.

[clearguy]

Please can you explain what SUM,T,K and U means?

[Uten]

Sorry about the late reply. Still don't get mail notification. Must be something with my forum settings.

You sort of find it in this line:

ConsoleWrite(StringFormat( "SUM:=%d\tT:%.6d, K:%d, U:%d, K+U:%d ms", $k, $time, $pd[1], $pd[2], Round(($pd[1]+$pd[2])/10000, 0)) & @LF)

So,

SUM The sum of my sample calculation.

T: Time as measured with TimerInit and TimerDiff

K: CPU time spent by then kernel.

U: CPU time spent in user code.

K+U: Total time spent by the process. This time should be compared with T: Especially on a computer running many processes.

Hope that explains it..