Ok, back to business. No electronics at least for a few posts though.

It will be clear later why I became interested in this topic. But it is, on its’ own, worth for a post, so here it is.

Measure-Command

The canonical way to measure how long something runs in PowerShell is to use Measure-Command cmdlet.

> Measure-Command { "do stuff" }


Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 0
Milliseconds      : 0
Ticks             : 7436
TotalDays         : 8,60648148148148E-09
TotalHours        : 2,06555555555556E-07
TotalMinutes      : 1,23933333333333E-05
TotalSeconds      : 0,0007436
TotalMilliseconds : 0,7436

One notable downside of this is that you see no output from a command. Time span is returned instead.

What else can we do?

Some options are listed in that post:

Pair of [DateTime] objects

Let’s calculate time span as a difference between two moments of time — before and after the command.

> $startTime=(Get-Date); "do stuff"; $Elapsed=(Get-Date)-$startTime; $Elapsed
do stuff


Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 0
Milliseconds      : 0
Ticks             : 9998
TotalDays         : 1,15717592592593E-08
TotalHours        : 2,77722222222222E-07
TotalMinutes      : 1,66633333333333E-05
TotalSeconds      : 0,0009998
TotalMilliseconds : 0,9998

Not as convenient as Measure-Command, but it does the job — we have both the command output and the time span.

[System.Diagnostics.Stopwatch] object

Approximately the same thing as previous method, but with .NET object, designed specifically for the task.

> $stopwatch = [System.Diagnostics.Stopwatch]::startNew(); "do stuff"; $stopwatch.Stop(); $stopwatch.Elapsed
do stuff


Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 0
Milliseconds      : 0
Ticks             : 6602
TotalDays         : 7,6412037037037E-09
TotalHours        : 1,83388888888889E-07
TotalMinutes      : 1,10033333333333E-05
TotalSeconds      : 0,0006602
TotalMilliseconds : 0,6602

It looks even less convenient when used as is.

Stopwatch wrapped into a function

Let’s try to improve the situation with Stopwatch class. In order to avoid the Measure-Command issue, we will pass output as is, and put time span into it’s own variable with Set-Variable cmdlet.

function Stopwatch-Command {
    param ( [ScriptBlock]$ScriptBlock )
    $stopwatch = [System.Diagnostics.Stopwatch]::StartNew()
    & $ScriptBlock
    $stopwatch.Stop()
    Set-Variable Elapsed -value $stopwatch.Elapsed -scope 1
}

After running Stopwatch-Command, $Elapsed variable will be set in a scope from which the function was called.

> Stopwatch-Command { "do stuff" }; $Elapsed
do stuff


Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 0
Milliseconds      : 1
Ticks             : 12149
TotalDays         : 1,40613425925926E-08
TotalHours        : 3,37472222222222E-07
TotalMinutes      : 2,02483333333333E-05
TotalSeconds      : 0,0012149
TotalMilliseconds : 1,2149

Looks nice and easy to use. There is about half a millisecond overhead — barely makes a difference.

Command output and elapsed time can also be swapped like this:

function Stopwatch-Command2 {
    param ( [ScriptBlock]$ScriptBlock )
    $stopwatch = [System.Diagnostics.Stopwatch]::StartNew()
    $output = & $ScriptBlock
    $stopwatch.Stop()
    $stopwatch.Elapsed
    Set-Variable Output -value $output -scope 1
}

> Stopwatch-Command2 {"do stuff"}; $Output


Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 0
Milliseconds      : 0
Ticks             : 6606
TotalDays         : 7,64583333333333E-09
TotalHours        : 1,835E-07
TotalMinutes      : 1,101E-05
TotalSeconds      : 0,0006606
TotalMilliseconds : 0,6606

do stuff

But I have no idea if there is any sense in doing this. Command output isn’t available until command is finished in this case.

More ideas from that stackoverflow question:

Execution time from command history

All commands executed in PowerShell are stored along with their start and end of execution times, and can be accessed with Get-History cmdlet.

I wrapped this into a function:

function Measure-Last {
    $command = Get-History -Count 1
    $command.EndExecutionTime - $command.StartExecutionTime
}

PS C:\some-folder
> "do stuff"
do stuff
PS C:\some-folder
> Measure-Last


Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 0
Milliseconds      : 2
Ticks             : 20013
TotalDays         : 2,31631944444444E-08
TotalHours        : 5,55916666666667E-07
TotalMinutes      : 3,3355E-05
TotalSeconds      : 0,0020013
TotalMilliseconds : 2,0013

Some overhead included into the numbers apparently, but the huge advantage is that it can be used as an afterthought.

Add $command.CommandLine into the function if you want to be sure that you’re measuring the right command.

In case you’re caught in a field and have no such function in your profile, you’ll have to reproduce it in place, of course:

PS C:\some-folder
> "do stuff"
do stuff
PS C:\some-folder
> $command = Get-History -Count 1; $command.EndExecutionTime - $command.StartExecutionTime


Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 0
Milliseconds      : 2
Ticks             : 20018
TotalDays         : 2,31689814814815E-08
TotalHours        : 5,56055555555556E-07
TotalMinutes      : 3,33633333333333E-05
TotalSeconds      : 0,0020018
TotalMilliseconds : 2,0018

Another Stopwatch wrapper

That thing may also have some use.

In case of single run it makes not much sense:

> time { "do stuff" }
do stuff

Avg: 1.3325ms
Min: 1.3325ms
Max: 1.3325ms

But averaging results from multiple runs is more meaningful:

> time { "do stuff" } -Samples 100 -Silent
....................................................................................................
Avg: 0.0472ms
Min: 0.035ms
Max: 0.6919ms

Proper benchmarking setup and results averaging is another can of worms, of course.

Using build automation tools

Psake will provide a report for you on how long it took to run your tasks.

If you have a file “my_tasks.ps1” with following content:

Task DoStuff {
    "do stuff"
}

You will get following results:

> Invoke-psake my_tasks.ps1 DoStuff
psake version 4.6.0
Copyright (c) 2010-2014 James Kovacs & Contributors

Executing DoStuff
do stuff

Build Succeeded!

----------------------------------------------------------------------
Build Time Report
----------------------------------------------------------------------
Name    Duration
----    --------
DoStuff 00:00:00.0206136
Total:  00:00:00.0751143

It should be quite handy to have things organized in form of tasks. Automatic time measurement is just one of benefits.

Time overhead is most notable here, with a whole 20 milliseconds. But still is small enough for practical purposes.

Unfortunately, psake is not exporting much information about task running results for later use, so task duration is only available for visual control.

In this post I listed some measuring tools, and some of them will be handy in one of the following posts. Stay tuned.