PowerShell Quickie: Measuring script performance with the Stopwatch class

No time for love, Dr. Jones

it feels really, really good to finish up a PowerShell function, doesn’t it? You call the code, it works exactly like you want it to, it’s got a nice complete help file, and even good -Verbose  logging and -WhatIf  support. Now that you’ve got it running though, you might start to question your work. “Could I have done it differently?” “Could I have done it more efficiently?”

“Could I have done it faster?”

That last one is tricky. I’m a firm believer of good code > fast code, but faster code is always good. Once I have something that works, I’ll go back and look for opportunities to make it faster. The first step is knowing just how fast your code actually runs.

Your expected wait time is…

If someone asks you how long your script takes to run, chances are you type this in:

Get-History | Select-Object ID, @{Expression={$_.EndExecutionTime - $_.StartExecutionTime}}, CommandLine

And you might see something like this:

We can see I cleared the history buffer of my session (Clear-History ), then ran a script. It’s nothing fancy; just connecting to my local instance of SQL Server and outputting a list of tables to a text file. With Get-History , I can see every command I put in the buffer, and using expressions I can calculate how long a command took.

And that’s great and all, but that’s the entire execution time. If there are multiple steps to your function, how long does each step take? If your script execution is 186 seconds, how much of time is spent on a database query? What about a loop? How long does each iteration take? Are you writing to a network share, and want to know what the latency is? Get-History  isn’t the tool of this, but thankfully we have other methods.

Runners, take your mark

In PowerShell since we have access to .NET classes, there’s one in particular that is super useful for measuring code performance: System.Diagnostics.Stopwatch. With the Stopwatch class, you can have discrete control over timing your code. Here’s my example code from the section above, but this time I added a stopwatch object and added verbose logging:

#Start-StopWatchExample.ps1
[cmdletbinding()]
param (
    [Parameter(Mandatory=$true)] [string] $ServerName,
    [Parameter(Mandatory=$true)] [string] $DatabaseName,
    [Parameter(Mandatory=$true)] [string] $FilePath
)
begin {
    $StopWatch = New-Object System.Diagnostics.Stopwatch
    $StopWatch.Start()
    Write-Verbose "Testing for required modules being loaded..."
    if ((Get-Module sqlps) -eq $null -and (Get-Module sqlserver) -eq $null)
    {
        Throw "SQLPS/SQLSERVER module not loaded! Unable to continue"
    }       
    
}

process {
    Write-Verbose "Getting all the tables in database $DatabaseName on server $ServerName"
    $Database = Get-ChildItem -Path "SQLSERVER:\SQL\$ServerName\DEFAULT\Databases" | Where-Object {$_.Name -eq $DatabaseName}
    $Tables = $Database.Tables
    Write-Verbose ("Completed ({0} ms)" -f $StopWatch.ElapsedMilliseconds)
    Write-Verbose "Outputting all tables from database $DatabaseName..."
    ForEach ($t in $Tables) {
        ($t.Schema + "." + $t.Name) | Out-File -FilePath ($FilePath + "\tablelist.txt") -Append
    }
    Write-Verbose ("Completed ({0} ms)" -f $StopWatch.ElapsedMilliseconds)
}

end {
    $StopWatch.Stop()
}

Running this (in VS Code, which by the way, why aren’t you using it yet?) we can see how the .ElapsedMilliseconds  property can show us time spent so far:

You can clearly see how adding in these measures can help with debugging, or user information if they’re curious just what step of your process is executing. Stopwatch is part of the system.diagnostic namespace, and I can’t think of a better place for it to live.

Sharp-eyed readers might notice that when I run the script, the times it outputs are cumulative; each step includes the previous steps times. If you want even more discrete timing of your code, you can use some of the object methods like .Reset()  and .Restart()  after each verbose logging statement. Check out the MSDN docs for more info.

Conclusion: “It’s fast” isn’t as good as “It takes X (milli)seconds to run.”

I’ll take quantitative over qualitative measurements any day of the week, and twice on Sundays. It’s not enough to know how long your script runs, but how long each section takes. If you’re looking to optimize, it helps to know what parts of your code are taking the longest and hopefully provide a starting point for optimization. Or, if something all of a sudden starts running slow, it can help tell you why: what step is your code on, and is it working with things out of your control (like a network share, or database query) With tools like the stopwatch class, you have the means to collecting that information more than you do with something like just Get-History .