What It Did?
Video Summary
In this video, I delve into an intriguing aspect of SQL Server’s plan caching behavior by exploring how stored procedures that execute dynamic SQL or other stored procedures can mislead you. I demonstrate the use of a stored procedure named `PCLSub` to illustrate how sub-executions—those nested within the main execution—can accumulate significant CPU costs, making the parent stored procedure appear as if it’s doing minimal work when in reality, it’s orchestrating complex operations. Through detailed analysis using tools like `sp_BlitzCache`, I show you how to uncover these hidden costs and understand the true workload of your stored procedures, helping you identify areas for optimization more effectively.
Full Transcript
HONK HONK! I am still Erik Darling with Erik Darling Data. And I am going to continue my series of things that lie to you in cached plans. And in this one I want to talk about what happens when you use a stored procedure to execute either a dynamic SQL or other stored procedures.
That’s the sub-executions, right? You know, like it’s not the main execution, it’s sub. It’s an execution within an execution. Sometimes within an execution. It’s executions all the way down.
Alright? Alright. Cool. So, I have this stored procedure thoughtfully named PCLSub, which is PlanCashLiar underscore sub, right? Sub-executions. Not subpar or anything like that.
But I’ve gone ahead and run it ahead of time. And the output here is just to show that we looped through some code 20 times. Now, on its own, that is very unimpressive.
Anyone can write a loop. But I want to show you what happened, or what query plans look like when, in the PlanCash, when we use a stored procedure to call other stored procedures. So, again, we’re going to see this low-cost, high CPU warning.
And maybe, maybe I should have included this in that section instead. I don’t know. But this one has a little bit more going on. So, I decided to give it its own thing. But it costs zero query bucks because, really, it doesn’t do anything other than execute other stuff.
But, if we go over here a little bit further, we’ll see that for one execution, we used a total of 75 seconds of CPU time. And the same thing on average because, divided by one, anything divided by one is itself. Good.
Yeah. Alright. Good on that. And, we used a total duration of about 20, well, let’s call it about 21 seconds there. 20.7. And I can round up on that one. I can also do that math. Alright.
Pretty good. Pretty good there. But, when we look at the query plan, we can see some stuff going on. Just not anything terribly helpful. We can see that we start a while loop here.
And, depending on that, we execute a procedure or execute a different procedure. And then, occasionally, we print something out. What really sucks is if we go to look at the text of this stored procedure, it’s going to look like that. While one is less than 20, boof, do nothing.
Not very helpful at all, is it? Well, you know, I, we can look at the text of the query from over here, the actual query text. And, I’m going to do a little bit of parsing here in front of you nice people.
Let’s get the while loop down here. And, let’s show that we declare some dynamic SQL and run it over here. And, let’s take careful note that we have this comment in there for dbo.sub.
So, we know that that dynamic SQL is run from dbo.sub. There is one exec. We exec sp execute SQL.
And, here is another exec where we call another stored procedure. Good stuff, right? So, we see exactly where those other execs are. And, we see exactly what was, what we were executing within the stored procedure.
So, good for us. So, now we can go look for some things. The first thing we’re going to go look at, look for, is the stored procedure that we called within there, called sub sub. And, if we go grab sub sub, we will see that select count, or the select count that’s inside the stored procedure.
And, we can see that it executed 10 times within sub, and that it used a total of about 32 seconds. Or, let’s call it 30. Let’s continue our rounding up extravaganza.
About 33 seconds of CPU time, and about 32 seconds on average. So, over 10 executions, we used 3 point, 3 point, whatever. Look at the numbers.
Do the math, right? Come on. And, that each execution on average. My brain is broken. On average. It took 822 milliseconds for a total of about 8.2 seconds total.
So, we’ve tracked that down. Now, let’s track down that statement. Alright. So, let’s run spBlitzCache. And, let’s use a couple of the less frequently used parameters there.
Now, we can use query filter to filter down to get procs or statements. And, we can use minimum execution count to tell SQL Server to ignore code that has executed less than a certain number of times. So, we’ll do that here.
And, as long as the plan cache didn’t clear out for some weird reason, we will get two things. We will get the text of the statement from sub sub. So, we have this statement here, which is the count from there.
And, we have the dynamic SQL, which has that dbo.sub comment in it. So, we can see that that came, where we added that comment there so we would know where that query came from. And, if we look at that query over here, or look at the metadata for that query over here, we’ll see that that also ran 10 times.
That this one used about 42 seconds of CPU time, total, for about 4.2 seconds on average. And, the average and totals, you know, they will multiply cleanly by 10 as well. So, good for us there.
We have started to figure this stuff out. And, if we look at everything in the database as a whole, I mean, don’t look at it as a whole. It might be quite completely filled in.
We will have the store procedure sub. We will have one of the statements from within sub. And, then we will have the procedure that sub calls. So, let’s just focus on these top three lines here, because these should give us enough information.
Where we have the one execution of the main store procedure resulted in 10 executions a piece of those two pieces of sub code. And, if we add up the CPU from those two pieces, we will get about that 75,000 number. And, the same thing with that.
Well, the average doesn’t quite work out, because we’re still dividing by one. And, that doesn’t quite work out. It’s difficult to figure that out. But, the total duration will also add up to there. So, main lessons here are a few things going on.
One, if you use a store procedure to call Dynamic SQL or other store procedures, it will inherit the metadata of those store procedures. And, that like the runtime, the CPU duration reads, writes, all that stuff will tally up to that main calling store procedure. That can be pretty misleading, if you see a store procedure that costs nothing, but has a lot, does a lot of work internally.
And, then you have to go kind of figure out what inside that store procedure does all that work internally. Now, there are other things that can cause this too. You know, it’s not, you know, like while loops, cursors, you know, things of that nature can also contribute to this phenomenon.
But, it’s important to realize, you know, that when the sub executions push their runtime, push their metrics up to the thing that calls them. And, that can be sort of confusing when you’re looking for expensive things to tune, and you look at this store procedure, and you’re like, oh, it’s just the stuff inside of it. And, sometimes, when you look, go to, if you use the, you know, just the query, the query plan to look at the text of something, it can be truncated and it’s very unhelpful.
So, this is another case in where the plan cache can be pretty unclear about what’s going on with something. We have to dig a little bit deeper to figure out what inside of the store procedure was going wild and crazy. All right. Cool.
All right. That does it for this one. In the next video, we will talk about something brand new, too. Woohoo! Yay! We’re gonna do it all day! By it, I mean record demos. Sick. Sick son of a gun.
All right. See you in the next video. Goodbye. See you in the next video. Goodbye.
Going Further
If this is the kind of SQL Server stuff you love learning about, you’ll love my training. Blog readers get 25% off the Everything Bundle — over 100 hours of performance tuning content. Need hands-on help? I offer consulting engagements from targeted investigations to ongoing retainers. Want a quick sanity check before committing to a full engagement? Schedule a call — no commitment required.