Quick hints for using the RAISERROR command.

Introduction

Sometimes you get a situation where a long-standing stored procedure seems to have started misbehaving. Either unexpected records are returned or expected records are omitted. Perhaps the procedure appears to freeze without completing.

The procedure seems to work correctly using Query Analyser in your test environment but in the live environment with the live application things do not appear to be working correctly.

You quickly establish that:

• The procedure is identical in both environments
• The database schema is identical in both environments
• The data in the tables used by the procedure is as it should be

You suspect that it is the way in which the application calls the stored procedure that is at fault but how do you prove it?

The simple approach

Well my approach would be to watch the parameters going into the procedure and variables flowing through the procedure to make sure that all is as it should be.

In your development environment you may have access to the SQL Query Analyser Debugger but in the live environment you do not thus step through debugging cannot take place. You have to resort to printing out parameters and variables at key stages of the functions in the procedure. There are three ways of doing this.

SELECT statement(s)

This is the simplest way and can print out multiple values of different types at once.

The down side is that other procedures may depend on your problem procedure and tampering with the recordsets that are output could break other parts of your application. For example if you have

INSERT INTO dbo.Tbl_MyTable (MyfieldList1....MyFieldListn)
EXEC dbo.usp_GetMyRecords @arg1, @arg2 ...@argn

Or you may have used the techniques described in "Reducing round trips to the server" to produce multiple recordsets and therefore having the server return additional recordsets will break application code that makes use of this method.

PRINT statement(s)

These do not break the two dependencies described above but they are somewhat cumbersome to use.

If you have an integer your cannot say PRINT 'The integer =' + @myIntVariable without casting the variable first. This makes printing multiple values a laborious job.

In addition the print statements will wait until the batch completes before returning any information. If you are trying to PRINT messages to see how far the procedure actually gets then not getting any messages until the batch completes is going to put a bit of a damper on things.

Of course the problem with both PRINT and SELECT is that your calling application has to be able to trap the message and log it. In large environments retrospectively adding logging code would constitute a new release and therefore instigate a whole new test cycle.

Although such testing is necessary in mission critical software all we want to do is establish some simple message logging.

RAISERROR statement(s)

Again, like the PRINT statement, these do not break the to dependencies described under SELECT statement(s) and they allow multiple values of different types to be printed.

They can also echo values into the Windows Event Log which is also a boon to the developer as message logging is shifted out of the application and into the stored procedure.

The example script below will write a message directly to the Windows Event Log.

DECLARE @sStringVar VARCHAR(440) ,
@lIntegerInt ,
@fFloatdecimal(6,2) ,
@byUnsignedInttinyint ,
SELECT @sStringVar='A string' ,
@lInteger=44 ,
@fFloat=3.14 ,
@byUnsignedInt = 56 ,
RAISERROR('The string variable contains %s, the int contains %d, the float contains %d, the uint contains %d',
10 - Informational severity only.
,1
,@sStringVar,
@lInteger,
@fFloat,
@byUnsignedInt
), WITH LOG, NOWAIT

The crucial statements are in the WITH clause.

Downsides to the RAISERROR statement

Message size is 440 characters, hardly a major concern.

REAL,Float and DATETIME values not allowed but they may be cast to strings using either CAST or CONVERT statements.

According to books online decimal values can be printed and you can specify the precision however I have never managed to get the statement to return anything other than strings and integers.

Number and type of arguments must match the number and type of place holders. Again, this is hardly a problem.

Tricks with RAISERROR placeholders

%+d will display the integer with the correct sign + or -.

10 will appear as +10, -10 will appear as -10.

%6d creates a space 6 wide to hold the value.

10 will appear right justified as ....10

%-6d creates a space 6 wide but left justifies the value.

%x will render the value in hexadecimal and in lower case

%X will render the value in hexadecimal and in upper case.

%#x will render hexadecimal in lower case i.e. 0x8f

%#X will render hexadecimal in upper case. 0X8F

%u will display int values of 0 to 2147483647 as is , -1 to -21474748348 will display as 4294967295 to 21474748348. In other words it displays the 2's complement value.

Real word example

The stored procedure I was trying to debug contained several SQL statements and although the procedure was locking solid there was no indication as to which statement block was causing the lock. All statement blocks contained the same tables/views albeit performing different tasks so sp_lock gave no clues.

What I did was to DECLARE a variable for my message at the head of the procedure.

DECLARE @sMessage VARCHAR(440) ,-- The maximum possible message size

Then around each statement block I placed the following commands

 @dtStart DATETIME ,
@dtEnd DATETIME ,
@lDuration
SET @dtStart=GETDATE()
SET @sMessage = CONVERT(CHAR(19),@dtEnd,120) + ' <proc name>:<block description> started'
RAISERROR(@sMessage,10,1) WITH LOG,NOWAIT
<statement block start>
...
<statement block end>
SET @dtEnd=GETDATE()
SET @lduration = DATEDIFF(ms,@dtStart,@dtEnd)
SET @sMessage = CONVERT(CHAR(19),@dtEnd,120) + ' : completed in %d milliseconds'
RAISERROR(@sMessage,10,1,@lDuration) WITH LOG,NOWAIT

The net result was an event log with paired messages confirming that:

• A particular block within the stored procedure had started and at what time.
• A particular block had completed at what time and had taken 'n' milliseconds.

As a side effect to confirming that certain blocks of code were running correctly I also gained a good impression of which blocks were taking the longest to run and were potentially consuming the most resources.