SQL Query Stats via Powershell
Sometimes, work tasks and questions that come up in the SQL Server Community Slack coincide.
A couple weeks ago, DrData asked
With
SET STATISTICS IO ON, is there really no way to show the TOTALS at the bottom? There are some nice tools like StatisticsParser but it sure would be nice to see the totals of all values right at the bottom, especially when there are many tables.
The task at hand in the office was a need to do the same thing, but with SET STATISTICS TIME ON. So I got to thinking…I can PowerShell my way through this, right?
Timing - The Naive Approach
You may be thinking “I can use Measure-Command to see how long my query took, why has Andy written so many words here?” And while that will tell you how long it took to process the query from PowerShell, it won’t be accurate for timing the execution of the query itself. As I learned and documented in a post several years ago, you’re measuring not only the time to execute the query, but also the time to send the results over the wire and process them on the client side. This is not ideal for our use case. We need the measurements to come from SQL Server itself, hence the use of SET STATISTICS TIME ON.
Getting the Data
By default, neither Invoke-DbaQuery (from dbatools) nor Invoke-SqlQuery (from Microsoft’s own sqlserver module) include the additional messages that are output when running a query with SET STATISTICS TIME ON. But all hope is not lost! With Invoke-SqlCmd, just include the -Verbose switch. If you’re using dbatools, you can get this information with the -MessagesToOutput switch. For both, we can include the SET statement as part of the query before we run it.
$Query = "set statistics time on; exec [dbo].[uspGetBillOfMaterials] @StartProductID = 966, @CheckDate = N'2024-01-15'";
Invoke-SqlCmd -Verbose -ServerInstance $SqlInstance -Database $Database -Query $Query;
Invoke-DbaQuery -ServerInstance $SqlInstance -Database $Database -Query $Query -MessagesToOutput;
But there’s a catch - you’ll notice that these two methods return your execution times in very different ways.
> Invoke-SqlCmd -Verbose -ServerInstance $SqlInstance -Database $Database -Query $Query
VERBOSE: SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
VERBOSE:
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
ProductAssemblyID : 966
ComponentID : 522
ComponentDesc : HL Touring Seat Assembly
TotalQuantity : 1.00
StandardCost : 145.8700
ListPrice : 196.9200
BOMLevel : 1
RecursionLevel : 0
# Many more results here
ProductAssemblyID : 531
ComponentID : 487
ComponentDesc : Metal Sheet 6
TotalQuantity : 1.00
StandardCost : 0.0000
ListPrice : 0.0000
BOMLevel : 4
RecursionLevel : 3
VERBOSE:
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 1 ms.
VERBOSE:
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 1 ms.
> Invoke-DbaQuery -ServerInstance $SqlInstance -Database $Database -Query $Query -MessagesToOutput;
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 1 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 2 ms.
ProductAssemblyID : 966
ComponentID : 522
ComponentDesc : HL Touring Seat Assembly
TotalQuantity : 1.00
StandardCost : 145.8700
ListPrice : 196.9200
BOMLevel : 1
RecursionLevel : 0
ServerInstance : localhost\sql22
Invoke-DbaQuery returns the output messages as part of the object that’s returned. This means that to capture and use those messages, we have to look through the Output stream and look for any of the type System.String instead of DataRows.
$BoM = Invoke-DbaQuery -ServerInstance $SqlInstance -Database $Database -Query $Query -MessagesToOutput;
$BoM | Where-Object { $PSItem.GetType().FullName -eq "System.String" };
Meanwhile, Invoke-SqlCmd returns the messages to the Verbose stream. This can’t be captured directly. But as Scott Newman points out, we can redirect Verbose to Output and capture it there.
(Invoke-SqlCmd -Verbose -ServerInstance $SqlInstance -Database $Database -Query $Query|out-null) 4>&1;
OK, Now What?
At this point, we’re able to:
- Execute the query
- Get compilation and execution times reported
- Capture the text containing these times
If I need to present a report of “this is how long these statements took”, I have more work to do - namely, parsing the output and figuring out which “bucket” it goes into. The complete script:
$SqlInstance = "localhost\sql22";
$Database = "AdventureWorks2022";
$Query = "set statistics time on; exec [dbo].[uspGetBillOfMaterials] @StartProductID = 966, @CheckDate = N'2024-01-15'";
$QueryParameters = @{
"SqlInstance" = $SqlInstance;
"Database" = $Database;
"Query" = $Query;
"CommandType" = "Text";
"AppendServerInstance" = $true;
"MessagesToOutput" = $true;
}
<#
Note: Because I'm including set statistics time on, I can't tell Invoke-DbaQuery that this is a stored procedure and pass parameters to it; I have to treat it as an ad-hoc (text) query
#>
$BoM = Invoke-DbaQuery @QueryParameters;
$QueryStats = $BoM | Where-Object { $PSItem.GetType().FullName -eq "System.String" };
<#
Note: If you want to use Invoke-SqlCmd, use the following instead:
$QueryStats = (Invoke-SqlCmd -Verbose -ServerInstance $SqlInstance -Database $Database -Query $QueryParameters["Query"] | out-null) 4>&1;
#>
$Regex = "CPU time = (\d+) ms,\s+elapsed time = (\d+) ms\.";
$ParseCPUTimeTotal = 0;
$ParseElapsedTimeTotal = 0;
$ExecuteCPUTimeTotal = 0;
$ExecuteElapsedTimeTotal = 0;
for ($i = 0; $i -lt $QueryStats.Count; $i++) {
$QueryStats[$i] -match $Regex | Out-Null;
if ($QueryStats[$i] -like "*SQL Server parse and compile time*") {
$ParseCPUTimeTotal += $Matches[1];
$ParseElapsedTimeTotal += $Matches[2];
}
if ($QueryStats[$i] -like "*SQL Server Execution Times*") {
$ExecuteCPUTimeTotal += $Matches[1];
$ExecuteElapsedTimeTotal += $Matches[2];
}
}
$QueryTimes = [PSCustomObject]@{
"Parsing CPU time (ms)" = $ParseCPUTimeTotal;
"Parsing elapsed time (ms)" = $ParseElapsedTimeTotal;
"Execution CPU time (ms)" = $ExecuteCPUTimeTotal;
"Execution elapsed time (ms)" = $ExecuteElapsedTimeTotal;
}
$QueryTimes;
And the output:
Parsing CPU time (ms) Parsing elapsed time (ms) Execution CPU time (ms) Execution elapsed time (ms)
--------------------- ------------------------- ----------------------- ---------------------------
0 0 0 4
Next Steps
This demonstrated how to capture the execution times. DrData asked for the I/O stats. Adding this isn’t terribly difficult - we just need to add io to our SET statement, another regular expression to search for, and then collect the data.
$SqlInstance = "localhost\sql22";
$Database = "AdventureWorks2022";
$Query = "set statistics time,io on; exec [dbo].[uspGetBillOfMaterials] @StartProductID = 966, @CheckDate = N'2024-01-15'";
$QueryParameters = @{
"SqlInstance" = $SqlInstance;
"Database" = $Database;
"Query" = $Query;
"CommandType" = "Text";
"AppendServerInstance" = $true;
"MessagesToOutput" = $true;
}
<#
Note: Because I'm including set statistics time on, I can't tell Invoke-DbaQuery that this is a stored procedure and pass parameters to it; I have to treat it as an ad-hoc (text) query
#>
$BoM = Invoke-DbaQuery @QueryParameters;
$QueryStats = $BoM | Where-Object { $PSItem.GetType().FullName -eq "System.String" };
<#
Note: If you want to use Invoke-SqlCmd, use the following instead:
$QueryStats = (Invoke-SqlCmd -Verbose -ServerInstance $SqlInstance -Database $Database -Query $QueryParameters["Query"] | out-null) 4>&1;
#>
$TimingRegex = "CPU time = (\d+) ms,\s+elapsed time = (\d+) ms\.";
$IORegex = "Table '[\#_\w+]+'\. Scan count (\d+), logical reads (\d+), physical reads (\d+)";
$ParseCPUTimeTotal = 0;
$ParseElapsedTimeTotal = 0;
$ExecuteCPUTimeTotal = 0;
$ExecuteElapsedTimeTotal = 0;
$Scans = 0;
$LogicalReads = 0;
$PhysicalReads = 0;
for ($i = 0; $i -lt $QueryStats.Count; $i++) {
$QueryStats[$i] -match $TimingRegex | Out-Null;
if ($QueryStats[$i] -like "*SQL Server parse and compile time*") {
$ParseCPUTimeTotal += $Matches[1];
$ParseElapsedTimeTotal += $Matches[2];
}
if ($QueryStats[$i] -like "*SQL Server Execution Times*") {
$ExecuteCPUTimeTotal += $Matches[1];
$ExecuteElapsedTimeTotal += $Matches[2];
}
if ($QueryStats[$i] -match $IORegex) {
$Scans += $Matches[1];
$LogicalReads += $Matches[2];
$PhysicalReads += $Matches[3];
}
}
$QueryTimes = [PSCustomObject]@{
"Parsing CPU time (ms)" = $ParseCPUTimeTotal;
"Parsing elapsed time (ms)" = $ParseElapsedTimeTotal;
"Execution CPU time (ms)" = $ExecuteCPUTimeTotal;
"Execution elapsed time (ms)" = $ExecuteElapsedTimeTotal;
"Scans" = $Scans;
"Logical Reads" = $LogicalReads;
"PhysicalReads" = $PhysicalReads;
}
$QueryTimes
The output:
Parsing CPU time (ms) : 0
Parsing elapsed time (ms) : 0
Execution CPU time (ms) : 0
Execution elapsed time (ms) : 10
Scans : 92
Logical Reads : 869
PhysicalReads : 0
This got formatted as a list by default due to the width.
Wait, Did You Just…
…create a poor imitation of StatisticsParser.com in PowerShell? Sure did! But I can extend this some more, if I want to.
- Wrap it up in a function
- Use it in automation
- Create a collection of queries/stored procedures and loop over them to collect the metrics in one go
- Pass the output to some other piece of PowerShell as part of a larger process
There’s a little cleanup I need to do on this to make it ready for use at the office, but hopefully I’ve answered DrData’s question.
