Dan Guzman Blog

I stumbled across surprising SQL Trace/Profiler behavior I think is worth mentioning.  Parameter values reported in trace RPC starting/completed events are not the values that SQL Server uses to execute the query.  Here’s an example I recently discovered that shows this behavior.

I ran the following C# code to execute parameterized query "SELECT @DateTime" with the parameter value set to October 11, 2007.  The console message verified that SQL Server returned the expected date.

Here is the SQL Profiler trace of the of the SQL:BatchCompleted and RPC:Completed events:

I pasted the script from the trace and ran it from a SQL Server Management Studio query window.  Here’s the trace of the SSMS script execution:

Even though the SQL looks the same, the SSMS query returned a different date (“November 10, 2007”) than the application ("October 11, 2007")!  What’s up with that?  Why would the same script return different values when run from application code vs. Management Studio (or Query Analyzer), even with identical session settings?

The reason for the behavior difference is the trace event class.  The application trace showed an RPC:Completed event but the SSMS session trace showed SQL:BatchCompleted.  Both had the same “exec sp_executesql…” statement in the TextData.  Even though the trace reported the same TextData for both events, SQL Server processed the RPC differently than the SQL batch and the trace didn’t show the complete story for the RPC event.

The issue is that the datetime input parameter value for the RPC event was not really included in the SQL statement like the trace RPC:Completed event showed.  The actual datetime parameter value that SQL Server used during RPC execution was passed in native (i.e. binary) format via the low-level TDS protocol.  The trace TextData was only a reverse-engineered string representation of that value rather than the actual value SQL Server used.

In contrast, the batch sent by SSMS wasn’t parameterized so SQL Server needed to parse the datetime string value in the batch text.  The datetime string "2007-10-11 00:00:00:000" (generated by the trace, not passed by the app) is ambiguous and interpreted differently depending on the DATEFORMAT setting.  Due to the "DATEFORMAT DMY" setting in the script, the date string value was (mis)interpreted as November 10, 2007 instead of October 11, 2007.  The DATEFORMAT setting had no affect on the RPC (parameterized value) because the setting affects only string parsing and not the native datetime value provided by the application.

I discovered this issue when I was helping a user who was working with a French language SQL Server (that's why I specified DATEFORMAT DMY) troubleshoot a datetime parameter problem.  The trace data led me down the wrong path because it didn't immediately click with me that 1) DATEFORMAT doesn't affect RPC datetime parameters and 2) trace RPC TextData isn't used for query execution anyway. 

I filed Connect feedback on this to suggest that SQL Trace/Profiler be changed to serialize RPC datetime values in a DATEFORMAT neutral format like "2007-10-11T00:00:00:000" or "20071011 00:00:00:000".  This will provide the same behavior when the trace TextData SQL is executed as a batch and be a bit more intuitive when analyzing trace data.