Monday, March 28, 2011

Towards a Print Statement that Appears in SQL Profiler –Part 1

The SQL Server PRINT statement can be very useful.  Some uses:
  1. Impromptu performance testing:  save the start time of a chunk of SQL in a variable, and at the end PRINT the difference between the current time and end time.
  2. Verifying during debugging that a variable used in a stored proc has the expected value at a certain point.
  3. Obtaining the value of a variable retrieved from the database during a proc so that the developer can do impromptu querying of other tables and verify their contents.
But the PRINT statement doesn’t echo to SQL Profiler.  This means that you can only do the above if you’re working with SSMS or otherwise have access to SQL Info Messages.  Oh, you can get a copy of the command you executed – “PRINT @ID” or whatever – but you won’t get visibility through Profiler to what @ID was. 

This is a problem if you’re trying to diagnose a stored procedure as an application executes it.  I started research a few days ago on how I might provide a PRINT to Profiler capability.

Let me say up front that I did not find a perfect solution.  But I can offer three partial ones.

1.  Use sp_trace_generateevent.  This is an extended stored procedure that lets you write a user-defined event to the trace log.  You can provide up to 256 chars of text and 8000 bytes of event data.  The characters appear in TextData and the 8000 bytes in BinaryData.   There are 10 reserved event Ids (82 to 91) that you can use for your own purposes. 

Here’s a stored proc that combines PRINT and using sp_trace_generateevent:
@Text nvarchar(max) 
DECLARE @UserData BINARY(8000) = 0
DECLARE @UserInfo NVARCHAR(256) = SUBSTRING(@Text,1,256)
PRINT   @Text
EXEC sp_trace_generateevent 82, @UserInfo, @UserData

In order to see the trace output in Sql Server Profiler, you need to turn on the appropriate user defined event.  My code above uses user-configurable event 0  (id=82), so you need to turn it on:


Here’s what the test script looked like:

DECLARE @PrintText varchar(256) = 'This is a test 
This is a test
This is a test
This is a test
This is a test'
EXEC PrintTrace1 @PrintText

And here’s what the SQL Profiler output looks like:


This works just fine, as long as you only need to PRINT 256 chars.  But suppose you need more?  Suppose your app works by retrieving templated SQL from a database table, and you need to be able to see every line that’s about to be executed?  In that case, sp_trace_generateevent won’t help you.  We’ll discuss other options next time.


Blogger use-writer said...

Hello Ann.
Thanks for this article, it helped me a lot today.
I just noticed how old this article is and I am curious about the other methods you told us about.
Do you still plan on writing about these (yeah, 10 years later, it may sound strange but as I told you, I just found out this blog post today :)).
In any case, thanks for this as it was really helpful.
Best regards!

4/07/2021 11:08 AM  

Post a Comment

<< Home