When you want to time something in a PowerShell script it is usually not high frequency timing you are looking into. That could be how long time it took to run the script. In a simple situation like this it is common to see a solution where a
DateTime object is created in the beginning and another object is created in the end and finally the duration is calculated. Usually the DateTime object is created with the
Get-Date cmdlet.
But this is rather ineffective as at least three objects are created: Two DateTime objects for the measure and one
TimeSpan object on the calculation.
A general recommendation in books and articles is to use a
Stopwatch object and read the elapsed time from there. This solution is way more effective as only one object is used for measure.
But...
There is a small penalty when asking the for the elapsed time from the Stopwatch object using the property
Elapsed. The Stopwatch object actually works with processor ticks internal so when the object is asked for the elapsed time it will have to calculate this time and create a TimeSpan object to return the result.
Actually there is another property on a Stopwatch object that return elapsed milliseconds (
ElapsedMilliseconds), but this return a Int64 object so the precision is not good enough for very fast activities.
You can get even closer to the Stopwatch object inner workings by asking for the Ticks with the property
ElapsedTicks. This will still have to create a new object to return the result but this object is a
Int64 object which is a much more simple object and then much more effective to create and handle.
When the activity is done you can convert the difference on these integers to a Timespan object. But this converting you can move away from the high performance part of your script.
Actually it is quite simple to convert Ticks or difference in Ticks to a TimeSpan in Powershell. All you have to do is to ask PowerShell for the conversion like this
$Timespan = [System.Timespan]$Stopwatch.ElapsedTicks
To make a simple comparison of the performance with the different solutions described above I have created four small test functions:
- DateTime by Get-Date
- Stopwatch.Elapsed
- Stopwatch Milliseconds
- Stopwatch Ticks
The general structure of each test function is to measure time over a simple loop. And this test is repeated over several iterations.
I have create a small function to calculate values of minimum, maximum and average on each testrun except in test function three on Stopwatch Milliseconds as this generates Int64 and not TimeSpan results.
[double]$Time = 0.0
[double]$sum = 0.0
[double]$max = 0.0
[double]$min = [double]::MaxValue
for ($i=0; $i -lt $Timespans.Length; $i++) {
$Time = $Timespans[$i].TotalMilliseconds
$sum += $Time
if ($Time -gt $max) { $max = $Time }
if ($Time -lt $min) { $min = $Time }
}
[double]$avg = $sum / $Timespans.Length
"Avg = $avg ms"
"Max = $max ms"
"Min = $min ms"
The first test function is rather straight foreward using the Get-Date cmdlet:
[System.TimeSpan[]]$TimeSpans = [System.TimeSpan[]]::new($Iterations)
foreach ($n in (0..($TimeSpans.Length-1))) {
$Start = Get-Date
foreach ($i in [int[]](0..$TimeLoops)) {
#Burn Time
}
$End = Get-Date
$TimeSpans[$n] = $End - $Start
}
Get-TimeStats -TimeSpans $TimeSpans
The second test function looks like many other examples on Stopwatch.Elapsed:
[System.TimeSpan[]]$TimeSpans = [System.TimeSpan[]]::new($Iterations)
foreach ($n in (0..($TimeSpans.Length-1))) {
$Stopwatch = [System.Diagnostics.Stopwatch]::StartNew()
foreach ($i in [int[]](0..$TimeLoops)) {
#Burn Time
}
$Stopwatch.Stop()
$TimeSpans[$n] = $Stopwatch.Elapsed
}
Get-TimeStats -Timespans $TimeSpans
As mentioned earlier the third test function on Stopwatch milliseconds is a bit longer as it has it own calculations on statistics:
[Int64[]]$Elapsed = [Int64[]]::new($Iterations)
[Int64]$sum = 0
[Int64]$min = [Int64]::MaxValue
[Int64]$max = 0
[System.Diagnostics.Stopwatch]$Stopwatch = [System.Diagnostics.Stopwatch]::StartNew()
foreach ($n in (0..($Elapsed.Length-1))) {
[Int64]$Start = $Stopwatch.ElapsedMilliseconds
foreach($i in [int[]](0..$TimeLoops)) {
#Burn Time
}
[Int64]$End = $Stopwatch.ElapsedMilliseconds
$Elapsed[$n] = $End - $Start
$sum += $Elapsed[$n]
if ($Elapsed[$n] -lt $min) { $min = $Elapsed[$n] }
if ($Elapsed[$n] -gt $max) { $max = $Elapsed[$n] }
}
[double]$avg = $sum / $Elapsed.Length
"Avg = $avg ms"
"Max = $max ms"
"Min = $min ms"
The fourth and last test function on the Stopwatch Ticks is not in common examples but still I think it is simple enough to be useful:
[System.TimeSpan[]]$Elapsed = [System.TimeSpan[]]::new($Iterations)
$Stopwatch = [System.Diagnostics.Stopwatch]::StartNew()
foreach ($n in (0..($Elapsed.Length-1))) {
$Start = $Stopwatch.ElapsedTicks
foreach($i in [int[]](0..$TimeLoops)) {
#Burn Time
}
$End = $Stopwatch.ElapsedTicks
$Elapsed[$n] = [System.TimeSpan]($End - $Start)
}
Get-TimeStats -TimeSpans $Elapsed
I have completed some test runs and my general impression is that
- The average test time is about the same on all test functions.
- The DateTime test function (#1) has a much higher max test time. Of the other three test functions the one on Stopwatch Ticks (#4) has the lowest max test time.
- As the precision on the Stopwatch Milliseconds (#3) is very bad on very low values it's min test time value is useless. Of the rest test functions StopWatch ticks (#4) has a slightly lower min test time than the other two test functions, but this is not significant.
My general and personal (subjective) conclusion is that I usually will go with Stopwatch Elapsed as it gives a nice blend of performance and convenience.
One situation where I would consider using Stopwatch Ticks is a sequence of several small activities where I want to measure each activity. In this I would start one Stopwatch and the just read ElapsedTicks before and after each activity. And only when all activities are finished I will shut down the Stopwatch.
In real high performance scenarios I will also consider using Stopwatch Ticks. Or switch to a high performance platform like C# or C++.
Posts
