Create Extended Events Session to Capture a Single Stored Procedure

Create Extended Events Session to Capture a Single Stored Procedure

Do you ever have a stored procedure that you know is performing badly and needs tuning, but you’re struggling to capture when it is run or what parameters were passed in?
I had this problem recently, I knew that a particular stored procedure was running slowly for some parameters, but figuring out what the bad combination was proved to be very difficult. What if, instead of trying to guess what the parameters were, I just captured all of the time that the stored proc ran, along with the run time?

Extended events feel like the right option, but building event sessions can be daunting, and the default sessions capture a lot of data we don’t care about (not to mention, if you leave them running, SSMS usually crashes on me).

Let’s see how to make a session for just my 1 stored proc. First, our stored proc:

CREATE PROC MyProc (@num1 INT, @num2 INT)
AS
BEGIN
SELECT @num1/@num2
END

Nice and simple. Ignore the lack of error checking for a divide by zero, or the fact that it’s completely pointless to call. It’ll do for our testing.
Next up, create an event session. You’ll see that we’re adding two events, the first is rpc_completed. If you’re doing your application code correctly, this is the event that you should be capturing. The second event is sql_batch_completed. This is what you need if you want to capture events from SSMS, or if your application is calling the stored procedure as part of a batch. You could also use sql_batch_completed to capture any bit of text from your query. Just make sure it matches exactly what the query passes in (or has the right wild cards).

CREATE EVENT SESSION [MyProc] ON SERVER 
ADD EVENT sqlserver.rpc_completed(
    WHERE ([object_name]=N'MyProc')),
ADD EVENT sqlserver.sql_batch_completed(
    WHERE ([sqlserver].[like_i_sql_unicode_string]([batch_text],N'%MyProc%')))
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=OFF)

That creates my Extended Event session, that you can see here:

When I run that and watch live data, I can now see the events coming in:

As you can see, each of these is running as sql_batch_completed and in the batch_text detail, I can see that 100 and 10 were passed through, and the duration shows 131 microseconds (not milliseconds).
If this was run from application code, the rpc_completed event would appear, and the text including the parameters would be seen in the statement or sql_text detail.

Another option, particularly if you have a SQL statement instead of a stored procedure, you can use the Query Hash to trace it. This is a little bit more fiddley, but pretty straight forward.

First, we have to make our sample query a bit more complex so it actually produces a query plan. Add a select statement that joins a table or two together. Run it a few times to make sure it’s in cache.

Next, find your query hash. You can do this by using a tool like sp_BlitzCache, or you can try and find it through running code and looking at query plans, do whatever you want! I’ve grabbed mine from sp_BlitzCache, it’s 0xC198A5403C9081F0.

Next, convert this into a BIGINT:

SELECT CAST(0xC198A5403C9081F0 AS BIGINT)

Mine comes back as -4496662532616846864. Take that number, ignore any negatives (you don’t need that negativity in your life anyway), and create an event for it:

CREATE EVENT SESSION [query hash] ON SERVER
ADD EVENT sqlserver.sp_statement_completed(
ACTION(package0.collect_system_time,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_name)
WHERE ([sqlserver].[query_hash]=(4496662532616846864.))),
ADD EVENT sqlserver.sql_statement_completed(
ACTION(package0.collect_system_time,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_name)
WHERE ([sqlserver].[query_hash]=(4496662532616846864.)))
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=5 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)

When you start capturing that data, you’ll see the queries flowing through with the parameters used, and the duration:

There’s some extra noise like the login/logout events in this one, and I’m not sure why, but it’s good enough to get what I’m after.

Let me know in the comments what other techniques you use to track a single stored procedure or statement with Extended Events.