The magic of Query Store for tracking application timeouts

If I were writing a click-baity title for an article on this, it would be "One Crazy Trick To Find Application Timeouts That Will Blow Your Mind!!!" It really is that useful. 

The bottom line is, Query Store is useful for far more than you might think, and specifically researching application timeouts.  

A system I've been working on lately has had many application timeouts, cause by the default setting (timeout after 30 seconds). The tool we were using for error tracking had some flaws, and it was very difficult to actually come up with the stored procedure name, that had the timeout. 

I had set up the Extended Event session for timeouts (on sqlserver.attention). However, potentially due to certain issues with the front end setup, the sqlserver.sql_text value was almost always blank when there was a timeout. I didn't investigate in depth, and moved on to other tasks.

But once I started spending more time on Query Store and using it more, I discovered the execution_type_desc field in query_store_runtime_stats. What does it contain?

Well, 99.9% of the time it has this string "regular". But occasionally, it contains this one "aborted". And these are your timeouts! It's so easy to find timeouts with this method that I'm surprised it's not more well known.

By using the execution_type_desc field in query_store_runtime_stats, I was able to find clusters of linked timeouts, and then dig deeper (also using query_store_runtime_stats, but that's another story) to find the root cause. 

Here's the query I frequently use, commenting out lines when necessary, to get the details I need. This will show 1 row for each QueryID and PlanID. If it's a stored procedure with many separate statements, you may want to filter on one particular QueryID or SQL text.

 SELECT   
   ObjectName = Object_Name(q.object_id)  
   ,RunTimeFirst = convert(varchar(16), rs.first_execution_time,121)  
   ,RunTimeLast = convert(varchar(16), rs.first_execution_time,121)  
   ,TotalExecutions = rs.count_executions  
   ,AverageCPU = round(rs.avg_cpu_time , 0)  
   ,AverageLogicalReads = round(rs.avg_logical_io_reads ,0)  
   ,AverageDuration = round(rs.avg_duration ,0)  
   ,q.query_id   
   ,p.plan_id   
   ,p.Is_Forced_Plan  
   ,rs.runtime_stats_id  
   ,execution_type_desc  
   ,qt.query_sql_text  
   -- Comment out unless necessary...takes a long time.   
   -- ,ExecutionPlan = CAST(p.query_plan as XML)  
 FROM sys.query_store_runtime_stats rs  
 JOIN sys.query_store_plan p   
   ON p.plan_id = rs.plan_id  
 JOIN sys.query_store_query q   
   ON q.query_id = p.query_id  
 JOIN sys.query_store_query_text qt   
   ON q.query_text_id = qt.query_text_id  
 WHERE   
   1=1 -- make it easier to comment/uncomment
   -- just show last 2 days by default  
   and first_execution_time >= dateadd(d, -2, getdate())  
   and Object_Name(q.object_id) = 'API_GetUserLearningPlanObjects'  
   and execution_type_desc = 'Aborted'  
   -- and q.query_id in (4013401)  
   -- and qt.query_sql_text like '%c.CourseID as ID%'  
 Order by RunTimeFirst desc  

Why is my transaction log growing?

I advise on the management of multiple large databases. One of them had a steadily growing transaction log.  Figuring out exactly why the log was growing was not a simple process. Here's the steps that I took to narrow down specifically which processes were causing the growth.

First, the most precise way to figure out what, specifically, is causing log growth, is through extended events. The event database_file_size_change will log all available data about the change (size, time, specifically which SQL cause the size change, etc).

If you've never used extended events before, do a little reading to learn about them first. They're insanely handy and highly recommended, but not necessarily straightforward. The below SQL will create an extended event to track the details. 

 CREATE EVENT SESSION [DB_Size_Tracking] ON SERVER   
 ADD EVENT sqlserver.database_file_size_change(  
 ACTION(sqlserver.client_app_name,  
 sqlserver.client_hostname,  
 sqlserver.database_name,  
 sqlserver.nt_username,  
 sqlserver.plan_handle,  
 sqlserver.query_hash,  
 sqlserver.query_plan_hash,  
 sqlserver.server_principal_name,  
 sqlserver.session_id,  
 sqlserver.session_nt_username,  
 sqlserver.sql_text,  
 sqlserver.username))  
 ADD TARGET package0.event_file(SET filename=N'D:\ExtendedEvents\DB_Size_Tracking.xel')  
 WITH (MAX_MEMORY=4096 KB,  
 EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,  
 MAX_DISPATCH_LATENCY=30 SECONDS,  
 MAX_EVENT_SIZE=0 KB,  
 MEMORY_PARTITION_MODE=NONE,  
 TRACK_CAUSALITY=OFF,  
 STARTUP_STATE=ON)  
 GO  

Once this extended event has been started, you can begin to see what, specifically is causing the size changes. Here's what I use to return data from the extended event session.

 If object_id('tempdb..#SizeChanges') is not null drop table tempdb..#SizeChanges  
 Select  
   -- Object_Name = n.value ('(data[@name="object_name"]/value)[1]', 'nvarchar(256)')   
   -- ,Duration = n.value ('(data[@name="duration"]/value)[1]', 'int')   
   SQLText = n.value('(action[@name="sql_text"]/value)[1]', 'nvarchar(max)')      
   ,Size_Change_KB = n.value ('(data[@name="size_change_kb"]/value)[1]', 'int')   
   ,Timestamp = convert(smalldatetime, n.value('(@timestamp)[1]', 'datetime2'))  
   ,database_name = n.value ('(data[@name="database_name"]/value)[1]', 'nvarchar(256)')   
   ,database_name_Action = n.value('(action[@name="database_name"]/value)[1]', 'nvarchar(256)')      
   ,file_name = n.value ('(data[@name="file_name"]/value)[1]', 'nvarchar(256)')   
 Into #SizeChanges  
 From (  
   Select cast(event_data as XML) as event_data  
   -- need to edit this for correct file, then UNCOMMENT  
   From sys.fn_xe_file_target_read_file('D:\ExtendedEvents\DB_Size_Tracking*.xel', null, null, null)  
   ) ed  
 Cross apply ed.event_data.nodes('event') as q(n)  
 Select * From #SizeChanges   

Once you have the temp table #SizeChanges created, you can do all kinds of queries and analysis.

In my situation, I found that a regular index maintenance job was causing the problem. Specifically, a large table with a clustered index built on a Unique Identifier field (never a good idea) was causing transaction growth, when the index was maintained. Once this was fixed, the transaction log growth was no longer a problem.

 

UPDATED! Performance tuning a stored procedure with user defined function calls in SQL Server

I had a previous post on the topic of performance tuning a stored procedure with multiple user defined function calls. I thought the method I reviewed was a pretty nifty way of getting very useful performance information. 

However, it turns out there's a much more straightforward method of getting a comprehensive  (including functions) performance picture when executing a stored procedure. 

This method (only to be used on a development server, not production) uses DBCC FREEPROCCACHE to completely clear out sys.dm_exec_procedure_stats and sys.dm_exec_function_stats. It also clears out other DMVs, so be aware of that.

Here's a sample of how it can be used. Basically, for each version of the code, you free the procedure cache, run the code, and then query sys.dm_exec_procedure_stats and sys.dm_exec_function_stats. Then, compare the two outputs. You'll get a comprehensive picture of the resource usage for each version, including functions.

  -- Run this for both versions of the stored procedure  
 DBCC FREEPROCCACHE  
 exec API_GetTiers_Old  @LocaleID= 1033, @CountryCode = 'US',@UserID = 60190667  
 -- exec API_GetTiers_New  @LocaleID= 1033, @CountryCode = 'US',@UserID = 60190667

   
 -- Get stats from functions  
 Select   
      Object_Name = Object_Name(Object_ID)  
      ,execution_count  
      ,Total_Worker_Time  
      ,Total_Logical_Reads   
	  ,Total_Elapsed_Time      
 From sys.dm_exec_function_stats  
 Union all  
 -- Get stats from procedures  
 Select   
      Object_Name = Object_Name(Object_ID)  
      ,execution_count  
      ,Total_Worker_Time  
      ,Total_Logical_Reads   
	  ,Total_Elapsed_Time      
 From sys.dm_exec_procedure_stats  
 -- Sum everything for convenience  
 Union all  
 Select 'TOTAL', null  
 , Total_Worker_Time =   
      IsNull((Select sum(Total_Worker_Time) From sys.dm_exec_function_stats ) , 0)
      + IsNull((Select sum(Total_Worker_Time) From sys.dm_exec_procedure_stats ) , 0) 
 , Total_Logical_Reads   
      = IsNull((Select sum(total_logical_reads) From sys.dm_exec_function_stats ) , 0)  
      + IsNull((Select sum(total_logical_reads) From sys.dm_exec_procedure_stats ) , 0) 
 , Total_Elapsed_Time   
      = IsNull((Select sum(Total_Elapsed_Time) From sys.dm_exec_function_stats ) , 0)  
      + IsNull((Select sum(Total_Elapsed_Time) From sys.dm_exec_procedure_stats ) , 0)
   

Tracking the total number of stored procedure executions, over time

UPDATE: Turns out there are a number of ways that this can be inaccurate. Use this as a potential pointer of what to investigate via other means, not as a final result.

******************************************* *******************************************

I had a situation recently where the performance of a particular stored procedure (previously never a resource hog), changed for the worse. It suddenly jumped to the top of the list of procedures returned by the Top Resource Consuming Queries in Query Store, in Duration, CPU, and Logical Reads. And it stayed there.

What's was going on? I started diving into the indexes, execution plan and logical reads. No big insights. Finally I started looking at the average CPU of the stored procedure, over time. This is available if only if you write SQL against the Query Store. Here's what I put together:

 SELECT   
   RunDate = convert(varchar(16), first_execution_time,121)  
   ,AverageCPU = round(rs.avg_cpu_time , 0)  
   ,AverageLogicalReads = round(rs.avg_logical_io_reads ,0)  
 FROM sys.query_store_runtime_stats rs  
 JOIN sys.query_store_plan p ON p.plan_id = rs.plan_id  
 JOIN sys.query_store_query q ON q.query_id = p.query_id  
 WHERE   
   Object_Name(q.object_id) = 'API_GetTiers'  
 ORDER BY RunDate desc  

When you'll run this, you'll notice that you have multiple rows for each day. This has to do with the Statistics Collection Interal set up in Query Store. Since you can't average an average, I just eyeballed the results for AverageCPU and AverageLogicalReads.  

And looking at the results for the past couple weeks, I saw something strange, which was—the AverageCPU and AverageLogicalReads didn't actually go up over time! I poked around a little more, and then added the count of executions. 

Bingo. It was the number of executions that had skyrocked, by about 8 times. It turns out that the api calling this stored procedure had changed, resulting in many more executions. It's a good thing I didn't waste too much time trying to optimize this stored procedure, because the first step to figure out was—why was this stored procedure suddenly called so many more times, and was it possible to avoid that?

Here's the spreadsheet, with chart, that I put together to explain the situation to the API developers. It was very helpful in showing where the problem was. 

Testing stored procedures - getting great coverage with zero external tools

I've been working on performance tuning stored procedures recently. These are stored procedure that just return data, with no data modification, mostly for reporting. Often the performance tuning isn't the hard part. The hard part is making sure that the changes that I make don't introduce bugs into the output.

Here's a process I use to make the testing processes easier for this type of procedure.

Step 1: Creating a select statement that outputs an executable script, with a random assortment of IDs

Most of the stored procedures take, as a parameter, a UserID (or some other ID field). In order to get a set of stored procedure calls with a random UserID, you can use a script like the following:

 Select Top 10  
   'exec api_GetTiers '   
   + '''' +   
   + convert(varchar(100), UserID) + ''''  
 From Users  
 Order by NEWID()  

When you run the above script, it will give you an output that is a set of calls to your target stored procedure. The NewID() function is used in order to get a random set of UserIDs for the parameter.

Step 2: Execute the stored procedure, with random UserIDs

The output of this script will look something like this:

 exec api_GetTiers '40273230'  
 exec api_GetTiers '60372087'  
 exec api_GetTiers '30128477'  
 exec api_GetTiers '60008969'  
 exec api_GetTiers '60121799'  
 exec api_GetTiers '00303810'  
 exec api_GetTiers '60466614'  
 exec api_GetTiers '60147429'  
 exec api_GetTiers '70278452'  
 exec api_GetTiers '50542343'  

Copy and paste the output into a new query window in SQL Server Management Studio, and change the output to Text mode instead of Grid Mode (right-click in the query window, click on Results To, then choose Text). 

Next, execute the set of stored procedure calls. 

Copy and paste the output (since the Results are now in text mode, it's easy to do) into a text editing tool. My tool of choice is Notepad++. 

---

The final step is to update the stored procedure that you're working on, and then follow the above procedure again. You will now have two chunks of text, one with the output of the old stored procedure and one with the output of the new stored procedure, both called with the same UserIDs. Compare the output from the old and the new versions of the stored procedure with your preferred text comparison tool (I use the Compare plugin, in Notepad++).

Any differences that show up are potential bugs.

Performance tuning a stored procedure with user defined function calls in SQL Server

UPDATE: It turns out that there are easier ways of doing this. Take a look at this post instead of following the below.

******************************************* *******************************************

Have you ever tried to do performance tuning on a stored procedure that has user defined function calls?  It can be very challenging. This is mainly because one of the of the most basic tools of performance tuning—checking the number of logical reads using Set Statistics IO—is just not accurate in this scenario. The logical reads of any user defined functions called during a stored procedure are not reported using Set Statistics IO, so you get output that doesn't reflect their true cost.  

Before I get into the details of how to work around this, let's just get this out of the way—yes, user defined functions have a very mixed reputation because of performance issues. Functions in the Select or Order By clause are likely to be okay. But functions have no place in the Where clause, and can cause huge performance issues.

Yet you may be working on a system that has hundreds of user defined functions scattered everywhere, including the Where clause, within hundreds of stored procedures. That's what I was recently faced with.

It's not possible to fix all these issues quickly, so you need to target the the worst performers, and figure out how to improve them. I use Query Store (usually using the Top Resource Consuming Queries report) to find the worst performers in general. But once you have a stored procedure targeted for performance improvement, how do you get the full performance picture if it contains user defined functions?

Here's a process you can use in order to get data that accurately reflects performance (including Logical Reads), even when there are user defined functions inside your stored procedure. The key is to use  the built-in reporting in Query Store, and not Statistics IO.

Step 1: Purge Query Store data

Make sure Query Store is turned on for your database. Information on how to do this is easy to find online. After ensuring it's turned on, click on the Purge Query Data button. (This is, of course, assuming you're not working on a production server). This will give you a blank slate in the Query Store.

Step 2: Run the stored procedure

Execute the stored procedure in a query window. This will populate the previously empty Query Store with just the performance metrics for this specific call.

Step 3: Check the Query Store: Top Resource Consuming Queries

Next, go to the Top Resource Consuming Queries report in Query Store, and open it. By default it gives you the graph output, which doesn't give you numbers. Instead, switch to the simple grid output, and copy and paste the results to a spreadsheet. I usually do this for both Logical Reads and CPU.

Now what? When I first ran through this with my stored procedure, I found that the user defined function calls in the stored procedure were actually not as big of a problem as I had suspected. Instead of focusing on user defined functions, I targetted other areas of the stored procedure and got a very substantial performance improvement. 

To validate the improvement, I ran through the same steps as above, but using the updated stored procedure. Comparing Logical Reads and CPU numbers between the old and new versions of the stored procedure gave me the results I was looking for. 

Analyzing a slow stored procedure using Query Store

I'll be honest - I've never used Query Store before in SQL Server, even though it's been out now since SQL Server 2016.

Now that I'm using it, I'm blown away at how useful it is. And the truth is that few people know how to use it well. There's not much written up on it. It takes quite some time for articles and blog posts (like this one) to appear that tell people when and how to use the new features.

Before Query Store was available, here's what I often did when I had to analyze long stored procedures for performance:

UPDATE	dbo.HotelFact
SET	SalesForceLastUpdateDate = ##SalesForce.LastUpdateDate          
FROM
    dbo.HotelFact
    INNER JOIN dbo.dimhotel  
        ON dimhotel.HotelKey = HotelFact.HotelKey
    INNER JOIN ##SalesForce
        ON ##SalesForce.SalesForceAccountNumber = dimHotel.SFAccountNumber
WHERE
    isnull(HotelFact.SalesForceLastUpdateDate,0)  <> isnull(##SalesForce.LastUpdateDate, 0)

exec MessageLog @DatabaseName, @ProcedureName , 'Info', 'Update records in HotelFact with SalesForce updates', @@Rowcount

Notice the call at the end, to MessageLog? After every significant statement, I would call it, and it logged the duration to a Message table. I'd check the Message to see what took longest.

That was a hassle. And it made the stored procedure harder to read. And of course, if the stored procedure didn't already use MessageLog, you'd have to update it.

But Query Store data blows this away. It gives you all the information you need to troubleshoot stored procedure performance at the statement level, with any metric, such as logical reads or CPU.

Say you have a stored procedure that's hundreds of lines long, and does dozens of reads and writes. And it's slow. You look at it and groan, imaging what a pain it will be to even figure out where you need to focus your attention.

No need to worry. Once you have Query Store turned on, you can analyze it in moments. This query gave me, for the specific procedure that was causing a problem, all the query plans, ordered by cpu time, for the last 24 hours.

 -- Query plan details on one object, perhaps a stored procedure that has a high duration
-- In this case, getting details on SE_SaveBuffer
SELECT qsq.query_id
	,qsp.plan_id
	,OBJECT_NAME(qsq.object_id) AS ObjectName
	,SUM(rs.count_executions) AS TotalExecutions
	,AVG(rs.avg_duration) AS Avg_Duration
	,AVG(rs.avg_cpu_time) AS Avg_CPU
	,AVG(rs.avg_logical_io_reads) AS Avg_LogicalReads
	,MIN(qst.query_sql_text) AS Query
FROM sys.query_store_query qsq
JOIN sys.query_store_query_text qst
	ON qsq.query_text_id = qst.query_text_id
JOIN sys.query_store_plan qsp
	ON qsq.query_id = qsp.query_id
JOIN sys.query_store_runtime_stats rs
	ON qsp.plan_id = rs.plan_id
JOIN sys.query_store_runtime_stats_interval rsi
	ON rs.runtime_stats_interval_id = rsi.runtime_stats_interval_id
WHERE qsq.object_id = OBJECT_ID(N'dbo.SE_SaveBuffer')
	AND rs.last_execution_time > DATEADD(HOUR, - 24, GETUTCDATE())
	AND rs.execution_type = 0
GROUP BY qsq.query_id
	,qsp.plan_id
	,OBJECT_NAME(qsq.object_id)
ORDER BY
	AVG(rs.avg_cpu_time) DESC

Once I got this, I knew exactly where to look—at the top of the list, the ones that are taking the longest. This is where the analysis needs to occur. The following query will allow you to see the query plan for a specific statement. You need to update it with your plan_id.

SELECT
    ConvertedPlan = TRY_CONVERT(XML, [query_plan])
    ,*
FROM sys.query_store_plan
WHERE
    plan_id IN (1830037)

At this point in my troubleshooting, it was easy. The worst performing statement, that took most of the CPU time, had a missing index. Adding that index improved the overall performance dramatically. 

So there you have it—a new tool that can make performance troubleshooting of long-running stored procedures a piece of cake. 

I haven't gone into all the details of how to actually set up the Query Store. The Microsoft documentation is great, and I also like the articles by Erin Stellato (https://sqlperformance.com/author/erinsqlskills-com),