We’re almost at the end of my Working Effectively with Legacy SQL series. My penultimate topic will be all about durability and visibility of your code. Looking at web and application development, we see certain patterns about logging and error handling which make sense in the T-SQL world, and I will cover those. I also intend to cover a couple of SQL-specific tips.
Error Handling
Let’s start with the point of common ground: error handling. Your applications (should) have error handling logic; in the world of .NET, that is typically exceptions which you handle with TRY-CATCH blocks. Microsoft implemented TRY-CATCH logic in SQL Server 2005, where it replaced the venerable @@ERROR command. I highly recommend that you switch to using TRY-CATCH whenever possible in your SQL code, as it makes error handling more reliable and more readable. If you are familiar with TRY-CATCH from C# or Java, the T-SQL version is very similar, except that you don’t get multiple CATCH blocks for handling different classes of exceptions.
So here’s an example of a simple query with TRY-CATCH. We’re going to use this simple query throughout the post as we build more and more logic into that procedure.
CREATE PROCEDURE dbo.GetFraction @Divisor INT = 5 AS SELECT 1.0 / @Divisor AS Quotient; GO
This is very simple code. If you run it like so, you’ll get the expected result:
EXEC dbo.GetFraction @Divisor = 5;
But what happens if somebody tries to divide by 0?
EXEC dbo.GetFraction @Divisor = 0;
We get an error, just like we would expect. The problem here is that nobody whose job it is to maintain the system has knowledge of this error. We don’t handle it anywhere and are relying upon the calling application or end user to have enough information to troubleshoot this issue. That might be okay in a simplistic example like this, but in a real development scenario, the error might be due to interdependencies between several parameters and a specific data set; re-generating that scenario could waste a lot of the troubleshooter’s time.
With that in mind, let’s introduce TRY-CATCH logic to the procedure.
IF (OBJECT_ID('dbo.GetFraction') IS NULL)
BEGIN
EXEC ('CREATE PROCEDURE dbo.GetFraction AS SELECT 1 AS Stub;');
END
GO
ALTER PROCEDURE dbo.GetFraction
@Divisor INT = 5
AS
BEGIN TRY
SELECT
1.0 / @Divisor AS Quotient;
END TRY
BEGIN CATCH
DECLARE
@ErrorMessage NVARCHAR(4000);
SELECT
@ErrorMessage = ERROR_MESSAGE();
THROW 50000, @ErrorMessage, 1;
END CATCH
GO
With that in place, we call the procedure with a divisor of 0 and…well, the same thing happens. To this point, we haven’t really done anything special. What we have done, however, is build the foundation for the next step. As a quick note before I move on, I want to point out that I re-throw the error in the catch block. This is important because we still want the application to fail like before; our goal here is to gain insight into failures more than trying to handle all errors. You can, of course, handle your errors and take care of them if you know the appropriate response, but for this scenario, we just want to log them.
Logging Errors
Until you catch your errors, you can’t log them. Now that we’re catching errors in this procedure, we can log relevant information related to each time calling the procedure throws an exception.
So why don’t we just log whatever gets sent back to the application using a framework like ELMAH? I hope you are doing this! But remember that your data environment is more than just procedures the application calls. You probably have SQL Agent jobs, SSIS packages, SSRS reports, other applications, etc. all hitting that database. Yes, there are ways of logging calls for each of those, but now you need to look at a number of different sources to determine if you have any unbeknownst-to-you errors popping up. Also, these tools have wildly different levels of granularity and value to the information they log. SQL Agent jobs have a fixed result size, meaning that they truncate error data. This makes it much harder to troubleshoot a long-running job. Also, relatively few options log the full call with all parameters and values, meaning that you may know what the error is, but not necessarily the set of steps required to replicate this error. With complex stored procedures, simply knowing that there was an error isn’t always enough to replicate it; you need parameters. One final problem is that even if these loggers do collect information, they don’t really know the SQL “call stack.” The application code doesn’t know that procedure1 called procedure2 which called procedure3 which called … procedureN. We know that procedure1 was the initial call and the error message typically tells us that procedureN failed, but if you have that level of complexity in stored procedure calls, troubleshooting becomes tedious.
With all of those problems in mind, let’s try to come up with a simplistic solution. This is a scaled-down version of something we use at the office:
CREATE TABLE [dbo].[ErrorLog] ( [DatabaseName] [NVARCHAR](128) NULL, [SchemaName] [NVARCHAR](128) NULL, [ProcedureName] [NVARCHAR](128) NULL, [ErrorLine] [INT] NULL, [ErrorMessage] [NVARCHAR](4000) NULL, [LogDateGMT] [DATETIME] NOT NULL, [ParameterList] [XML] NULL );
With this table in mind, let’s fix up the CATCH block so that we can insert a row into the error log. Now our procedure looks a bit like this:
IF (OBJECT_ID('dbo.GetFraction') IS NULL)
BEGIN
EXEC ('CREATE PROCEDURE dbo.GetFraction AS SELECT 1 AS Stub;');
END
GO
ALTER PROCEDURE dbo.GetFraction
@Divisor INT = 5
AS
BEGIN TRY
SELECT
1.0 / @Divisor AS Quotient;
END TRY
BEGIN CATCH
DECLARE
@DatabaseName NVARCHAR(128),
@CallingProcedureName NVARCHAR(128),
@CallingSchemaName NVARCHAR(128),
@ErrorLine INT,
@ErrorMessage NVARCHAR(4000),
@ParameterList XML,
@ErrorNumber INT;
SELECT
@DatabaseName = DB_NAME(),
@CallingProcedureName = OBJECT_NAME(@@PROCID),
@CallingSchemaName = OBJECT_SCHEMA_NAME(@@PROCID),
@ErrorLine = ERROR_LINE(),
@ErrorMessage = ERROR_MESSAGE(),
@ErrorNumber = ERROR_NUMBER();
SET @ParameterList =
(
SELECT
@Divisor AS [@Divisor]
FOR XML PATH ('ParameterList'), ROOT ('Root'), ELEMENTS XSINIL
);
INSERT INTO dbo.ErrorLog
(
DatabaseName,
SchemaName,
ProcedureName,
ErrorLine,
ErrorMessage,
LogDateGMT,
ParameterList
)
VALUES
(
@DatabaseName,
@CallingSchemaName,
@CallingProcedureName,
@ErrorLine,
@ErrorMessage,
GETUTCDATE(),
@ParameterList
);
THROW 50000, @ErrorMessage, 1;
END CATCH
GO
That is a pretty lengthy catch block and I would recommend creating a utility stored procedure to simplify some of this logic. In any event, when we call GetFraction with a valid divisor, we still get the same results back. When we call it with a divisor whose value is 0, you get the following error message:
Note that this error message looks the same as our old one, except that we have a line which reads (1 row(s) affected) right above it. That shows us that we inserted a record into the ErrorLog table:
This tells us when we had an error, what the error was, and if you click on ParameterList, you’ll even get a listing of which parameters were passed in:
<Root xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"> <ParameterList Divisor="0" /> </Root>
There’s a little work translating parameters back to the relevant T-SQL, but what’s nice is that you have everything you need to re-create this error message.
Before I move on, I want to note one more thing. I collect the error number in @ErrorNumber but I don’t use it in the THROW. The reason I don’t re-throw using that error number is because if I do, I will get the following error:
If you want to re-raise an error message and you want to use THROW, you can simply have “THROW;” be your message or you can re-raise with a custom error number. If your calling code expects to handle certain types of errors by error number, then you should just throw without re-numbering. Otherwise, it doesn’t make that much of a difference.
Capture Performance Data
You probably have some sort of administrative tool which tracks procedure performance. If so and if that works well enough for you, then you don’t need to do much here. There may be circumstances in which you want to get finer-grained performance data, even if you have a top-level tool which tracks procedure times. For example, suppose you have a procedure which generates a number of different dynamic SQL statements. Suppose that we can generate a query for the sales team, a separate query for the marketing team, and a third query for the accounts payable team based on our data. Each of those teams has sorting and filtering functionality, so the Sales query has the same core components but might not always look the same from run to run, especially the WHERE and ORDER BY clauses. Our generator knows which query it will generate, so we can build performance collection metrics into our system by query, letting us figure out which of the three queries is actually a problem.
For this example, I’m going to stick with my simplistic division case. We now want to introduce performance logging. To do that, I’m going to track when the procedure begins and when it ends. If the procedure fails, I don’t want to log the amount of time it took. If you do want to log performance of errors, you’d need to modify your CATCH block somewhat and it would make the procedure a little more complex.
To track this new performance data, we’ll create a new table called PerformanceLog:
CREATE TABLE [dbo].[PerformanceLog] ( [DatabaseName] [NVARCHAR](128) NULL, [SchemaName] [NVARCHAR](128) NULL, [ProcedureName] [NVARCHAR](128) NULL, [StartDateGMT] DATETIME2(7) NOT NULL, [EndDateGMT] DATETIME2(7) NOT NULL, [ParameterList] [XML] NULL, RunTimeInMilliseconds AS DATEDIFF(MILLISECOND, StartDateGMT, EndDateGMT) );
Note that several of the parameters for PerformanceLog are the same as ErrorLog. Thus, when I refactor my procedure to include performance information, I will move those matching variables out to a common area:
IF (OBJECT_ID('dbo.GetFraction') IS NULL)
BEGIN
EXEC ('CREATE PROCEDURE dbo.GetFraction AS SELECT 1 AS Stub;');
END
GO
ALTER PROCEDURE dbo.GetFraction
@Divisor INT = 5
AS
DECLARE
@StartDateGMT DATETIME2(7) = SYSUTCDATETIME(),
@DatabaseName NVARCHAR(128) = DB_NAME(),
@CallingProcedureName NVARCHAR(128) = OBJECT_NAME(@@PROCID),
@CallingSchemaName NVARCHAR(128) = OBJECT_SCHEMA_NAME(@@PROCID),
@ParameterList XML;
BEGIN TRY
SET @ParameterList =
(
SELECT
@Divisor AS [@Divisor]
FOR XML PATH ('ParameterList'), ROOT ('Root'), ELEMENTS XSINIL
);
SELECT
1.0 / @Divisor AS Quotient;
INSERT INTO dbo.PerformanceLog
(
DatabaseName,
SchemaName,
ProcedureName,
StartDateGMT,
EndDateGMT,
ParameterList
)
VALUES
(
@DatabaseName,
@CallingSchemaName,
@CallingProcedureName,
@StartDateGMT,
SYSUTCDATETIME(),
@ParameterList
);
END TRY
BEGIN CATCH
DECLARE
@ErrorLine INT,
@ErrorMessage NVARCHAR(4000),
@ErrorNumber INT;
SELECT
@ErrorLine = ERROR_LINE(),
@ErrorMessage = ERROR_MESSAGE(),
@ErrorNumber = ERROR_NUMBER();
INSERT INTO dbo.ErrorLog
(
DatabaseName,
SchemaName,
ProcedureName,
ErrorLine,
ErrorMessage,
LogDateGMT,
ParameterList
)
VALUES
(
@DatabaseName,
@CallingSchemaName,
@CallingProcedureName,
@ErrorLine,
@ErrorMessage,
GETUTCDATE(),
@ParameterList
);
THROW 50000, @ErrorMessage, 1;
END CATCH
GO
Let’s walk through the code changes here. First of all, I moved some of the variable declarations outside of the CATCH block. I also added in a new variable called @StartTimeGMT, which I declared as DATETIME2(7) in order to get maximum precision. If you want to use a DATETIME2(7), you shouldn’t use GETUTCDATE() anymore because it just returns at DATETIME precision. Here’s a sample of the difference, where the first two records used GETUTCDATE() and the third used SYSUTCDATETIME():
Remember that DATETIME has a precision of 3 milliseconds, so if your procedure takes less than 3ms to run, you can’t store the difference.
Moving the choice of time measure aside, the other big change was my insertion into dbo.PerformanceLog. This is another case where creating a helper stored procedure might be worth it, but to make the demo simpler, I decided to keep that insert statement inline.
Now that we have error and performance tracking, let’s move on to the last section.
Handling Transactions
The above sections on using TRY-CATCH, logging errors, and logging performance are all right out of the handbook and apply to languages like C# or Java as well. But here’s something which is more SQL-specific: be sure to handle your transactions.
In this scenario, we aren’t opening any explicit transactions. Our statement is a simple SELECT statement which does not modify data. Nevertheless, let’s say that we really do want transactions. Here’s the final version of the procedure:
IF (OBJECT_ID('dbo.GetFraction') IS NULL)
BEGIN
EXEC ('CREATE PROCEDURE dbo.GetFraction AS SELECT 1 AS Stub;');
END
GO
ALTER PROCEDURE dbo.GetFraction
@Divisor INT = 5
AS
DECLARE
@InNestedTransaction BIT;
DECLARE
@StartDateGMT DATETIME2(7) = SYSUTCDATETIME(),
@DatabaseName NVARCHAR(128) = DB_NAME(),
@CallingProcedureName NVARCHAR(128) = OBJECT_NAME(@@PROCID),
@CallingSchemaName NVARCHAR(128) = OBJECT_SCHEMA_NAME(@@PROCID),
@ParameterList XML;
BEGIN TRY
SET @ParameterList =
(
SELECT
@Divisor AS [@Divisor]
FOR XML PATH ('ParameterList'), ROOT ('Root'), ELEMENTS XSINIL
);
IF ( @@TRANCOUNT > 0 )
BEGIN
SET @InNestedTransaction = 1;
END
ELSE
BEGIN
SET @InNestedTransaction = 0;
BEGIN TRANSACTION;
END;
SELECT
1.0 / @Divisor AS Quotient;
INSERT INTO dbo.PerformanceLog
(
DatabaseName,
SchemaName,
ProcedureName,
StartDateGMT,
EndDateGMT,
ParameterList
)
VALUES
(
@DatabaseName,
@CallingSchemaName,
@CallingProcedureName,
@StartDateGMT,
SYSUTCDATETIME(),
@ParameterList
);
IF ( @InNestedTransaction = 0 AND @@TRANCOUNT > 0 )
BEGIN
COMMIT TRANSACTION;
END;
END TRY
BEGIN CATCH
IF ( @InNestedTransaction = 0 AND @@TRANCOUNT > 0 )
BEGIN
ROLLBACK TRANSACTION;
END
DECLARE
@ErrorLine INT,
@ErrorMessage NVARCHAR(4000),
@ErrorNumber INT;
SELECT
@ErrorLine = ERROR_LINE(),
@ErrorMessage = ERROR_MESSAGE(),
@ErrorNumber = ERROR_NUMBER();
INSERT INTO dbo.ErrorLog
(
DatabaseName,
SchemaName,
ProcedureName,
ErrorLine,
ErrorMessage,
LogDateGMT,
ParameterList
)
VALUES
(
@DatabaseName,
@CallingSchemaName,
@CallingProcedureName,
@ErrorLine,
@ErrorMessage,
GETUTCDATE(),
@ParameterList
);
THROW 50000, @ErrorMessage, 1;
END CATCH
GO
The big change was the addition of @InNestedTransaction on line 12 and its use throughout the procedure. If you are already inside a transaction, you don’t want to go any deeper; nested transactions in SQL Server are broken.
But why would we already be in a transaction? The answer is: parent procedures and processes. GetFraction might be the third procedure in a chain, and if I have a chain of procedures, I don’t want to commit my transaction until everything has succeeded. Putting it another way, suppose Procedure1 calls Procedure2 and Procedure3. If Procedure2 succeeds and Procedure3 fails, I want to roll back everything—I don’t want to leave data in a state in which some of the information is new (because Procedure2 ran) but some of it is old (because Procedure3 was rolled back).
Note that my PerformanceLog insert statement is inside the transaction. You can argue either way about this one, but my general tendency is to make sure all INSERT statements are wrapped inside a transaction. The other side of this argument is that you wouldn’t want your procedure to fail simply because logging failed. If you are insistent upon this point, you could take that INSERT statement out of the transaction and wrap the insertion statement in a TRY-CATCH block which swallows errors. Just be sure to leave a note explaining why you’re swallowing errors so that whoever needs to maintain this procedure doesn’t curse your name later when they see no data for performance stats.
Wrapping Up
Our seven-line procedure (including some generous spacing) has ballooned up to 105 lines as a result of all of these changes. Yeah, you can probably shave a couple dozen lines off with utility procedures, but we added a lot of boilerplate. On the other hand, we now have error logging, performance logging, and transaction safety. We definitely want error logging and (when modifying data) transaction safety, so those are certainly worthy endeavors. Performance logging is a little more iffy, particularly if you have a solution in place which returns these numbers, but it can be helpful as well.
36 Chambers - The Legendary Journeys: Execution to the max! 