Advanced Scripts Execution Timing.

Scripting Forums Code Exchange
#1 

set repetitions to 12 -- or other. The more repetitions, the more accurate the result. 

set theTime to 0
repeat repetitions times
	set timeStart to current date
	
	-- HERE PUT YOUR TESTED SCRIPT'S ON RUN HANDLER
	
	set theTime to theTime + ((current date) - timeStart)
end repeat
set theTime to (1000 * theTime / repetitions) as integer -- result as milliseconds

This tip is very useful for me to test code lines one by one, or some snippet of the script, or the whole script.

For example, getting all properties of selected in “Mail” messages results on my machine in 900 milliseconds (that is, 0.9 seconds) with 10 iterations:


set repetitions to 10 -- or other what you want. 

set theTime to 0
repeat repetitions times
	set timeStart to current date
	
	tell application "Mail"
		set aMessage to item 1 of (get selection)
		tell aMessage
			set aContent to content
			set |source| to source
			set |subject| to subject
			set |sender| to sender
			set |messageId| to message id
			set messageSize to message size
			set wasForwarded to was forwarded
			set wasRedirected to was redirected
			set wasRepliedTo to was replied to
			set replyTo to reply to
			set readStatus to read status
			set junkMailStatus to junk mail status
			set |id| to id
			set flaggedStatus to flagged status
			set flagIndex to flag index
			set deletedStatus to deleted status
			set backgroundColor to background color
			set dateReceived to date received
			set dateSent to date sent
			set |mailBox| to its mailbox
		end tell
	end tell
	
	set timeEnd to current date
	set theTime to theTime + ((current date) - timeStart)
end repeat
set theTime to (1000 * theTime / repetitions) as integer -- result as milliseconds
#2

I was curious if the above script has any advantage over the following. I ran some timing tests using delay as the task being performed and the results were the same. So perhaps this is just a matter of style. BTW, I do a lot of script timing tests and would like to know if there is any best way to do this.


set repetitions to 10

set startTime to (time of (current date))
repeat repetitions times
	delay 1 --substitute whatever task is being performed
end repeat
set executeTime to (time of (current date)) - startTime

set theTime to (1000 * executeTime / repetitions) as integer
#3

Hi.

KniazidisR’s script doesn’t include the small amount of time it takes the repeat itself to execute, but does add two current date calls and some date math per repeat (although these only partially add to the timings). peavine’s does the opposite. Also, by subtracting the dates’ times instead of the dates themselves, it lays itself open to strange results if midnight occurs during the test!

In both cases, the time interval on which the final calculation is done is an exact number of seconds and is based on the number of date second boundaries crossed between the current date calls. So the “milliseconds” end result is likely to be far from accurate.

A more accurate result can be obtained by using NSDate in ASObjC. The interval result’s still in seconds, but with the fractional part included to quite a large number of decimal places:

use AppleScript version "2.4" -- Yosemite (10.10) or later
use framework "Foundation"
use scripting additions

set repetitions to 10
set startTime to current application's class "NSDate"'s |date|()

repeat repetitions times
	delay 0.75 --or whatever
end repeat

