Sometimes, when developing SQL code, you need to run an automated test and benchmark over and over again. In this test run ‘with bits’,\u00a0 you want a lot of diagnostic information such as the CPU, \u00a0IO, \u00a0which can be saved, parsed and compared between runs. \u00a0You want the results of the SQL so you can compare that with what you expect the result to be. You also want all the diagnostic information. If you’re feeling sensible, you’ll want to do this in PowerShell, but the code is easily translated to VB or C#.<\/p>\n
You need to do this because you want to see if the code gives the results and whether it is doing it in a reasonable way with adequate performance. if it is slow, you want to know why.\u00a0 You can’t do this in SSMS if, like me, everything you do is a race against the clock.<\/p>\n
The SET STATISTICS\u00a0 options (SET STATISTICS IO<\/a> ,SET STATISTICS PROFILE <\/a>, SET STATISTICS TIME <\/b><\/a>\u00a0and SET STATISTICS XML<\/a> \u00a0are the ones you’ll want.\u00a0 They all send their data via the message stream. This is a good example of the sort of place where you need to get the contents of the message stream from SQL Server. You know, all that stuff that gets\u00a0 put in a separate pane in SSMS when you view query results via a grid. To do this in .NET you create a\u00a0 delegate, identifying the method that handles the event,\u00a0 to listen for the InfoMessage event on the SqlConnection class.\u00a0 This gets you all the info, and this would be a rather short blog were it not for the fact that it is likely that you’ll want to run a whole batch rather than a single query.\u00a0\u00a0<\/p>\n I generally don’t do more than SET STATISTICS IO<\/a> \u00a0or SET STATISTICS TIME <\/b><\/a>because you can sort out which statement the timings or IO are related to by means of deft PRINT statements (Print statements also go down the message stream, to the great bafflement of rookie Database developers). However, there are few satisfactions in life like saving all your XML execution plans to disk as you run a batch. It saves so much messing about.<\/p>\n Here is, stripped down, the whole works. You’ll just have to imagine that those separate results are being saved to disk as CSV for later analysis, and you’ll have to imagine that we can split the message string into its separate queries and even parse that data if you want. (its not as hard to do as you think, but that’s another blog post. You’ll also just have to imagine that this isn’t AdventureWorks, it’s easy if you try)<\/p>\n This gives the output (after the results which merely list the returned results as a table)<\/p>\n Sometimes, when developing SQL code, you need to run an automated test and benchmark over and over again. In this test run ‘with bits’,\u00a0 you want a lot of diagnostic information such as the CPU, \u00a0IO, \u00a0which can be saved, parsed and compared between runs. \u00a0You want the results of the SQL so you can……<\/p>\n","protected":false},"author":154613,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[2],"tags":[],"coauthors":[],"class_list":["post-6782","post","type-post","status-publish","format-standard","hentry","category-blogs"],"acf":[],"_links":{"self":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/6782","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/users\/154613"}],"replies":[{"embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/comments?post=6782"}],"version-history":[{"count":12,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/6782\/revisions"}],"predecessor-version":[{"id":67387,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/6782\/revisions\/67387"}],"wp:attachment":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/media?parent=6782"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/categories?post=6782"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/tags?post=6782"},{"taxonomy":"author","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/coauthors?post=6782"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}
\n \r\n$SQL=@'\r\nuse adventureworks\r\n \r\nSet statistics time on\r\nSet statistics io on\r\nprint 'first query'\r\nSELECT count(*) as FirstResult\r\nFROM Sales.SalesOrderDetail s\r\nINNER JOIN Production.Product p\r\n ON s.ProductID = p.ProductID;\r\n \r\nprint 'Second query'\r\nSELECT BusinessEntityID as SecondResult\r\nFROM HumanResources.Employee\r\nWHERE NationalIDNumber = '509647174';\r\n \r\nprint 'final query'\r\nSELECT count(*) as ThirdResult\r\nFROM HumanResources.Employee\r\nWHERE JobTitle LIKE 'Production%';\r\n \r\nSet statistics time off\r\nSet statistics io off\r\n \r\n'@\r\n$message =[string]''\r\n \r\n$ErrorActionPreference = \"Stop\" # nothing can be retrieved\r\n#\r\n$conn = new-Object System.Data.SqlClient.SqlConnection(\"Server=MyServer;DataBase=AdventureWorks;password=WouldntYouLikeToKnow; uid=PhilFactor\")# fill this in before you run it!\r\n$conn.Open() | out-null #open the connection\r\n$handler = [System.Data.SqlClient.SqlInfoMessageEventHandler] {param($sender, $event) $global:message = \"$($message)`n $($event.Message)\" };\r\n$conn.add_InfoMessage($handler);\r\n$conn.FireInfoMessageEventOnUserErrors=$true\r\n$cmd = new-Object System.Data.SqlClient.SqlCommand($SQL, $conn)\r\n$rdr = $cmd.ExecuteReader()\r\ndo\r\n {\r\n $datatable = new-object System.Data.DataTable\r\n $datatable.Load($rdr)\r\n $datatable |Format-table\r\n }\r\nwhile ($rdr.IsClosed -eq $false)\r\n$message\r\n<\/pre>\n \r\n Changed database context to 'Adventureworks'.\r\n \r\n SQL Server Execution Times:\r\n CPU time = 0 ms, elapsed time = 0 ms.\r\n \r\n SQL Server Execution Times:\r\n CPU time = 0 ms, elapsed time = 0 ms.\r\n first query\r\n \r\n SQL Server Execution Times:\r\n CPU time = 0 ms, elapsed time = 0 ms.\r\n Table 'Product'. Scan count 1, logical reads 15, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.\r\n Table 'SalesOrderDetail'. Scan count 1, logical reads 276, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.\r\n \r\n SQL Server Execution Times:\r\n CPU time = 94 ms, elapsed time = 96 ms.\r\n Second query\r\n \r\n SQL Server Execution Times:\r\n CPU time = 0 ms, elapsed time = 0 ms.\r\n SQL Server parse and compile time:\r\n CPU time = 0 ms, elapsed time = 0 ms.\r\n Table 'Employee'. Scan count 0, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.\r\n \r\n SQL Server Execution Times:\r\n CPU time = 0 ms, elapsed time = 1 ms.\r\n final query\r\n \r\n SQL Server Execution Times:\r\n CPU time = 0 ms, elapsed time = 0 ms.\r\n Table 'Employee'. Scan count 1, logical reads 9, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.\r\n \r\n SQL Server Execution Times:\r\n CPU time = 16 ms, elapsed time = 1 ms.\r\n \r\nPS C:\\Users\\Phil.Factor> \r\n<\/pre>\n","protected":false},"excerpt":{"rendered":"