Registered: 2012-03-27
Posts: 363
Loc: London, England
I have looked through the UDF's and I cannot find any UDF that calculates the running time for each line of code in a script. I probably could work out how to create this specific UDF, but I would imagine that somebody has already done this before, so rather than re-invent the wheel, I just thought that I would ask as I want to improve the login times for some netbooks that we have at one client where the script is taking about 1 minute to complete instead of 5 seconds. I think that I have narrowed it down to the netbooks taking a long time to delete the temp files on login as this is where the script is stopping according to the script screen. But I thought that it would be a good idea to get ask if there was an existing UDF that can log just how long the script takes to run and what is taking the longest time to complete. Thank you.
The function is called as TimeStamp('ID'), where "ID" is a line number or code block identifier. $PERFLOG is a global var that contains all the timestamp text and is written to a file just prior to the script exiting. This overhead is minimal while processing, compared to writing to the log at each invocation. The log write is as simple as
Registered: 2012-03-27
Posts: 363
Loc: London, England
Thank you. I will test this out either this week or next week depending on when I am finished with a few other things. I knew that somebody had written some code along those lines as surely this is a very common requirement. You should incorporate that into the UDF's and call it scriptruntime or something like that. Thank you. I will let you know the results of the test when I have time to run it!
#208296 - 2014-01-1210:35 PMRe: Running time of each line of code in kixtart
[Re: Robdutoit]
Glenn BarnasGlenn Barnas KiX Supporter
Registered: 2003-01-28
Posts: 4403
Loc: New Jersey
This UDF is embedded in our Universal Login Script... we make between 50 and 80 calls to it depending on the number of objects we're processing.
Two caveats.. the accuracy is about +/- 8ms. I think that's got something to do with how Kix processes the timer. In testing in our ULS, I find that it adds a minimal amount of overhead to the script. Depending on the size of the script and where the "Kix timing cycle" is when the script starts, the difference is 0-16 ms when timestamping is enabled.
Also - I write the $PERFLOG value to a file AFTER tha last TimeStamp() call so the performance logging isn't included in the script performance. If I were to hazard a guess, it takes longer to write the PerfLog data than to collect it!
Glenn
_________________________ Actually I am a Rocket Scientist!
Registered: 2002-05-13
Posts: 311
Loc: STRASBOURG, France
Glenn, instead of using a string manipulation with right(...)in the function, why don't you use directly @TICKS, which is the number of milliseconds elapsed since computer was last booted ? with a code like that :
#208321 - 2014-01-1407:47 PMRe: Running time of each line of code in kixtart
[Re: ChristopheM]
Glenn BarnasGlenn Barnas KiX Supporter
Registered: 2003-01-28
Posts: 4403
Loc: New Jersey
Christophe,
On long running systems, @TICKS can become negative. I seem to recall that it takes somewhere around 37 or 38 days to roll over. Not sure it this was fixed in current versions of Kix, but I tend to avoid it for that reason. I do use @TICKS for specific timing checks, usually in a function that detects negative values and adjusts the calculation accordingly.
This example is a timestamp of when the event occurred, so @MSECS is the correct usage - the number of ms in the current second. The Right(...) is simply to pad the value with zeros so there is no confusion when scanning the log. It's always displayed in thousands of a second. If I used @TICKS along with @DATE and @TIME, the time that the event occurred would be inaccurate.
Glenn
_________________________ Actually I am a Rocket Scientist!
Registered: 2002-05-13
Posts: 311
Loc: STRASBOURG, France
you are right but... it seems that @ticks returns a signed 32bits counter. it means that the value : - is incremented from 0 to 2147483647 (24d 20h 31m 23s and 647ms) - then becomes -2147483648 - then is incremented from -2147483648 to 2147483647 (49d 17h 2m 47s and 295ms) and so on. It would be unlucky to measure script execution when @ticks reaches the max value but it is possible. If i have a code like the following
the result is wrong only if $starttime > $endtime. In this case, we should use (2147483647-$startime)+(2147483648+$endtime)+1. As i have a problem with minimal negative value in kix, i have the following code :
Code:
$starttime=@ticks
...
"elapsed time : " elapsedtime( $startime, @ticks ) ?
function elapsedtime( $t1, $t2 )
if ($t2<$t1)
$c1 = CDBL(2147483647.0)-$t1 ; from $t1 to 2147483647
$c2 = CDBL(1.0) * $t2 + 2147483647 + 1 ; from -2147483648 to $t2
$elapsedtime = INT($c1 + $c2 + 1)
else
$elapsedtime = $t2 - $t1
endif
endfunction
An other reason to use @TICKS in calculation instead of @Date, @Time, @MSecs is that in background, w32time service can change the windows clock !!! I use @Date and @Time to write in log file but it is just an indication. I don't use theses macros to calculate elapsed time.