-- startTime was so many seconds *ago*, so multiply the interval by *minus* 1000 for a positive number of milliseconds.
set thetime to ((startTime's timeIntervalSinceNow()) * -1000 / repetitions) as integer
#4

Nigel–thanks for the script. I tested it with various code snippets and it works great.

I was curious and ran each script with one repetition with a timed-task of “delay 0.3”. The results were:

Peavine’s script - 0 milliseconds

KniazidisR’s script - 0 milliseconds

Nigel’s script - 302 milliseconds

This is not a usable test of anything but appears to demonstrate the decimal seconds returned when using NSDate.

#5

You should keep in mind that editors add a certain amount of overhead via instrumentation callbacks, especially when the codes involve sending events. This can distort results significantly. You’ll get a more accurate result if you use my Script Geek.app, which skips any callbacks, but ultimately an applet is the best host (assuming your ultimate destination is an applet).

#6

For geeks only…

I looked into this a bit more recently, and there are a couple of alternatives to using NSDate in ASObjC. First is the function CFAbsoluteTimeGetCurrent():

set theStart to current application's CFAbsoluteTimeGetCurrent()
-- do stuff
set timeTaken to (current application's CFAbsoluteTimeGetCurrent()) - theStart

Its main attraction is that it’s a little simpler to use/type than NSDate. It’s also actually a bit faster to execute, although that’s unlikely to make any difference unless you’re not timing repetitions.

There’s also systemUptime() in NSProcessInfo:

set theStart to current application's NSProcessInfo's processInfo()'s systemUptime()
-- do stuff
set timeTaken to (current application's NSProcessInfo's processInfo()'s systemUptime()) - theStart

More effort to type, and a bit slower to boot.

However, all of these are tied to the calculated time, which can change (time syncing, OS making corrections, leap seconds, timezone changes). Depending on a range of factors, the first two are not infrequent.

The most accurate clock on the system is a low-level kernel function, mach_absolute_time(), which is precise to the nanosecond — but it is not accessible to ASObjC. However, there’s another function, CACurrentMediaTime(), which is based on it and converts the result to seconds. So:

set theStart to current application's CACurrentMediaTime()
-- do stuff
set timeTaken to (current application's CACurrentMediaTime()) - theStart

Although it’s part of the QuartzCore framework, I don’t believe it needs a use framework statement other than for Foundation. In terms of overhead, it’s somewhere between using NSDate and CFAbsoluteTimeGetCurrent().

Here’s a bit more info:

https://kandelvijaya.com/2016/10/25/precisiontiminginios/

#7

The whole point of my hocus-pocus trick is the multiplicity of repetitions. If I meant 1 repetition, then the repetitions variable would not exist. As my article would not exist at all.

For myself, I decided to use the version with NSDate (by Nigel Garvey). I also consider this version the most optimal from all solutions, provided here. Of course, I will use a minimum of 2 repetitions.

And, Peavine, you forget say 1 thank to author of idea. This is not good. :slight_smile:

#8

KniazidisR. I clearly stated my intent in running only one repetition of the three scripts:

It was not my intent to criticize your script, and I’m sorry if it appeared that way.

#9

Now, I will search for fastest way to get base name of file. (in microseconds).
To get such results, I will use -1000000 multiplier. I will use 100 repetitions and will run test 5 times x 100 repetitions.

The file on my disk is this:

set theFile to "/Users/123/Library/Scripts/Get the Selection in app.scpt"

The 1st way will be the text item delimiters way:

set TID to text item delimiters
	set text item delimiters to {"/"}
	set n to last text item of theFile
	set text item delimiters to TID
--> 8,9,9,10,9 --> about 9 microseconds

The 2nd way will be the do shell script way:

set n to do shell script "basename " & quoted form of theFile
--> 21992, 20921, 22719, 22846, 25280 --> about 23000 microseconds

The 3rd way will be the System Events way:

tell application "System Events" to set n to name of disk item theFile
--> 7749, 7798, 7806, 8404, 8136 --> about 8000 microseconds

Next will be the info for way:

set n to name of (info for (POSIX file theFile as alias))
--> 6130, 4558, 4259, 2498, 2500 --> about 4000 microseconds

And last but not least the ASObjC way:

set theURL to current application's |NSURL|'s fileURLWithPath:theFile
	set n to theURL's lastPathComponent() as text
--> 209, 194, 183, 200, 219 --> about 200 microseconds

Note: when I put 1st line of this code offside the repeat loop, 2nd line code still takes 90 microseconds.

All these tests was performed with Nigel Garvey’s timing wrapper :slight_smile:

#10

Now, I will try the same tests with CACurrentMediaTime, proposed by Shane Stanley. (in nanoseconds)


use AppleScript version "2.4" -- Yosemite (10.10) or later
use framework "Foundation"
use scripting additions

set theFile to "/Users/123/Library/Scripts/Get the Selection in app.scpt"
set repetitions to 100

set theStart to current application's CACurrentMediaTime()
repeat repetitions times
	
	set TID to text item delimiters
	set text item delimiters to {"/"}
	set n to last text item of theFile
	set text item delimiters to TID
	
end repeat
set timeTaken to 1000000 * ((current application's CACurrentMediaTime()) - theStart) as integer
--> about 950 nanoseconds (0,95 microseconds)

set n to do shell script "basename " & quoted form of theFile
--> about 1982328 nanoseconds (1982 microseconds)

tell application "System Events" to set n to name of disk item theFile
--> about 735700 nanoseconds (736 microseconds)

Wow! I will not continue. So everything is already clear. The method proposed by Shane Stanley is better since the last timing code line itself consume very little time.

Thank you all for your contribution in this thread. :slight_smile:

#11

Shane. I starting using Script Geek and like it a lot. I especially like the convenience of having it running to the side when I’m writing/optimizing a script in Script Editor. Thanks.

#12

One caveat with CACurrentMediaTime() that was pointed out in a post a few years ago is that it stops timing when the computer goes into stand-by mode. Although this scenario is unlikely in real-world testing, it is for this reason that I have gotten in the habit of timing scripts with CFAbsoluteTimeGetCurrent(), which differs from CACurrentMediaTime() in execution speed and accuracy by only a small handful of nanoseconds.

#13

Not only is it unlikely, but in the context we’re talking about here, if it did happen, having the timer also stop would be a huge plus in terms of accuracy. But I think there’s more chance of the operator going to sleep running these sorts of tests than the computer going to sleep.

(And if your computer does a clock resync while a test is running, the difference can be quite a bit more than a handful of nanoseconds.)

#14

Shane, while neither of the scenarios you mention is likely to happen in real-world testing, your points are well taken and have convinced me to go with CACurrentMediaTime().

#15

FWIW, Script Geek uses mach_absolute_time(), and runs the scripts using an NSActivityOption of NSActivityLatencyCritical (“the activity requires the highest amount of timer and I/O precision available”). That probably makes its times a bit on the optimistic side.

#16

I normally use Script Geek to run timing tests but I occasionally need to exclude sections of a script from the timing results. With Shane’s help (see his posts below), I settled on the following revised script for this purpose:

use framework "Foundation"
use scripting additions

-- untimed code
set theDelay to 0.33 -- just an example

-- start time
set startTime to current application's CFAbsoluteTimeGetCurrent()

-- timed code
delay theDelay -- just an example

-- elapsed time
set elapsedTime to (current application's CFAbsoluteTimeGetCurrent()) - startTime
set nf to current application's NSNumberFormatter's new()
nf's setFormat:"0.000"
set elapsedTime to ((nf's stringFromNumber:elapsedTime) as text) & " seconds"

-- result
elapsedTime

It should be noted that this script does not work reliably with HFS file specifiers and the solution is to build file references using coercions. This is explained at:

https://latenightsw.com/adding-applescriptobjc-to-existing-scripts/

Also, the script will often issue a warning dialog if it is not compiled before being saved. There is no simple way to prevent this.

#17

It’s probably easier to use a number formatter:

use framework "Foundation"
use scripting additions

-- untimed code

set theStart to current application's CACurrentMediaTime()

-- timed code
delay 0.33 -- just an example

set timeTaken to (current application's CACurrentMediaTime()) - theStart
set nf to current application's NSNumberFormatter's new()
nf's setFormat:"0.0000"
return ((nf's stringFromNumber:timeTaken) as text) & " seconds"
#18

Thanks Shane. I tested both of our scripts and, as expected, the returned results were essentially identical. Your suggestion is simplest and is the one I’ll use.

#19

Shane (or another forum member). Your suggestion works great but it occasionally returns a number to 1 or 2 decimal places, and I would prefer that trailing 0’s be shown. I can do this with basic AS but I wondered if this is possible with ASObjC.

BTW, I modified your script to return (log actually) the timing results to 3 decimal places. So, just by way of example “0.2 seconds” would become “0.200 seconds” Thanks.

#20

I’ve changed the format string above to what it should have been.