Stored procedure output parameters in SQL Server Profiler

Question

I've got a stored procedure with an int output parameter. If I run SQL Server Profiler, execute the stored procedure via some .Net code, and capture the RPC:Completed event, the TextData looks like this:

declare @p1 int
set @p1=13
exec spStoredProcedure @OutParam=@p1 output
select @p1

Why does it look like it's getting the value of the output parameter before executing the stored procedure?

Earth

? because that's the way it's displayed?? Where's the question? – Cottle

Well, the way it's displayed makes it look like it's magically guessing the value of the output parameter before executing the stored procedure. This obviously isn't the sequence of commands being executed, so I was just wondering why it's displayed that way. – Earth

Answer 1

The RPC:Completed event class indicates that a remote procedure call has been completed. So the output parameter is actually known at that point. See if tracing the RPC:Started shows you what you expect.

Phycomycete

Ok, I see, in the RPC:Started event the @p1 variable is set to NULL. Makes sense I suppose. – Earth

I am convinced this is a bug (and added an answer to that effect) - do you have any indication that this is intended behaviour? I could find no documentation either way. – Jiggered

Answer 2

This is, no matter how you look at it, a bug. The intent of the SQL Profiler "TextData" is to enable someone to understand and repeat the stored procedure call. In this case, running this T-SQL can give you a completely different result, if the spStoredProcedure procedure has any logic dependent on the input value of the @OutParam parameter, where that value of "13" were somehow meaningful as an input value.

It's easy to see how it can be convenient (enables you to see the output values of the proc call, which would otherwise need to do with the "RPC Output Parameter" event), but it is effectively a "lie" as to what T-SQL equivalent was executed.

RELATED: I just came across an article from the Microsoft Customer Service and Support team - about another case where conversion of the RPC:Completed event's BinaryData into a displayable TextData value results in an inaccurate reproduction of the original RPC call - this time codepage issues:
http://blogs.msdn.com/b/psssql/archive/2008/01/24/how-it-works-conversion-of-a-varchar-rpc-parameter-to-text-from-a-trace-trc-capture.aspx

UPDATED: By experimenting with this, I found another peculiarity of the behaviour - the profiler will only use this incorrect initial SET if the input value for that parameter, in the RPC call, was Null. If a non-null value was provided (and the parameter, in .Net SqlClient, had direction "InputOutput"), then that initial SET holds the true input value, and not the resulting output value. But if the input was null, then the output value is set instead. This observation supports the notion that this is simply a null-handling bug in the profiler RPC-to-TSQL display conversion.

Jiggered