Extended Events and Stored Procedure Parameter Values

One complaint I’ve received frequently is that you can’t see stored procedure parameter values in Extended Events. That is patently not true. However, it does depend on where and how you capture the events and which stored procedure parameter values you’re going for. I think this is a holdover from 2008 when Extended Events… well, let’s be kind and say… didn’t work well. Now, they do. Let’s explore this a little.

Capturing Stored Procedure Executions

As with most things, there’s more than one way to capture stored procedure execution in Extended Events. First up, it depends entirely on how they’re called and on your intentions when you capture the information. Here are the three methods I know to capture just the completion metrics on stored procedure calls:

rpc_completed
sql_batch_completed
module_end

The first, rpc_completed, is exactly the same as the equivalent trace event and captures stored procedure calls from invoked code. Straight forward. The second, sql_batch_completed, captures batch commands, but these can contain stored procedure calls, even with invoked code if the invoked code is using sp_execute_sql to call procedures (yeah, maybe not the best way to write code, but when did that slow people down much). Finally, there’s module_end. Now this event is a little different. It captures stored procedures, sure, but also captures functions and other things. It’s very useful, but a little different. The duration metrics returned for this, for example, only include internal execution time, not any kind of communication times. This means you’ll see differences between module_end and the other events as we go through this (and in your own code).

Here’s the session I’m going to use:

CREATE EVENT SESSION StoredProcedureParameterValues
ON SERVER
    ADD EVENT sqlserver.module_end
    (SET collect_statement = (1)
     WHERE (sqlserver.database_name = N'AdventureWorks2017')),
    ADD EVENT sqlserver.rpc_completed
    (WHERE (sqlserver.database_name = N'AdventureWorks2017')),
    ADD EVENT sqlserver.sp_statement_completed
    (WHERE (sqlserver.database_name = N'AdventureWorks2017')),
    ADD EVENT sqlserver.sql_batch_completed
    (WHERE (sqlserver.database_name = N'AdventureWorks2017')),
    ADD EVENT sqlserver.sql_statement_completed
    (WHERE (sqlserver.database_name = N'AdventureWorks2017'))
    ADD TARGET package0.event_file
    (SET filename = N'C:\PerfData\StoredProcedureParameterValues.xel')
WITH (TRACK_CAUSALITY = ON);
GO

Yeah, I’m capturing statement level events and I’m tracking causality. I’ll explain why in a bit.

Capturing Stored Procedure Parameter Values

In order to test this, we have to execute a stored procedure. Here is a stored procedure:

CREATE OR ALTER PROC dbo.ProductTransactionHistoryByReference (@ReferenceOrderID INT)
AS
BEGIN
    SELECT p.Name,
           p.ProductNumber,
           th.ReferenceOrderID
    FROM Production.Product AS p
        JOIN Production.TransactionHistory AS th
            ON th.ProductID = p.ProductID
    WHERE th.ReferenceOrderID = @ReferenceOrderID;
END;

Using that procedure, here’s a way to execute it with a parameter value:

EXEC dbo.ProductTransactionHistoryByReference @ReferenceOrderID = 1255;

Here are the results laid out neatly in Live Data:

Click on that to make it larger. What you’ll see is, in order of completion, an sp_statement_completed event followed by module_end event, followed by sql_statement_completed and then sql_batch_completed. This demonstrates the order that would occur from execution of a stored procedure in a batch. If you look at the last event, the batch execution, you can see the parameter value. However, I know this will not satisfy people because, sure, it captures the strings executed in batches, but what about when you do remote procedure calls. Well, hang on. Before we get to that, take a look at the module_end event’s statement column. I’ll paste it here for you:

EXEC dbo.ProductTransactionHistoryByReference @ReferenceOrderID = 1255

I may be wrong, but that sure looks like I captured the stored procedure parameter value to me. However, we should test it to be sure. Oh, and, note that the execution time for the module_end is very different for the sql_batch_completed event. After executing this procedure using PowerShell, here are the results:

The first rpc_completed event you see in the sequence there is an artifact from my PowerShell code and doesn’t have any bearing on these proceedings. I left it in so that it didn’t look like I was hiding things. Now, look at the last line, the rpc_completed event. You’ll see this:

exec dbo.ProductTransactionHistoryByReference @ReferenceOrderID=41750

I have again captured the stored procedure parameter value.

What About Wrapper Procedures?

Now, let’s create another procedure that looks like this:

CREATE PROC dbo.Wrapper @OrderID INT
AS
EXEC dbo.ProductTransactionHistoryByReference @ReferenceOrderID = @OrderID;

That’s an extremely simplistic example of a wrapper proc. If we execute that, the extended events come back like this:

We have several more events this time because of the nature of the execution. Two different stored procedures were executed therefore we get module_end and sp_statement_completed events for each. Then, because I called this procedure from a batch, we also get the batch statement and batch completed events. However, note that the internal call does not show the stored procedure parameter value that was passed to it. It’s not in either the statement or the module events. This is the one place where I don’t know how to capture the stored procedure parameter value.

Also of note here, you can see exactly the order of events because I’m using causality tracking. It adds a GUID and a sequence. That sequence lets me see the order of events. It has an overhead cost associated with it, but I find myself gleefully paying that overhead in order to get that kind of information.

What About Profiler?

Well, obviously Extended Events are horrible and we should just use Profiler instead. What about Profiler, or more accurately, Trace Events? Can we get the stored procedure parameter values out of a wrapper procedure using Trace Events?

To test this, I set up a set of Trace Events using the equivalent events. Here are the results:

I don’t know about you, but I can’t see any stored procedure parameter values in the output of Trace Events either.

Conclusion

The most important thing I can say is, yes, extended events captures stored procedure parameter values. Further, I didn’t really do anything special to capture these values. I just captured the standard events and I had them. From what I can tell, this is the same behavior as you get in Trace. For those who have said that capturing stored procedure parameter values is the one showstopper preventing them from moving to Extended Events, time to pack.

---

I’m sorry to say that this is your final chance this year to attend my all-day seminar on query performance tuning tools. I’m thrilled to say that it’s in Munich on October 26, 2018. Go here now to join the class.