How can I guarantee the order that objects are instantiated in Powershell?

Question

It's fairly simple to time a block of code using Measure-Command, [system.diagnostics.stopwatch] or by diffing a couple of Get-Date calls, but here's the weird thing;

When I wrap Measure-Command with two date objects, sometimes Measure-Command.TotalMilliseconds is longer than ($EndTime - $StartTime).TotalMilliSeconds.

Is the $EndTime object being instantiated before Measure-Command finishes?

Why does this still happen if I run single-threaded; powershell.exe -sta?

Is there any way to force $EndTime to be set after Measure-Command ends?

Is there any guarantee StartTime has been created before Measure-Command?

Clearly this particular method is not a sensible way to evaluate code execution time.

$Stopwatch = [system.diagnostics.stopwatch]::startNew() 
$mc =Measure-Command{Invoke-WebRequest -Uri "http://www.google.com" -Method Head}
$Stopwatch.stop()


$mc.TotalMilliseconds
$Stopwatch.Elapsed.TotalMilliSeconds
"="
 $Stopwatch.Elapsed.TotalMilliSeconds - $mc.TotalMilliseconds


"`n"

$StartTime = (get-Date)
$mc = Measure-Command{Invoke-WebRequest -Uri "http://www.google.com" -Method Head}
$EndTime = (get-Date)

$mc.TotalMilliseconds
($EndTime - $StartTime).TotalMilliSeconds
"="
($EndTime - $StartTime).TotalMilliSeconds - $mc.TotalMilliseconds #This should never be negative but sometimes it is.

"`n"

$mc1 =Measure-Command{$mc2 = Measure-Command{Invoke-WebRequest -Uri "http://www.google.com" -Method Head}}

$mc1.TotalMilliseconds - $mc2.TotalMilliseconds 

Example output

122.3065
122.4322
=
0.125700000000009


142.8695
140.6371
=
-2.23240000000001


0.104199999999992

Answer 1

Oh boy, that's a lot of interesting questions, although I sense you may have been led astray by the fact that not all methods of measuring are equal - so let's go through them!

Why does this still happen if I run single-threaded; powershell.exe -sta?

Because this is not a threading or concurrency issue

Is there any way to force $EndTime to be set after Measure-Command ends?

Yes, by splitting them into separate statements (as you've already done)

Is there any guarantee $StartTime has been created before Measure-Command?

For the same underlying reasons as the previous answer; yes!

Clearly this particular method is not a sensible way to evaluate code execution time.

Aaaaaaand, you just gave yourself the answer :)

---

DateTime.Now is a terrible source for accurate interval measurements

Get-Date, without any parameters specified, returns the value of DateTime.Now

Although DateTime.Now returns a DateTime struct with a high degree of precision, its value is obtained by querying the operating system for the current wall-clock time, and this interaction does not produce a result that is accurate commensurate its potential precision - for more on this I'd suggest reading this blog post by Eric Lippert

You'll likely see a lot of "jitter" rather than a normal interval distribution if you tested it with something like:

$timestamp = Get-Date
0..9 |%{
    $timestamp - ($timestamp = Get-Date)
} |Select Ticks

In this example I'm even comparing the Ticks property rather than TotalMilliSeconds, getting values with (supposedly) 10000 times the precision - if you compared TotalMilleseconds instead you're even likely to get results of on a modern PC 0.

---

Measure-Command internally uses a StopWatch, which in turn uses the kernel32!QueryPerformanceCounter API, which provides a much more precise source of linear interval measurements, since its unaffected by wall-clock jitter and synchronization - and this is exactly the reason you never see this discrepancy when you use [StopWatch] for the outer measurement

Answer 2

To complement Mathias R. Jessen's helpful answer - whose main point bears repeating: use System.Diagnostics.Stopwatch for the most accurate time measurements available, don't use System.DateTime:

As a minor point: If you do use System.DateTime - for convenience, in cases where accuracy isn't paramount - use [DateTime]::UtcNow rather than [DateTime]::Now, for two reasons:

• Using UTC (UtcNow) works anytime: unlike local time (Now) it isn't affected by DST (daylight-saving time) transitions.

  • However, you're still susceptible to realtime-clock changes due to time synchronization.

• There is no benefit in translating UTC to local time in this case (which also slows things down, though only marginally so).

Curiously, the accuracy of System.DateTime seems to have improved in .NET Core (cross-platform) vs. .NET Framework (Windows-only), and therefore also in PowerShell Core vs. Windows PowerShell.

That is, in my test the symptom you describe no longer surfaces in PowerShell Core, on any supported platform, whereas it can reliably be reproduced in Windows PowerShell.

The simplest test is to do the following:

# Loop for as long two *consecutive* [datetime]::UtcNow calls
# report the *same* tick count.
while (([datetime]::UtcNow - [datetime]::UtcNow).Ticks -eq 0) { write-host -nonewline . }

If [datetime]::UtcNow is accurate enough to detect that time has elapsed between two consecutive calls to it, the loop should never be entered.^[1]

• That is indeed what happens in PowerShell Core.

• By contrast, in Windows PowerShell, the two consecutive calls typically report the exact same point in time: you'll see many dots and never none. Eventually, a difference is reported, after a wildly varying number of iterations.

The same applies to a variation of your code:

$i = 0
do {

  Write-Host . -NoNewline
  ++$i

  $StartTime = (get-Date)
  # Note: the specific command being measured is incidental to the issue.
  $mc = Measure-Command { $PSVersionTable } 
  $EndTime = (get-Date)

  $diff = ($EndTime - $StartTime).TotalMilliSeconds - $mc.TotalMilliseconds #This should never be negative but sometimes it is.

} while ($diff -ge 0)
Write-Host
"Took $i try/tries to get negative value: $diff; DateTime timespan: $(($EndTime - $StartTime).TotalMilliSeconds)"

The code loops and prints a dot in each iteration until the difference in timespans is unexpectedly negative.

PowerShell Core keeps printing dots indefinitely, while Windows PowerShell stops after 1 - 2 iterations.

---

^{[1] PowerShell's need to initially interpret and then JIT-compile its code certainly slows the individual calls down, compared to precompiled code. Running compiled C# code while (true) Console.WriteLine((DateTime.UtcNow - DateTime.UtcNow).Ticks); still gives you 0 in .NET Core, but only about two thirds of the time in my tests, whereas in .NET Framework it seems to be exclusively 0.}