Showing posts with label datetime. Show all posts
Showing posts with label datetime. 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++.

2017-04-29

T-SQL formatted duration

I have a database backup that takes more than two days, and I want to look at the duration. But looking at the result of a DATEDIFF the figures are difficult to compare direct.
That took me to format the duration to something readable. At first I wanted to format to ISO-8601, but that turned out to be too cumbersome in Transact-SQL. Especially getting the leading zeros was a challenge that I usually can handle in PowerShell or JavaScript, but T-SQL is not a programming language similar user friendly formatting…
Jeff Smith wrote back in 2007 a great article "Working with Time Spans and Durations in SQL Server", but I wanted to avoid the strange date-like part and the multiple columns he worked with.

To combine the different parts into one single-column answer I use part indicators like 'd' for days, 'h' for hours, 'm' for minutes and 's' for seconds. That I think is quite common indicators and should be immediately recognizable to most people. Also non-IT end users.

Most log solutions give a duration with a lot of seconds, like a SQL Server  database backup. But that can be difficult to comprehend and compare directly

DECLARE @duration INT = 221231;  -- seconds
SELECT CAST(@duration / 86400 AS varchar(3)) + 'd' + CAST((@duration % 86400) / 3600 AS varchar(2)) + 'h' + CAST((@duration % 3600) / 60 AS varchar(2)) + 'm' + CAST(@duration % 60 AS varchar(2)) + 's'

This gives the output
2d13h27m11s
That is 2 days, 13 hours, 27 minutes and 11 seconds.

The motivation for this blog entry is database backup history, and the formatting above can be used against the history
SELECT
  [database_name]
 ,backup_set_id, media_set_id, name
 ,backup_start_date, backup_finish_date
 ,CAST(DATEDIFF(SECOND, [backup_start_date], [backup_finish_date]) / 86400 AS varchar(3)) + 'd '
   + CAST((DATEDIFF(SECOND, [backup_start_date], [backup_finish_date]) % 86400) / 3600 AS varchar(2)) + 'h '
   + CAST((DATEDIFF(SECOND, [backup_start_date], [backup_finish_date]) % 3600) / 60 AS varchar(2)) + 'm '
   + CAST(DATEDIFF(SECOND, [backup_start_date], [backup_finish_date]) % 60 AS varchar(2)) + 's' AS [duration_formatted]
 ,(backup_size / 1024 / 1024 / 1024) as [backup_size_gb]
 ,(compressed_backup_size / 1024 / 1024 / 1024) as [compressed_backup_size_gb]
FROM msdb.dbo.backupset
--WHERE [database_name] = 'my_large_database'
ORDER BY [backup_finish_date] DESC

You can comment in or out lines in the statement above to get what you need in the given situation.

Maybe one can use STUFF to insert values in pre-formatted output, but that I could not get to work in first shot. And it did not really add significant value to the output...

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.

2008-08-14

ISO 8601 date formatting using PowerShell

My favorite timestamp is the ISO 8601 format [YYYY]-[MM]-[DD]T[hh]:[mm]:[ss.sss]Z.
The ISO 8601 standard is very well described in a Wikipedia article (ISO 8601).

I do miss a ISO formatting option in .NET/PowerShell, but using DateTime formatting, an acceptable result is found:
$theDate = Get-Date
"{0:yyyy'-'MM'-'dd'T'HH':'mm':'ss'.'fffffff'Z'}" -f $theDate.ToUniversalTime()
$theDate.ToUniversalTime().ToString( "yyyy-MM-ddTHH:mm:ss.fffffffZ" )
The formatting is shown twice using different syntax.
I've chosen seven digits on the second because I have logging in mind while working with time stamp. I have (once) seen that three digits wasn't enough - it was in a technical database log on a z/Server "mainframe".

A execution gives this result:
2008-01-13T10:02:36.8992896Z
I would like to get the week of the year, but again this is a problem. Is it because a week number is more used in Europe than on the other side of the Atlantic?
Thomas Lee has tried (eggheadcafe conversation), and I tried his examples. I regret to say he's right – again.

Using the formatting specifier 'o' (oscar) from the DateTimeFormatInfo Class to the CmdLet Get-Date will generate a output with seven digits, but also a a part with a reference to the timezone. Mark Puckett has made a comment to this post about this possibility. And he is right that this specifier wil give a output that is very precise. But I choose not to use this as I go for UTC time in a log as I think it makes the log entries more readable on senior management level.

History

2008-01-14 Blog post created
2017-02-05 Section on -Format o added inspired by comment by Mark Puckett.