Showing posts with label TimeSpan. Show all posts
Showing posts with label TimeSpan. Show all posts

2020-01-03

High performance script timer

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:
  1. DateTime by Get-Date
  2. Stopwatch.Elapsed
  3. Stopwatch Milliseconds
  4. 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++.

2012-07-04

Readable seconds

When I restored a SQL Server database, the message ended with a status of the restore:
RESTORE DATABASE successfully processed 15025885 pages in 3372.932 seconds (34.803 MB/sec).

That is a lot of seconds, but I was asked by management about the restore time. Just giving a couple of thousands of seconds was just not good enough.
But PowerShell came to the rescue with the CmdLet New–TimeSpan:
(New-TimeSpan -Seconds 3372.932).ToString()
that gives
00:56:13

The format is hh:mm:ss given by the ToString() method to the .NET TimeSpan structure.

As the CmdLet is based on the .NET TimeSpan structure, and PowerShell is integrated with .NET, it is also possible to use the static method FromSeconds() exposed by the structure:
[System.TimeSpan]::FromSeconds(3372.932).ToString()

The result is exactly the same — as expected.


2012-05-29

Stopwatch

Some time ago I write about timestamp difference, and I have used it for measuring execution times.
But actually there is a much better way.

By using the Stopwatch class (System.Diagnostics.Stopwatch) I get a measument by a single object in stead of two DateTime (System.DateTime) objects.
Also I can take a look at the stopwatch while it is running by the Elapsed property.
The result given is a TimeSpan (System.TimeSpan) object, and by reading the value with the ToString method it is very usefull.

The Stopwatch is created by calling the static method StartNew():
PS C:\> $mywatch = [System.Diagnostics.Stopwatch]::StartNew()
Stopping the stopwatch is
PS C:\> $mywatch.Stop()
Reading the stopwatch without formatting the answer is also quite simple:
PS C:\> $mywatch.Elapsed

Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 14
Milliseconds      : 975
Ticks             : 149755134
TotalDays         : 0,000173327701388889
TotalHours        : 0,00415986483333333
TotalMinutes      : 0,24959189
TotalSeconds      : 14,9755134
TotalMilliseconds : 14975,5134

Reading the stopwatch with standard formatting [HH:mm:ss.ddddddd] gives you the result more readable:
PS C:\> $mywatch.Elapsed.ToString()
00:15:02.9033008

I use it for execution times. On scripts for the entire script and some subtasks.

2011-06-27

Timestamp difference

I was looking into Windows Application Log and SQL Server Error Log to investigate a incident, and needed to calculate the effective duration of the incident.

This is actually quite simple using PowerShell and the CmdLet Get-Date:
(Get-Date "24-06-2011 08:00:24") - (Get-Date "23-06-2011 16:24:49")

Days              : 0
Hours             : 15
Minutes           : 35
Seconds           : 35
Milliseconds      : 0
Ticks             : 561350000000
TotalDays         : 0,649710648148148
TotalHours        : 15,5930555555556
TotalMinutes      : 935,583333333333
TotalSeconds      : 56135
TotalMilliseconds : 56135000

A more compact answer can be acquired by
((Get-Date "24-06-2011 08:00:24") - (Get-Date "23-06-2011 16:24:49")).ToString()
15:35:35

The statement converts the timestamp strings to DateTime (System.DateTime) objects, subtracts the two objects and returns a TimeSpan (System.TimeSpan) object.