Wednesday, October 24, 2012

How do you debug your stored procedures?

Well, perhaps 'Debugging' is not the best way to describe it. If you need to debug a procedure step-by-step, there are tools within SQL Server (or Visual Studio) that will, in most cases, allow you to do so.

But in real life (or let's just say - production), we often face a different situation where Stored-Procedures are being executed by the Application side (DAL's in most cases)
And sometimes, we don't just need to see which procedure was executed when (if we want to do this Profiler is there to help) - we need to track certain activities inside the stored procedures.

While application developers have a lot of logger libraries (such as Log4Net, for example), SQL Developers don't have an out-of-the-box solution.

So SQL Developers write their own solutions, and sometimes even use PRINT (god forbid!) within the procedures to track the output (yes, even today!)

This is why we've created Log Table Viewer.
The solution includes a simple table/procedure to write the log message (+severity and some other optional properties), and a client viewer to easily see and explore the written messages.

After deploying the solution (which is done automatically by the viewer app - by clicking this button):

you get a new procedure, which can be executed as simple as that:



EXEC usp_write_to_log @source='TestScript', @message='Hello World', @severity=1

What happens (by default) is this:
1:
You see an immediate output to the screen (if executed by SSMS) with the message
[Oct 24 2012  4:06:13:397AM] Hello World
The console does not use "PRINT" (which does not flush immediately into the screen), but rather a RAISERROR(@console_message,10,1) WITH NOWAIT statement, which is better in these cases

2:
A log message is written to our log table (tblLog)


There are many other option parameters when executing the procedures, here's the actually interface:
usp_write_to_log( 
 @source VARCHAR(255),
 @message VARCHAR(4192), -- 4k
 @severity INT = 1, /*0=Debug, 1=Informational, 2=Warning, 3=Critical*/
 @category INT = 1, /*1=Databases. For future use if more clients use this usp*/
 @write_to_console BIT = 1, /*New: Only write to console, not table*/
 @write_to_table BIT = 1, /*New: Only write to table not console */
 @write_to_sql_log BIT = 1, /*New: output to SQL errorlog as well (only for warning, error)*/
 @write_to_sql_log_minimum_severity INT = 3,
 @suppress BIT = 0 /*New emergency option; When compiled with (1) no actual writes to tblLog are made.*/
                           )


So now, you can easily use this procedure to write various messages inside your SQL Code.
Here's a screenshot for one of my servers, with some recent messages (just so you get the look & feel)
You can see the "Hello World" message we just wrote on the previous example:

Log Table Viewer - Real-time display