When Profiling SQL Server Stored Procedures Goes Wrong
Thanks for reading!
Video Summary
In this video, I delve into the intricacies of using extended events to profile stored procedures, specifically focusing on a common issue where multiple quick queries add up to significant overall duration. I introduce SP_HumanEvents, a tool I developed to simplify working with human events in SQL Server, and demonstrate how it can be used to identify performance bottlenecks in scenarios where individual queries are fast but collectively take longer than expected. By sharing this practical example, I aim to provide insights for query tuners faced with complex stored procedures that require fine-grained optimization at the micro-level.
Full Transcript
Erik Darling here. Does any of this surprise you at this point? Darling Data, alive and well, thriving, writhing, grinding away. In today’s video, we’re going to talk about extended events profiling ics. There’s actually really only one ics, but it’s happened to me so many times I’m going to pluralize it. So, I’ve got a stored procedure. You may have heard of it. You may have used it. You may have it installed on your server, but it sits there collecting dust while you don’t update anything, called SP underscore human events, events, events, events. And of course, the point of it is to make working with human events a lot easier than Microsoft has made it, because as usual, Erik Darling cares about you where Microsoft does not. Erik Darling wants you to succeed. Erik Darling wants you to figure out your problems. Erik Darling wants you to succeed. Erik Darling wants you to live a long, happy life. Microsoft cares not, except for anything other than maximizing shareholder happiness. So, we’re going to look at that today. Not shareholder happiness, but that thing up there. Anyway, before we do that, let’s talk about my happiness. If you really like this channel content and you find me worth $4 a month, there’s a link in the video description where it says become a member, which is sort of a strange way of putting it, but I guess that’s what you become when you get a membership. You become a member. You can do that for $4 a month. If $4 a month is just far beyond your financial grasp, I get it. Not everyone can make these lucrative YouTube videos for money.
I am up to nearly 20 members at this point. So, if you do the math on that per month, I can almost pay one month of a cable bill. Almost. You can, liking, commenting, subscribing, all free. I’ll open things that you can do to make me a happy man. If you need help with your SQL Server and you are looking around the internet saying, gosh, all these consultants look stupid and goofy and they say, they write schlocky things about leadership or whatever.
I’m very good at all these things. I’m much better than the rest of them. So, if you need help with that at a reasonable rate, you know how to reach me. I’m very reachable. Reach anywhere and find me. Up, down, around. Pretty much any preposition or proposition. Anyway, if you want some SQL Server training of the low cost, high quality variety, if you go to that link up there and you put in that coupon code, you can get all of mine for the rest of your life for about 150 US dollars. It’s a pretty good deal. It’ll make you happy.
It really, really tickles the dopamine. If you want to catch me live and in person, I will be alongside Kendra Little for two days of performance, tuning, wonderfulness, this November 4th and 5th in Seattle, Washington.
If there’s an event near you that you think Erik Darling would make a good component of, a good member of, you can let me know what that event is and I can talk to the organizers and maybe get a pre-con there so that, you know, I can pay my hotel bill or something, which is always nice when that happens.
So, anyway, with that out of the way, let’s talk about extended event ics, or rather an ick that I have with extended events. Now, I’ve got a store procedure here called eventually. And the whole point of this store procedure is that there is a one second delay and then a very fast query and then a one second delay and a very fast query.
And what I’m going to do is I’m going to use spHumanEvents. Well, I’ve already used it. We’ve already got this thing over here, which is we’re watching live data. If you know, but I’ve set up, I’ve run spHumanEvents with this set of parameters to set up this session to look at query performance data.
And then I came over here and I right clicked on this and I hit watch live data. Now, when I do that and I click run here, this is going to run for about six seconds because there are about one, two, three, four, five, six, wait for delays.
Now, the way that I set up spHumanEvents to run is I put a query duration filter on here of five seconds, which means anything that runs over five seconds, we’re going to capture information about. Usually a pretty good starting place when you’re profiling an entire store procedure because, you know, something that runs over five seconds, you can usually do something about that.
If you have stuff that runs for way longer than five seconds, like if the whole thing runs for an hour and like there’s three queries, you might want to set that a little higher so that you figure out, you know, we don’t know, probably maybe one of the queries takes a second and the other one takes like three seconds and the other one takes like many minutes.
Well, you don’t really need to see query plans and stuff for the other ones. That’s kind of boring. But sometimes in unprofiling store procedures, there’s a lot of stuff going on. There’s lots of tiny little queries.
There might even be dynamic SQL. There might even be other store procedures getting executed. There might be all sorts of stuff that happens. I can’t possibly predict all of the insane things you people will put into your store procedures. So I usually start off by doing something like this so I can just capture the sort of higher value stuff and figure out what of that stuff I need to tune.
The thing is, all of the queries in here ran pretty quick, right? So we had the wait for delays that bumped up the total duration, the wall clock time, but nothing in here took a whole lot of CPU time or took a lot of wall clock time individually.
It happened as a group. Now, so when we come over here and we look at the output in extended events, we’re only going to see a couple lines.
We’re going to see module end and statement completed. So we see where the store procedure finished. That’s module end. And we see SQL statement completed. That was the query that I ran in SSMS saying we’re all done, right?
And they each had a duration of just about six seconds of wall clock time. There’s a little bit of difference in microseconds there, I guess, for whatever reason. Not really terribly important.
Not something we have to worry about. Maybe it was just probably just the difference between like the store procedure ending and SQL Server being signaling back to SSMS, hey, this is done. This can happen when you have code where sort of like what I was talking about before, you have a whole bunch of queries that run very quickly individually, but they add up to a lot of time in the aggregate, a high duration in the aggregate.
You might have loops. You might have, you know, cursors. You might do all sorts of weird stuff in a store procedure that makes the store procedure run for a long time.
But you don’t have an actual single individual query that you can go in tune very easily. It’s not a very easy situation when you’re dealing with that because now you have to figure out, you know, like at a very, very small scale, very small improvements you can make so that, you know, each individual step finishes faster than it did before so that in the aggregate, things are faster.
You know, like with a big query that takes a long time to run, you might be able to make, you know, let’s just say it takes 30 seconds to run, you might be able to make a whole bunch of changes to that one query to bring that one query down to like, I don’t know, two, three seconds or something.
But when you have a query that runs, say, you know, a million times and you need to get that query to produce results in the aggregate faster, you’re looking at really micromanaging a lot of different individual things.
That’s when you have to start getting query plans for much smaller bits of SQL and say, taking something that takes 300 milliseconds and getting that down to even fewer milliseconds, like three or two or five milliseconds or something crazy.
And going from 300 down to that smaller number is where you start, you know, seeing the bigger results again in the aggregate. That’s a little bit beyond what I can do in this short video, but it is something that it is an eventuality that a lot of query tuners need to prepare for where, you know, you can even compare this to like, if you have a big, gigantic, massive query, and let’s say it finishes in 500 milliseconds, but there are 500 operators in there and they all take very few milliseconds.
You know, sometimes a query like that is just the sum of its parts, right? Like you, like the only way for you to make something faster is either to take parts out of that or really start breaking down where like any amount of time is spent and trying to improve that.
Not always the easiest thing to do for, especially for big queries like that, you might even have significant compile time on the query itself. But anyway, just something that you should be aware of when you’re profiling. I mean, if you’re not using SP human events, you’re, you’re, you’re screwing up, but something to be aware of when you’re profiling stuff is that you might have a store procedure that takes five or six seconds to run, but none of the individual parts really contribute heavily to that.
So that’s when you would have to start taking the query duration filter and putting this down to a much smaller number, like, you know, like either one second or 500 milliseconds or something else in order to find query tuning opportunities. So that for each individual execution of that thing, you can speed that individual execution up and bring down the entire wall clock time of the whole shebang. So anyway, thank you for watching.
I hope you enjoyed yourselves. I hope you learned something. I hope that you will continue to view this channel, comment, subscribe, like, maybe even become a member. Anyway, that’s good for me here.
Thank you for watching.
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.