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?

Answer 1

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())"