PowerShell timer/stopwatch accuracy

Question

I find that the System.Diagnostics.Stopwatch class has what seems to be measurable inaccuracy, even over a short time period (i.e. 20 seconds). My process is showing an elapsed time of 20.3+ seconds for a process coded to run 20 seconds:

$elapsed = [System.Diagnostics.Stopwatch]::StartNew()
write-host "Started at $(get-date)"

for ($t=1; $t -le 20; $t++) {
    Write-Host "Elapsed Time: $($elapsed.Elapsed.ToString())"
    sleep 1
}

write-host "Ended at $(get-date)"
write-host "Total Elapsed Time: $($elapsed.Elapsed.ToString())"

    Started at 02/02/2013 15:08:43
    Elapsed Time: 00:00:00.0329924
    Elapsed Time: 00:00:01.0417435
    Elapsed Time: 00:00:02.0547547
    Elapsed Time: 00:00:03.0689716
    Elapsed Time: 00:00:04.0820497
    Elapsed Time: 00:00:05.0963413
    Elapsed Time: 00:00:06.1113915
    Elapsed Time: 00:00:07.1244044
    Elapsed Time: 00:00:08.1396105
    Elapsed Time: 00:00:09.1528952
    Elapsed Time: 00:00:10.1659905
    Elapsed Time: 00:00:11.1800884
    Elapsed Time: 00:00:12.1940009
    Elapsed Time: 00:00:13.2081824
    Elapsed Time: 00:00:14.2223585
    Elapsed Time: 00:00:15.2375023
    Elapsed Time: 00:00:16.2506360
    Elapsed Time: 00:00:17.2656845
    Elapsed Time: 00:00:18.2790676
    Elapsed Time: 00:00:19.2928700
    Ended at 02/02/2013 15:09:04
    Total Elapsed Time: 00:00:20.3080067

Is this kind of accuracy drift to be expected when using the Stopwatch class in PowerShell? It seems to increase disproportional to the time span (i.e. 10 seconds is off by 0.1 and 20 by 0.3). Is my code at fault?

Joinery

Answer 1

The question is, what are you trying to do? If you are trying to determine how long it takes a script to run, exactly, you should use the stopwatch. However, if you are trying to start a new sequence of commands after a specified period, use a [System.Timers.Timer] and register an event for the elapsed event on the timer object. Then specify the action of the registered event to what it you are trying to accomplish.

Pesticide

Answer 2

You have 20 1 second pauses, but you have other things going on as well. There is a loop that increments and tests a variable, and you write the elapsed time on each iteration. These extra things take time.

This still has a 20 second pause, and the elapsed time is closer to 20 seconds because there is less extra stuff that PowerShell has to do:

$elapsed = [System.Diagnostics.Stopwatch]::StartNew()
write-host "Started at $(get-date)"
sleep 20
write-host "Ended at $(get-date)"
write-host "Total Elapsed Time: $($elapsed.Elapsed.ToString())"

Tatar

Get rid of the Started and Ended Write-Host calls and it should be even closer. Stopwatch uses Windows' high frequency counter api so it is pretty accurate. – Husch

Rynant, that would be 20 seconds. But it would no longer be a stopwatch -- just an sleep timer. That would stop my script from running until the sleep is complete. I need it to run a process and at the end, tell me how long it took to complete. – Joinery

I think you missed the point of my example. I was trying to show that the Diagnostics.Stopwatch class is not inaccurate. The reason the stopwatch in your script shows "20.3080067" seconds is because your script is doing other things besides sleeping. Also, the reason the Get-Date statements appear to be exactly 20 seconds apart is because the displayed time is rounded to the nearest second. – Tatar

Gotcha. So, if running my additional commands throws StopWatch off, how would one use Stopwatch to actually time a process accurately? Or would StopWatch not be the way to go for something like that? My actual code could take hours to complete, and I would like to get an elapsed time more accurate than this. – Joinery

Running additional commands does not throw stopwatch off. Running additional commands takes more time; hence, stopwatch is showing the correct time. Use stopwatch, it is accurate. – Tatar

Answer 3

The total time your code runs, depends on other factors, like how busy your system are.

Looking at source code of .NET, we can see that [System.Diagnostics.Stopwatch]::StartNew() uses the high resolution time counter. It calls the WINAPI QueryPerformanceCounter. That is: The class is so very precise!

I look on most recent source code of Start-Sleep, and noted that it uses kernel mode events to implement time wait. In addition to details already mentioned by users, Windows schedule can put another threads to run when powershel finishes your wait for sleep time, resulting in more time before your code calculates the elapsed time.

Also, writing to the video is cost operation because it is very high used resource on computer. To by pass it, i rewrite your code, so it don't write to video every time:

$elapsed = [System.Diagnostics.Stopwatch]::StartNew()
write-host "Started at $(get-date)"

$out = new-object 'string[]' 100;

for ($t=1; $t -le 20; $t++) {
    $out[$t] = "Elapsed Time: $($elapsed.Elapsed.ToString())"
    sleep 1
}
$out;
write-host "Ended at $(get-date)"
write-host "Total Elapsed Time: $($elapsed.Elapsed.ToString())"

Take a look on runs on system, powershell 5.1, Desktop, windows 10, CPU intel 3.0 Ghz.

First, i ran your original code, at normal priority, low concurrency: Script took 20.14s

Next, I ran original code, with some other CPU intensive process:Tooks 24.21s

Back, I ran my version of code, without write-host under idle system:Script tooks just 20.03s

The last one have a big difference to the first (idle with writes to the screen).

Sandman

Answer 4

Stopwatch is highly accurate. Sleep is not. Sleeping for 1 second will typically yield anywhere from a 0.985s to a 1.015s sleep; however, it could be substantially longer if there are other activities going on.

Helve