{"id":972,"date":"2018-12-13T09:15:36","date_gmt":"2018-12-13T17:15:36","guid":{"rendered":"http:\/\/3.209.169.194\/blogs\/erin\/?p=972"},"modified":"2020-05-01T08:09:25","modified_gmt":"2020-05-01T15:09:25","slug":"slowest-query-in-a-stored-procedure","status":"publish","type":"post","link":"https:\/\/www.sqlskills.com\/blogs\/erin\/slowest-query-in-a-stored-procedure\/","title":{"rendered":"Finding the Slowest Query in a Stored Procedure"},"content":{"rendered":"<p><em>This post, <a href=\"https:\/\/www.pass.org\/Community\/PASSBlog\/tabid\/1476\/entryid\/898\/Finding-the-Slowest-Query-in-a-Stored-Procedure.aspx\">Finding the Slowest Query in a Stored Procedure<\/a>, originally appeared on the PASS website.\u00a0 It has been re-posted here with permission.<\/em><\/p>\n<p>Figuring out exactly what causes slow performance for a stored procedure can sometimes feel like trying to unravel a ball of Clark Griswold\u2019s Christmas lights.\u00a0 It\u2019s not uncommon to see procedures with hundreds, even thousands of lines of code.\u00a0 You may have been told which stored procedure runs slow by a user or manager, or you might have found it by looking in SQL Server DMVs.\u00a0 Either way, once you have detected the offending procedure, where do you start?<\/p>\n<p>If you\u2019re running SQL Server 2016, one option is Query Store.\u00a0 Query Store captures individual queries, but it also captures the object_id, so you can find all the queries that are associated with an object to determine which ones are problematic.<\/p>\n<p><strong>Setup<\/strong><\/p>\n<p>We\u2019ll work with a restored copy of the WideWorldImporters database, which you can download from <a href=\"https:\/\/github.com\/Microsoft\/sql-server-samples\/tree\/master\/samples\/databases\/wide-world-importers\">GitHub<\/a>.<\/p>\n<p>First, since this is a demo database, we will enable Query Store and clear out any historical information:<\/p>\n<pre class=\"brush: sql; title: ; notranslate\" title=\"\">\r\nALTER DATABASE &#x5B;WideWorldImporters]\r\n     SET QUERY_STORE = ON;\r\nGO\r\n\r\nALTER DATABASE &#x5B;WideWorldImporters]\r\n     SET QUERY_STORE (\r\n     OPERATION_MODE=READ_WRITE,\r\n     INTERVAL_LENGTH_MINUTES = 10\r\n     );\r\nGO\r\n\r\n\/*\r\nDo not run in a Production database unless you want\r\nto remove all Query Store data\r\n*\/\r\n\r\nALTER DATABASE &#x5B;WideWorldImporters]\r\n    SET QUERY_STORE CLEAR;\r\nGO\r\n<\/pre>\n<p>Next, we will create a very simple stored procedure that has multiple queries within.<\/p>\n<pre class=\"brush: sql; title: ; notranslate\" title=\"\">\r\nUSE &#x5B;WideWorldImporters];\r\nGO\r\n\r\nDROP PROCEDURE IF EXISTS &#x5B;Sales].&#x5B;usp_GetCustomerDetail];\r\nGO\r\n\r\nCREATE PROCEDURE &#x5B;Sales].&#x5B;usp_GetCustomerDetail]\r\n     @CustomerName NVARCHAR(100)\r\nAS\r\n\r\nCREATE TABLE #CustomerList (\r\n     &#x5B;RowID] INT IDENTITY (1,1),\r\n     &#x5B;CustomerID] INT,\r\n     &#x5B;CustomerName] NVARCHAR (100)\r\n     );\r\n\r\nINSERT INTO #CustomerList (\r\n     &#x5B;CustomerID],\r\n     &#x5B;CustomerName]\r\n     )\r\nSELECT\r\n     &#x5B;CustomerID],\r\n     &#x5B;CustomerName]\r\nFROM &#x5B;Sales].&#x5B;Customers]\r\nWHERE &#x5B;CustomerName] LIKE @CustomerName\r\nUNION\r\nSELECT\r\n     &#x5B;CustomerID],\r\n     &#x5B;CustomerName]\r\nFROM &#x5B;Sales].&#x5B;Customers_Archive]\r\nWHERE &#x5B;CustomerName] LIKE @CustomerName;\r\n\r\nSELECT\r\n     &#x5B;o].&#x5B;CustomerID],\r\n     &#x5B;o].&#x5B;OrderID],\r\n     &#x5B;il].&#x5B;InvoiceLineID],\r\n     &#x5B;o].&#x5B;OrderDate],\r\n     &#x5B;i].&#x5B;InvoiceDate],\r\n     &#x5B;ol].&#x5B;StockItemID],\r\n     &#x5B;ol].&#x5B;Quantity],\r\n     &#x5B;ol].&#x5B;UnitPrice],\r\n     &#x5B;il].&#x5B;LineProfit]\r\nINTO #CustomerOrders\r\nFROM &#x5B;Sales].&#x5B;Orders] &#x5B;o]\r\nINNER JOIN &#x5B;Sales].&#x5B;OrderLines] &#x5B;ol]\r\n     ON &#x5B;o].&#x5B;OrderID] = &#x5B;ol].&#x5B;OrderID]\r\nINNER JOIN &#x5B;Sales].&#x5B;Invoices] &#x5B;i]\r\n     ON &#x5B;o].&#x5B;OrderID] = &#x5B;i].&#x5B;OrderID]\r\nINNER JOIN &#x5B;Sales].&#x5B;InvoiceLines] &#x5B;il]\r\n     ON &#x5B;i].&#x5B;InvoiceID] =\u00a0 &#x5B;il].&#x5B;InvoiceID]\r\n     AND &#x5B;il].&#x5B;StockItemID] = &#x5B;ol].&#x5B;StockItemID]\r\n     AND &#x5B;il].&#x5B;Quantity] = &#x5B;ol].&#x5B;Quantity]\r\n     AND &#x5B;il].&#x5B;UnitPrice] = &#x5B;ol].&#x5B;UnitPrice]\r\nWHERE &#x5B;o].&#x5B;CustomerID] IN (SELECT &#x5B;CustomerID] FROM #CustomerList);\r\n\r\nSELECT\r\n     &#x5B;cl].&#x5B;CustomerName],\r\n     &#x5B;si].&#x5B;StockItemName],\r\n     SUM(&#x5B;co].&#x5B;Quantity]) AS &#x5B;QtyPurchased],\r\n     SUM(&#x5B;co].&#x5B;Quantity]*&#x5B;co].&#x5B;UnitPrice]) AS &#x5B;TotalCost],\r\n     &#x5B;co].&#x5B;LineProfit],\r\n     &#x5B;co].&#x5B;OrderDate],\r\n     DATEDIFF(DAY,&#x5B;co].&#x5B;OrderDate],&#x5B;co].&#x5B;InvoiceDate]) AS &#x5B;DaystoInvoice]\r\nFROM #CustomerOrders &#x5B;co]\r\nINNER JOIN #CustomerList &#x5B;cl]\r\n     ON &#x5B;co].&#x5B;CustomerID] = &#x5B;cl].&#x5B;CustomerID]\r\nINNER JOIN &#x5B;Warehouse].&#x5B;StockItems] &#x5B;si]\r\n     ON &#x5B;co].&#x5B;StockItemID] = &#x5B;si].&#x5B;StockItemID]\r\nGROUPBY &#x5B;cl].&#x5B;CustomerName], &#x5B;si].&#x5B;StockItemName],&#x5B;co].&#x5B;InvoiceLineID],\r\n     &#x5B;co].&#x5B;LineProfit], &#x5B;co].&#x5B;OrderDate], DATEDIFF(DAY,&#x5B;co].&#x5B;OrderDate],&#x5B;co].&#x5B;InvoiceDate])\r\nORDER BY &#x5B;co].&#x5B;OrderDate];\r\nGO\r\n<\/pre>\n<p><strong>Viewing the Data<\/strong><\/p>\n<p>With the stored procedure created, we can now execute it with different input parameters:<\/p>\n<pre class=\"brush: sql; title: ; notranslate\" title=\"\">\r\nEXEC &#x5B;Sales].&#x5B;usp_GetCustomerDetail] N'Alvin Bollinger';\r\nGO 10\r\nEXEC &#x5B;Sales].&#x5B;usp_GetCustomerDetail] N'Tami Braggs';\r\nGO 10\r\nEXEC &#x5B;Sales].&#x5B;usp_GetCustomerDetail] N'Logan Dixon';\r\nGO 10\r\nEXEC &#x5B;Sales].&#x5B;usp_GetCustomerDetail] N'Tara Kotadia';\r\nGO 10\r\n<\/pre>\n<p>If we use the Query Store Top Resource Consuming Queries report within Management Studio, we can see what individual queries have been executed:<\/p>\n<figure id=\"attachment_973\" aria-describedby=\"caption-attachment-973\" style=\"width: 900px\" class=\"wp-caption aligncenter\"><a href=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/1_TopResReport.jpg\"><img fetchpriority=\"high\" decoding=\"async\" class=\"wp-image-973\" src=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/1_TopResReport-1024x619.jpg\" alt=\"Top Resource Consuming Queries\" width=\"900\" height=\"544\" srcset=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/1_TopResReport-1024x619.jpg 1024w, https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/1_TopResReport-300x181.jpg 300w, https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/1_TopResReport-900x544.jpg 900w\" sizes=\"(max-width: 900px) 100vw, 900px\" \/><\/a><figcaption id=\"caption-attachment-973\" class=\"wp-caption-text\">Top Resource Consuming Queries Report<\/figcaption><\/figure>\n<p>In this example, the queries for our stored procedure are quite evident \u2013 but we don\u2019t have much of a workload.\u00a0 In a production system, all the queries from a stored procedure probably won\u2019t appear in this view. It will likely be necessary to use T-SQL to find all the queries for a stored procedure, which currently has no built-in report to find all queries for a given stored procedure.\u00a0 Using the query below, we can list all queries captured by Query Store for the usp_GetCustomerDetail procedure:<\/p>\n<pre class=\"brush: sql; title: ; notranslate\" title=\"\">\r\nSELECT\r\n     &#x5B;qsq].&#x5B;query_id],\r\n     &#x5B;qsp].&#x5B;plan_id],\r\n     &#x5B;qsq].&#x5B;object_id],\r\n     &#x5B;qst].&#x5B;query_sql_text],\r\n     ConvertedPlan = TRY_CONVERT(XML, &#x5B;qsp].&#x5B;query_plan])\r\nFROM &#x5B;sys].&#x5B;query_store_query] &#x5B;qsq]\r\nJOIN &#x5B;sys].&#x5B;query_store_query_text] &#x5B;qst]\r\n     ON &#x5B;qsq].&#x5B;query_text_id] = &#x5B;qst].&#x5B;query_text_id]\r\nJOIN &#x5B;sys].&#x5B;query_store_plan] &#x5B;qsp]\r\n     ON &#x5B;qsq].&#x5B;query_id] = &#x5B;qsp].&#x5B;query_id]\r\nWHERE &#x5B;qsq].&#x5B;object_id] = OBJECT_ID(N'Sales.usp_GetCustomerDetail');\r\nGO\r\n<\/pre>\n<figure id=\"attachment_974\" aria-describedby=\"caption-attachment-974\" style=\"width: 906px\" class=\"wp-caption aligncenter\"><a href=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/2_query1output.jpg\"><img decoding=\"async\" class=\"wp-image-974\" src=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/2_query1output-1024x86.jpg\" alt=\"All queries for usp_GetCustomerDetail\" width=\"906\" height=\"76\" srcset=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/2_query1output-1024x86.jpg 1024w, https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/2_query1output-300x25.jpg 300w, https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/2_query1output-900x76.jpg 900w, https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/2_query1output.jpg 1800w\" sizes=\"(max-width: 906px) 100vw, 906px\" \/><\/a><figcaption id=\"caption-attachment-974\" class=\"wp-caption-text\">All queries for usp_GetCustomerDetail<\/figcaption><\/figure>\n<p>This confirms which queries are part of the procedure \u2013 but if we are troubleshooting performance, we are really interested in execution statistics.\u00a0 We can expand this query slightly to get the data we want:<\/p>\n<pre class=\"brush: sql; title: ; notranslate\" title=\"\">\r\nSELECT\r\n     &#x5B;qsq].&#x5B;query_id],\r\n     &#x5B;qsp].&#x5B;plan_id],\r\n     &#x5B;qsq].&#x5B;object_id],\r\n     &#x5B;rs].&#x5B;runtime_stats_interval_id],\r\n     &#x5B;rsi].&#x5B;start_time],\r\n     &#x5B;rsi].&#x5B;end_time],\r\n     &#x5B;rs].&#x5B;count_executions],\r\n     &#x5B;rs].&#x5B;avg_duration],\r\n     &#x5B;rs].&#x5B;avg_cpu_time],\r\n     &#x5B;rs].&#x5B;avg_logical_io_reads],\r\n     &#x5B;rs].&#x5B;avg_rowcount],\r\n     &#x5B;qst].&#x5B;query_sql_text],\r\n     ConvertedPlan = TRY_CONVERT(XML, &#x5B;qsp].&#x5B;query_plan])\r\nFROM &#x5B;sys].&#x5B;query_store_query] &#x5B;qsq]\r\nJOIN &#x5B;sys].&#x5B;query_store_query_text] &#x5B;qst]\r\n     ON &#x5B;qsq].&#x5B;query_text_id] = &#x5B;qst].&#x5B;query_text_id]\r\nJOIN &#x5B;sys].&#x5B;query_store_plan] &#x5B;qsp]\r\n     ON &#x5B;qsq].&#x5B;query_id] = &#x5B;qsp].&#x5B;query_id]\r\nJOIN &#x5B;sys].&#x5B;query_store_runtime_stats] &#x5B;rs]\r\n     ON &#x5B;qsp].&#x5B;plan_id] = &#x5B;rs].&#x5B;plan_id]\r\nJOIN &#x5B;sys].&#x5B;query_store_runtime_stats_interval] &#x5B;rsi]\r\n     ON &#x5B;rs].&#x5B;runtime_stats_interval_id] = &#x5B;rsi].&#x5B;runtime_stats_interval_id]\r\nWHERE &#x5B;qsq].&#x5B;object_id] = OBJECT_ID(N'Sales.usp_GetCustomerDetail')\r\n     AND &#x5B;rs].&#x5B;last_execution_time] &gt; DATEADD(HOUR, -1, GETUTCDATE())\r\n     AND &#x5B;rs].&#x5B;execution_type] = 0\r\nORDER BY &#x5B;qsq].&#x5B;query_id], &#x5B;qsp].&#x5B;plan_id], &#x5B;rs].&#x5B;runtime_stats_interval_id];\r\nGO\r\n<\/pre>\n<figure id=\"attachment_975\" aria-describedby=\"caption-attachment-975\" style=\"width: 900px\" class=\"wp-caption aligncenter\"><a href=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/3_query2output.jpg\"><img decoding=\"async\" class=\"wp-image-975\" src=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/3_query2output-1024x74.jpg\" alt=\"Runtime statistics for usp_GetCustomerDetail\" width=\"900\" height=\"65\" srcset=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/3_query2output-1024x74.jpg 1024w, https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/3_query2output-300x22.jpg 300w, https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/3_query2output-900x65.jpg 900w\" sizes=\"(max-width: 900px) 100vw, 900px\" \/><\/a><figcaption id=\"caption-attachment-975\" class=\"wp-caption-text\">Runtime statistics for usp_GetCustomerDetail<\/figcaption><\/figure>\n<p>We\u2019ve only retrieved CPU, duration, and IO metrics in this query \u2013 much more information is available in Query Store depending on what you\u2019re interested in seeing, or the problem you are trying to solve.\u00a0 A quick review of the duration and CPU columns helps us identify the second query in the stored procedure as the one that takes the longest to execute.<\/p>\n<p>There are a few important items worth noting about the query we ran, and its output:<\/p>\n<p>1. We restricted the runtime statistics to only those from the last hour with this predicate:<br \/>\n[rs].[last_execution_time] &gt; DATEADD(HOUR, -1, GETUTCDATE())<\/p>\n<p>2. We restricted the output to show only successful executions with this predicate:<br \/>\n[rs].[execution_type] = 0<\/p>\n<p>3.\u00a0\u00a0Runtime statistics are aggregated across the collection interval, which is set with the INTERVAL_LENGTH_MINUTES option.\u00a0 For this demo, the interval was set to 10 minutes, a value that\u2019s low for a production environment, and we\u2019re only seeing data for <em>one <\/em>10-minute interval (19:30 to 19:40 on 2018-11-28) because we\u2019ve only run our set of queries one time.<\/p>\n<p><em>*If you\u2019re not familiar with Query Store settings and considerations around them, check out my Query Store Settings <a href=\"https:\/\/www.sqlskills.com\/blogs\/erin\/query-store-settings\/\">post<\/a>.<\/em><\/p>\n<p>4.\u00a0\u00a0The statistics represent the average CPU, duration, logical I\/O, etc. for a query\u2019s plan, based on how many times the query was executed in that interval (count_executions).\u00a0 Minimum, maximum, and standard deviation numbers for each counter are also calculated and can be useful in finding plans with high variability.<\/p>\n<p>From here, we can drill further into this specific query using the Query Store Tracked Queries report and the query_id (2).<\/p>\n<figure id=\"attachment_976\" aria-describedby=\"caption-attachment-976\" style=\"width: 900px\" class=\"wp-caption aligncenter\"><a href=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/4_TrackedQueries.jpg\"><img loading=\"lazy\" decoding=\"async\" class=\"wp-image-976\" src=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/4_TrackedQueries-1024x619.jpg\" alt=\"Tracked Queries Report for query_id 2\" width=\"900\" height=\"544\" srcset=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/4_TrackedQueries-1024x619.jpg 1024w, https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/4_TrackedQueries-300x181.jpg 300w, https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/4_TrackedQueries-900x544.jpg 900w\" sizes=\"(max-width: 900px) 100vw, 900px\" \/><\/a><figcaption id=\"caption-attachment-976\" class=\"wp-caption-text\">Tracked Queries Report for query_id 2<\/figcaption><\/figure>\n<p>Again, we\u2019ve only executed the stored procedure 40 times in total, so while it\u2019s great to see this query\u2019s plan and see that we have a missing index recommendation, this data isn\u2019t that interesting compared to what we might see in a production environment.\u00a0 We can use a simple loop to run the stored procedure repeatedly with different Customer Names, and let that run for a bit to generate some data:<\/p>\n<pre class=\"brush: sql; title: ; notranslate\" title=\"\">\r\nDECLARE @CustomerID INT = 801\r\nDECLARE @CustomerName NVARCHAR(100)\r\n\r\nWHILE 1=1\r\nBEGIN\r\n\r\n     SELECT @CustomerName = SUBSTRING(&#x5B;CustomerName], 1, 10) + '%'\r\n     FROM &#x5B;Sales].&#x5B;Customers]\r\n     WHERE &#x5B;CustomerID] = @CustomerID;\r\n\r\n     EXEC &#x5B;Sales].&#x5B;usp_GetCustomerDetail] @CustomerName;\r\n\r\n     IF @CustomerID &lt; 1092\r\n     BEGIN\r\n          SET @CustomerID = @CustomerID + 1\r\n     END\r\n     ELSE\r\n     BEGIN\r\n          SET @CustomerID = 801\r\n     END\r\n\r\nEND\r\n<\/pre>\n<p>Now if we look at our execution statistics, you will see we have more intervals of data (noted by the start_time and end_time, and the respective runtime_stats_interval_id).\u00a0 In addition, you\u2019ll note that query_id 3 has three plans (plan_ids 3, 16, and 18):<\/p>\n<figure id=\"attachment_977\" aria-describedby=\"caption-attachment-977\" style=\"width: 900px\" class=\"wp-caption aligncenter\"><a href=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/5_query2output_aftermoreexecutions.jpg\"><img loading=\"lazy\" decoding=\"async\" class=\"wp-image-977\" src=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/5_query2output_aftermoreexecutions-1024x187.jpg\" alt=\"Runtime Statistics for usp_GetCustomerDetail after additional executions\" width=\"900\" height=\"164\" srcset=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/5_query2output_aftermoreexecutions-1024x187.jpg 1024w, https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/5_query2output_aftermoreexecutions-300x55.jpg 300w, https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/5_query2output_aftermoreexecutions-900x164.jpg 900w\" sizes=\"(max-width: 900px) 100vw, 900px\" \/><\/a><figcaption id=\"caption-attachment-977\" class=\"wp-caption-text\">Runtime Statistics for usp_GetCustomerDetail after additional executions<\/figcaption><\/figure>\n<p>Looking at query performance across time is not that easy in the grid output.\u00a0 If we look at any individual query again in the Tracked Queries report for a 30-minute window, we get a much better view of the data:<\/p>\n<figure id=\"attachment_978\" aria-describedby=\"caption-attachment-978\" style=\"width: 900px\" class=\"wp-caption aligncenter\"><a href=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/6_TrackedQueries_aftermoreexecutions.jpg\"><img loading=\"lazy\" decoding=\"async\" class=\"wp-image-978\" src=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/6_TrackedQueries_aftermoreexecutions-1024x619.jpg\" alt=\"Tracked Queries Report for query_id 3\" width=\"900\" height=\"544\" srcset=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/6_TrackedQueries_aftermoreexecutions-1024x619.jpg 1024w, https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/6_TrackedQueries_aftermoreexecutions-300x181.jpg 300w, https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/6_TrackedQueries_aftermoreexecutions-900x544.jpg 900w\" sizes=\"(max-width: 900px) 100vw, 900px\" \/><\/a><figcaption id=\"caption-attachment-978\" class=\"wp-caption-text\">Tracked Queries Report for query_id 3<\/figcaption><\/figure>\n<p>Important points about this output:<\/p>\n<p>1. This is query_id 3, which has three different plans, which are represented by the different plan_id values on the right, and different colors on the graph.<\/p>\n<p>2.\u00a0\u00a0The circles represent the average values for successful execution.\u00a0 The squares represent canceled executions (which we excluded in our query).\u00a0 If you see a triangle, that means an error in the execution.<\/p>\n<p>3.\u00a0\u00a0Clicking on the different plan_id values displays the corresponding query plan in the bottom window.\u00a0 Hold down the SHIFT key to select two plan_id values, then use the ComparePlans button above to open a new window and see both plans side-by-side.<\/p>\n<p>Even though this view allows us to trend individual query performance over time, we don\u2019t get a good sense of overall query performance relative to <em>other queries<\/em> in the stored procedure. \u00a0We have to go back to T-SQL for that, and for this example, we\u2019ll aggregate our metrics based on the query_id and the plan\u00ad_id, as a query can have multiple plans and they may have wildly different performance characteristics.<\/p>\n<pre class=\"brush: sql; title: ; notranslate\" title=\"\">\r\nSELECT\r\n     &#x5B;qsq].&#x5B;query_id],\r\n     &#x5B;qsp].&#x5B;plan_id],\r\n     OBJECT_NAME(&#x5B;qsq].&#x5B;object_id])AS &#x5B;ObjectName],\r\n     SUM(&#x5B;rs].&#x5B;count_executions]) AS &#x5B;TotalExecutions],\r\n     SUM(&#x5B;rs].&#x5B;avg_duration]) \/ SUM(&#x5B;rs].&#x5B;count_executions]) AS &#x5B;Avg_Duration],\r\n     SUM(&#x5B;rs].&#x5B;avg_cpu_time]) \/ SUM(&#x5B;rs].&#x5B;count_executions]) AS &#x5B;Avg_CPU],\r\n     SUM(&#x5B;rs].&#x5B;avg_logical_io_reads]) \/ SUM(&#x5B;rs].&#x5B;count_executions]) AS &#x5B;Avg_LogicalReads],\r\n     MIN(&#x5B;qst].&#x5B;query_sql_text]) AS&#x5B;Query]\r\nFROM &#x5B;sys].&#x5B;query_store_query] &#x5B;qsq]\r\nJOIN &#x5B;sys].&#x5B;query_store_query_text] &#x5B;qst]\r\n     ON &#x5B;qsq].&#x5B;query_text_id] = &#x5B;qst].&#x5B;query_text_id]\r\nJOIN &#x5B;sys].&#x5B;query_store_plan] &#x5B;qsp]\r\n     ON &#x5B;qsq].&#x5B;query_id] = &#x5B;qsp].&#x5B;query_id]\r\nJOIN &#x5B;sys].&#x5B;query_store_runtime_stats] &#x5B;rs]\r\n     ON &#x5B;qsp].&#x5B;plan_id] = &#x5B;rs].&#x5B;plan_id]\r\nJOIN &#x5B;sys].&#x5B;query_store_runtime_stats_interval] &#x5B;rsi]\r\n     ON &#x5B;rs].&#x5B;runtime_stats_interval_id] = &#x5B;rsi].&#x5B;runtime_stats_interval_id]\r\nWHERE &#x5B;qsq].&#x5B;object_id] = OBJECT_ID(N'Sales.usp_GetCustomerDetail')\r\n     AND &#x5B;rs].&#x5B;last_execution_time] &gt; DATEADD(HOUR, -1, GETUTCDATE())\r\n     AND &#x5B;rs].&#x5B;execution_type] = 0\r\nGROUP BY &#x5B;qsq].&#x5B;query_id], &#x5B;qsp].&#x5B;plan_id], OBJECT_NAME(&#x5B;qsq].&#x5B;object_id])\r\nORDER BY AVG(&#x5B;rs].&#x5B;avg_cpu_time]) DESC;\r\nGO\r\n<\/pre>\n<p>The data is ordered by avg_cpu_time descending, so the worst performing query in terms of CPU is listed first.\u00a0 You can change the order based on what is of interest to you, but you\u2019ll notice that query_id 2 is still our worst offender.<\/p>\n<figure id=\"attachment_979\" aria-describedby=\"caption-attachment-979\" style=\"width: 900px\" class=\"wp-caption aligncenter\"><a href=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/7_averaged_outupt.jpg\"><img loading=\"lazy\" decoding=\"async\" class=\"wp-image-979\" src=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/7_averaged_outupt-1024x143.jpg\" alt=\"Averaged runtime statistics by query for usp_GetCustomerDetail\" width=\"900\" height=\"125\" srcset=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/7_averaged_outupt-1024x143.jpg 1024w, https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/7_averaged_outupt-300x42.jpg 300w, https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/7_averaged_outupt-900x125.jpg 900w, https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/7_averaged_outupt.jpg 1480w\" sizes=\"(max-width: 900px) 100vw, 900px\" \/><\/a><figcaption id=\"caption-attachment-979\" class=\"wp-caption-text\">Averaged runtime statistics by query for usp_GetCustomerDetail<\/figcaption><\/figure>\n<p><strong>Conclusion<\/strong><\/p>\n<p>There are multiple sources of query performance data within SQL Server, and the DMVs and Extended Events (or Trace for those of you running SQL Server 2008R2 and below) are traditional tools used to understand how long it takes for a query to execute.\u00a0 Query Store is a new option for capturing query metrics, and it shines over both in that it\u2019s persisted in the user database (the DMVs only represent what\u2019s currently in cache, and are cleared on a restart).\u00a0 In addition, Query Store doesn\u2019t require any setup other than enabling it one time &#8211; you need to have an event session defined and running to capture query performance with Extended Events, and the same with Trace.\u00a0 Lastly, Query Store allows you to look at all the queries for a stored procedure and drill into what is not performing well either at this moment, or over time.<\/p>\n<p>T-SQL code used here can be found in its entirety on <a href=\"https:\/\/github.com\/erinstellato\/SQL-Server-Query-Store\/blob\/master\/FindSPQueries_UsingQueryStore.sql\">GitHub<\/a>.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>This post, Finding the Slowest Query in a Stored Procedure, originally appeared on the PASS website.\u00a0 It has been re-posted here with permission. Figuring out exactly what causes slow performance for a stored procedure can sometimes feel like trying to unravel a ball of Clark Griswold\u2019s Christmas lights.\u00a0 It\u2019s not uncommon to see procedures with [&hellip;]<\/p>\n","protected":false},"author":7,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[15,46],"tags":[],"yoast_head":"<!-- This site is optimized with the Yoast SEO plugin v21.9.1 - https:\/\/yoast.com\/wordpress\/plugins\/seo\/ -->\n<title>Finding the Slowest Query in a Stored Procedure - Erin Stellato<\/title>\n<meta name=\"description\" content=\"Have you ever wondered how to find the slowest query in a stored procedure? With Query Store, it&#039;s incredibly easy, as shown in this post.\" \/>\n<meta name=\"robots\" content=\"index, follow, max-snippet:-1, max-image-preview:large, max-video-preview:-1\" \/>\n<link rel=\"canonical\" href=\"https:\/\/www.sqlskills.com\/blogs\/erin\/slowest-query-in-a-stored-procedure\/\" \/>\n<meta property=\"og:locale\" content=\"en_US\" \/>\n<meta property=\"og:type\" content=\"article\" \/>\n<meta property=\"og:title\" content=\"Finding the Slowest Query in a Stored Procedure - Erin Stellato\" \/>\n<meta property=\"og:description\" content=\"Have you ever wondered how to find the slowest query in a stored procedure? With Query Store, it&#039;s incredibly easy, as shown in this post.\" \/>\n<meta property=\"og:url\" content=\"https:\/\/www.sqlskills.com\/blogs\/erin\/slowest-query-in-a-stored-procedure\/\" \/>\n<meta property=\"og:site_name\" content=\"Erin Stellato\" \/>\n<meta property=\"article:published_time\" content=\"2018-12-13T17:15:36+00:00\" \/>\n<meta property=\"article:modified_time\" content=\"2020-05-01T15:09:25+00:00\" \/>\n<meta property=\"og:image\" content=\"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/1_TopResReport-1024x619.jpg\" \/>\n<meta name=\"author\" content=\"Erin Stellato\" \/>\n<meta name=\"twitter:label1\" content=\"Written by\" \/>\n\t<meta name=\"twitter:data1\" content=\"Erin Stellato\" \/>\n\t<meta name=\"twitter:label2\" content=\"Est. reading time\" \/>\n\t<meta name=\"twitter:data2\" content=\"10 minutes\" \/>\n<script type=\"application\/ld+json\" class=\"yoast-schema-graph\">{\"@context\":\"https:\/\/schema.org\",\"@graph\":[{\"@type\":\"WebPage\",\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/erin\/slowest-query-in-a-stored-procedure\/\",\"url\":\"https:\/\/www.sqlskills.com\/blogs\/erin\/slowest-query-in-a-stored-procedure\/\",\"name\":\"Finding the Slowest Query in a Stored Procedure - Erin Stellato\",\"isPartOf\":{\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/erin\/#website\"},\"datePublished\":\"2018-12-13T17:15:36+00:00\",\"dateModified\":\"2020-05-01T15:09:25+00:00\",\"author\":{\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/erin\/#\/schema\/person\/76170223ffffa1df03fd9be5b66cb158\"},\"description\":\"Have you ever wondered how to find the slowest query in a stored procedure? With Query Store, it's incredibly easy, as shown in this post.\",\"breadcrumb\":{\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/erin\/slowest-query-in-a-stored-procedure\/#breadcrumb\"},\"inLanguage\":\"en-US\",\"potentialAction\":[{\"@type\":\"ReadAction\",\"target\":[\"https:\/\/www.sqlskills.com\/blogs\/erin\/slowest-query-in-a-stored-procedure\/\"]}]},{\"@type\":\"BreadcrumbList\",\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/erin\/slowest-query-in-a-stored-procedure\/#breadcrumb\",\"itemListElement\":[{\"@type\":\"ListItem\",\"position\":1,\"name\":\"Home\",\"item\":\"https:\/\/www.sqlskills.com\/blogs\/erin\/\"},{\"@type\":\"ListItem\",\"position\":2,\"name\":\"Finding the Slowest Query in a Stored Procedure\"}]},{\"@type\":\"WebSite\",\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/erin\/#website\",\"url\":\"https:\/\/www.sqlskills.com\/blogs\/erin\/\",\"name\":\"Erin Stellato\",\"description\":\"The SQL Sequel\",\"potentialAction\":[{\"@type\":\"SearchAction\",\"target\":{\"@type\":\"EntryPoint\",\"urlTemplate\":\"https:\/\/www.sqlskills.com\/blogs\/erin\/?s={search_term_string}\"},\"query-input\":\"required name=search_term_string\"}],\"inLanguage\":\"en-US\"},{\"@type\":\"Person\",\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/erin\/#\/schema\/person\/76170223ffffa1df03fd9be5b66cb158\",\"name\":\"Erin Stellato\",\"image\":{\"@type\":\"ImageObject\",\"inLanguage\":\"en-US\",\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/erin\/#\/schema\/person\/image\/\",\"url\":\"https:\/\/secure.gravatar.com\/avatar\/0c8b485bd54ea26b57e99f79b525f409?s=96&d=mm&r=g\",\"contentUrl\":\"https:\/\/secure.gravatar.com\/avatar\/0c8b485bd54ea26b57e99f79b525f409?s=96&d=mm&r=g\",\"caption\":\"Erin Stellato\"},\"sameAs\":[\"http:\/\/3.209.169.194\/blogs\/erin\"],\"url\":\"https:\/\/www.sqlskills.com\/blogs\/erin\/author\/erin\/\"}]}<\/script>\n<!-- \/ Yoast SEO plugin. -->","yoast_head_json":{"title":"Finding the Slowest Query in a Stored Procedure - Erin Stellato","description":"Have you ever wondered how to find the slowest query in a stored procedure? With Query Store, it's incredibly easy, as shown in this post.","robots":{"index":"index","follow":"follow","max-snippet":"max-snippet:-1","max-image-preview":"max-image-preview:large","max-video-preview":"max-video-preview:-1"},"canonical":"https:\/\/www.sqlskills.com\/blogs\/erin\/slowest-query-in-a-stored-procedure\/","og_locale":"en_US","og_type":"article","og_title":"Finding the Slowest Query in a Stored Procedure - Erin Stellato","og_description":"Have you ever wondered how to find the slowest query in a stored procedure? With Query Store, it's incredibly easy, as shown in this post.","og_url":"https:\/\/www.sqlskills.com\/blogs\/erin\/slowest-query-in-a-stored-procedure\/","og_site_name":"Erin Stellato","article_published_time":"2018-12-13T17:15:36+00:00","article_modified_time":"2020-05-01T15:09:25+00:00","og_image":[{"url":"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-content\/uploads\/2018\/12\/1_TopResReport-1024x619.jpg"}],"author":"Erin Stellato","twitter_misc":{"Written by":"Erin Stellato","Est. reading time":"10 minutes"},"schema":{"@context":"https:\/\/schema.org","@graph":[{"@type":"WebPage","@id":"https:\/\/www.sqlskills.com\/blogs\/erin\/slowest-query-in-a-stored-procedure\/","url":"https:\/\/www.sqlskills.com\/blogs\/erin\/slowest-query-in-a-stored-procedure\/","name":"Finding the Slowest Query in a Stored Procedure - Erin Stellato","isPartOf":{"@id":"https:\/\/www.sqlskills.com\/blogs\/erin\/#website"},"datePublished":"2018-12-13T17:15:36+00:00","dateModified":"2020-05-01T15:09:25+00:00","author":{"@id":"https:\/\/www.sqlskills.com\/blogs\/erin\/#\/schema\/person\/76170223ffffa1df03fd9be5b66cb158"},"description":"Have you ever wondered how to find the slowest query in a stored procedure? With Query Store, it's incredibly easy, as shown in this post.","breadcrumb":{"@id":"https:\/\/www.sqlskills.com\/blogs\/erin\/slowest-query-in-a-stored-procedure\/#breadcrumb"},"inLanguage":"en-US","potentialAction":[{"@type":"ReadAction","target":["https:\/\/www.sqlskills.com\/blogs\/erin\/slowest-query-in-a-stored-procedure\/"]}]},{"@type":"BreadcrumbList","@id":"https:\/\/www.sqlskills.com\/blogs\/erin\/slowest-query-in-a-stored-procedure\/#breadcrumb","itemListElement":[{"@type":"ListItem","position":1,"name":"Home","item":"https:\/\/www.sqlskills.com\/blogs\/erin\/"},{"@type":"ListItem","position":2,"name":"Finding the Slowest Query in a Stored Procedure"}]},{"@type":"WebSite","@id":"https:\/\/www.sqlskills.com\/blogs\/erin\/#website","url":"https:\/\/www.sqlskills.com\/blogs\/erin\/","name":"Erin Stellato","description":"The SQL Sequel","potentialAction":[{"@type":"SearchAction","target":{"@type":"EntryPoint","urlTemplate":"https:\/\/www.sqlskills.com\/blogs\/erin\/?s={search_term_string}"},"query-input":"required name=search_term_string"}],"inLanguage":"en-US"},{"@type":"Person","@id":"https:\/\/www.sqlskills.com\/blogs\/erin\/#\/schema\/person\/76170223ffffa1df03fd9be5b66cb158","name":"Erin Stellato","image":{"@type":"ImageObject","inLanguage":"en-US","@id":"https:\/\/www.sqlskills.com\/blogs\/erin\/#\/schema\/person\/image\/","url":"https:\/\/secure.gravatar.com\/avatar\/0c8b485bd54ea26b57e99f79b525f409?s=96&d=mm&r=g","contentUrl":"https:\/\/secure.gravatar.com\/avatar\/0c8b485bd54ea26b57e99f79b525f409?s=96&d=mm&r=g","caption":"Erin Stellato"},"sameAs":["http:\/\/3.209.169.194\/blogs\/erin"],"url":"https:\/\/www.sqlskills.com\/blogs\/erin\/author\/erin\/"}]}},"_links":{"self":[{"href":"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-json\/wp\/v2\/posts\/972"}],"collection":[{"href":"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-json\/wp\/v2\/users\/7"}],"replies":[{"embeddable":true,"href":"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-json\/wp\/v2\/comments?post=972"}],"version-history":[{"count":0,"href":"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-json\/wp\/v2\/posts\/972\/revisions"}],"wp:attachment":[{"href":"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-json\/wp\/v2\/media?parent=972"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-json\/wp\/v2\/categories?post=972"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.sqlskills.com\/blogs\/erin\/wp-json\/wp\/v2\/tags?post=972"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}