Friday, September 17, 2021

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.