|
|
|
Trace Level |
Meaning |
|
0 |
None |
|
1 |
Error |
|
2 |
Warning |
|
3 |
Informational |
|
4 |
Verbose |
When I’m writing code I set the trace level to 4/Verbose to see all trace information. Once the code is working I set the trace level down to 3/Informational. When the code moves into production I set the level down to 2/Warning and once I’m comfortable with the application I might set the trace level down to 1/Error or just leave it at 2/Warning.
What determines the level for a particular message? That is, what makes a message an error versus a warning or informational? I have some rules of thumb that I follow. The message is a….
· Error if the result is unexpected and program must terminate because if it.
· Warning if the result is unexpected but the program can continue.
· Informational if it's reporting a successful or expected result.
· Verbose for dumping out intermediate results or internal variables
In the end, each programming team must decide how to classify their messages.
By default .Net TRACE output normally goes to the Visual Studio Debug Output Window. I prefer to have the information saved to a file so I take advantage of the ability to add a custom trace listener and add my own file trace listener. This lets me review the trace messages after the fact and to review the messages generated by my colleagues and by users of the early versions of the program.
So how does this apply to SQL coding? It applies because I’ve created a similar facility in SQL server and use it to trace the execution of stored procedures in my applications. I’ve patterned its behavior after the .Net TRACE. There are the same five message levels as in .Net. Also, I’ve implemented the ability to direct messages either to the SQL Query Analyzer Results output or to the AppSessionTrace table. Here’s the CREATE TABLE script for AppSessionTrace:
CREATE TABLE
AppSessionTrace (
TraceMessageID int IDENTITY (1,
1) NOT NULL ,
SessionID int NOT NULL ,
Source varchar (24)
NULL ,
Category varchar (16)
NULL ,
MsgDT datetime NOT NULL
CONSTRAINT DF_AppSessionTrace_MsgDT
DEFAULT (getdate()),
RunningTraceLevel smallint NOT NULL
CONSTRAINT DF_AppSessionTrace_TraceLevel
DEFAULT (0),
MessageTraceLevel smallint NOT NULL
CONSTRAINT DF_AppSessionTrace_MessageTraceLevel
DEFAULT (0),
Msg nvarchar (3000)
NOT NULL ,
CONSTRAINT PK_AppSessionTrace
PRIMARY KEY CLUSTERED
(
TraceMessageID
) WITH FILLFACTOR
= 90
)
To write trace lines I use a stored procedure, usp_AppSession_Trace, which writes one trace message. Here’s its CREATE PROCEDURE script:
CREATE PROCEDURE
dbo.usp_AppSession_Trace
@TraceMessageID int OUTPUT
, @SessionID int
, @RunningTraceLevel smallint
-- Negative numbers for Storage,
--
Positive for printing
, @MessageTraceLevel smallint
-- Msg Level 0-4
, @Msg nvarchar(3000)
, @TraceSource varchar(24) = ''
-- originator of msg
, @TraceCategory varchar(16)
= '' -- Category of the message.
/* Stores a single debug message in the AppSessionTrace table
* or prints it. The RunningTraceLevel determines what actually
* happens with the message.
*
* © Copyright 2005 Andrew Novick http://www.NovickSoftware.com
* You may use this code in any of your SQL Server databases
* including databases that you sell, so long as they contain
* other unrelated database objects. You may not publish this
* procedure either in print or electronically.
* Published as Coding in SQL Newsletter Vol 3 #4 1/25/05
http://www.NovickSoftware.com/coding-in-sql.htm
****************************************************************/
AS
SET NOCOUNT ON
DECLARE @myError int,
@myRowCount int
-- Only do anything if the Running
trace level is >= the level of
-- the message
IF ABS(@RunningTraceLevel) >=
@MessageTraceLevel BEGIN
IF @RunningTraceLevel < 0
BEGIN
INSERT INTO
AppSessionTrace
([SessionID], [MsgDT], [Source], [Category]
, [RunningTraceLevel], [MessageTraceLevel], [Msg])
VALUES (@SessionID,
getdate()
, @TraceSource, @TraceCategory
, ABS(@RunningTraceLevel)
, @MessageTraceLevel, @msg)
SELECT @myError = @@Error,
@myRowcount = @@Rowcount
IF @MyError = 0
BEGIN
SET
@TraceMessageID = SCOPE_IDENTITY()
END
END
ELSE IF
@RunningTraceLevel > 0 BEGIN
-- Print it
PRINT convert(varchar(12),
getdate(), 14) + '-'
+ @TraceSource + '-'
+ @Msg
END
END
The following table describes the use of each of the parameters to usp_AppSession_Trace:
|
Parameter |
Data Type |
Description |
|
@TraceMessageID |
Int OUTPUT |
The ID of the message. |
|
@SessionID |
Int |
Key to AppSession that was returned by usp_AppSession_Create or usp_AppSession_SQLJOB |
|
@RunningTraceLevel |
Smallint |
Encapsulates information on how to handle the message. The sign of the message indicates where to send the message: · Positive: to the message output. · Negative: to the AppSessionTrace table The absolute value determines the trace level of run-time message handling. This is analogous to the .Net Trace Switch: 0=No
trace messages |
|
@MessageTraceLevel |
Smallint |
The trace level used to a value in this message. When invoked the message trace level is usually a constant. It is always a positive number. |
|
@Msg |
Nvarchar(3000) |
The actual message. I allow a large amount of for the message because when I'm writing stored procedures that create dynamic SQL I generally put the SQL statement into the message. |
|
@TraceSource |
Varchar(24) |
Stored procedure or program that originated the message. This is the specific stored procedure or client program that writes the message. |
|
@TraceCategory |
Varchar(16) |
Category of the message. Used to group messages of different types. |
When debugging I set @RunningTraceLevel to 4 so that all possible trace output is sent to the SQL Query Analyzer Results window. Programs running in production usually run with @RunningTraceLevel set to -2, which inserts error and warning output to the AppSessionTrace table.
Now lets take a look at a stored procedure that uses the AppSession and AppSessionTrace tables and stored procedures that are in this issue and the previous issue to record what's happening inside an stored procedure. usp_AppSession_Example is going to be invoked by SQL Server Agent. It’s given duration to run and loops every three seconds for that duration and calls its two worker sprocs usp_AppSession_Example_Worker1 and usp_AppSession_Example_Worker2. The CREATE PROCEDURE scripts follow. You’ll also need udf_DT_AddTime from Volume 1 #38 of the T-SQL UDF of the Week Newsletter.
CREATE PROC
dbo.usp_AppSession_Example
@Duration datetime =
'00:01:00' -- Duration to run
, @TraceLevel Smallint = -1
-- 0=None, 1=Error, 2=Warning
--
3=Information, 4=Verbose
, @TraceSesID int OUTPUT
-- AppSession.SessionID
AS
/* This SP is an example of how to write application trace
* information using the usp_AppSession_* procedures and the
* AppSession and AppSessionTrace tables.
*
* This sp is intended to be run by a SQL Agent Job but can be
* run any other way.
*
* Example:
DECLARE @RC int, @TID int
EXEC @RC = usp_AppSession_Example
"00:00:10" -- Duration 10 seconds
, 3 -- Trace Level Informational
, @TID OUTPUT -- AppSession.SessionID
PRINT 'RC='+ coalesce(convert(varchar(20),@RC), '<null>')
+ ' Session = ' + coalesce(convert(varchar(20),@TID), '<null>')
SELECT * FROM AppSessionTrace where SessionID = @TID
*
* © Copyright 2005 Andrew Novick http://www.NovickSoftware.com
* You may use this code in any of your SQL Server databases
* including databases that you sell, so long as they contain
* other unrelated database objects. You may not publish this
* UDF either in print or electronically.
* Published as Coding in SQL Newsletter Vol 3 #4 1/19/05
http://www.NovickSoftware.com/coding-in-sql.htm
****************************************************************/
DECLARE @TerminateRunningDT
datetime
-- when to stop gathering
, @WaitFor_Interval datetime
, @LastRecordingDT datetime
, @RecordingDT datetime
, @myError int
, @myRowCount int
, @LastRequestDT datetime
, @TargetRows int
, @Msg varchar(1999)
, @WorstError int
, @RC int
, @TotalRows int
, @TraceSource varchar(24)
, @TraceCategory varchar(16)
, @JobStartTime datetime
, @TraceMsgID int
-- The ID of a particular message
, @Results1 int
-- example results
, @Results2 int
-- example results
, @Worker1_Tot int
-- Total of Worker1 = SUM(Results1)
, @Worker2_Tot int
-- Total of Worker2 = SUM(Results2)
SET NOCOUNT ON
SELECT @WaitFor_Interval = CONVERT(datetime,
'00:00:03')
, @TerminateRunningDT =
dbo.udf_DT_AddTime (getdate(),
@Duration)
, @WorstError = 0
, @TotalRows = 0
, @JobStartTime = getdate()
, @TraceSource = 'usp_AppSession_Example'
, @TraceCategory = 'SP'
, @Worker1_Tot = 0 -- Init so it's
not NULL
, @Worker2_Tot = 0 -- Init so
it's not NULL
-- Create the session
EXEC usp_AppSession_SQLJOB 0,
'usp_AppSession_Example', USER_ID
, @TraceSesID OUTPUT
-- Write the startup message
SET @Msg = 'Testing dur=' +
coalesce(convert(varchar(20),
@Duration, 121), '<null>' )
+ ' Session=' + coalesce(convert(varchar(10),
@TraceSesID), '<null>')
exec usp_AppSession_Trace @TraceMsgID
output, @TraceSesID, @TraceLevel
, 3, @Msg, @TraceSource, @TraceCategory
WHILE getdate() <= @TerminateRunningDT
BEGIN
-- Invoke Worker1
exec @rc =
usp_AppSession_Example_Worker1 @TraceLevel, @TraceSesID
, @Results1
OUTPUT
SELECT @myError =
@@Error, @MyRowCount = @@Rowcount --
Capture immediately
SELECT @WorstError =
CASE WHEN ABS(@myError) >
ABS(@WorstError)
THEN @myError
WHEN ABS(@RC)
> ABS(@WorstError)
THEN @RC
ELSE
@WorstError END
, @Worker1_Tot = @Worker1_Tot + @Results1
-- Invoke Worker2
exec @rc =
usp_AppSession_Example_Worker2 @TraceLevel, @TraceSesID
, @Results2
OUTPUT
SELECT @myError =
@@Error, @MyRowCount = @@Rowcount --
Capture immediately
SELECT @WorstError =
CASE WHEN ABS(@myError) >
ABS(@WorstError)
THEN @myError
WHEN ABS(@RC)
> ABS(@WorstError)
THEN @RC
ELSE
@WorstError END
, @Worker2_Tot = @Worker2_Tot + @Results2
WAITFOR DELAY @WaitFor_Interval
-- delay
END
SET @Msg = 'Done Worker1 Total = ' +
CONVERT(VARCHAR,
@Worker1_Tot)
+ ' Worker2 Total = ' + CONVERT(VARCHAR,@Worker2_Tot)
exec usp_AppSession_Trace @TraceMsgID
output, @TraceSesID, @TraceLevel
, 2, @Msg, @TraceSource, @TraceCategory
-- usp_AppSession_End is in the next
issue.
RETURN @WorstError
GO
CREATE PROC
dbo.usp_AppSession_Example_Worker1
@TraceLevel Smallint = -1
-- 0=None, 1=Error, 2=Warning
--
3=Information, 4=Verbose
, @TraceSesID int
-- AppSession.SessionID.
, @Result1 int OUTPUT
-- Example output
AS
/* This SP is an example of how to
write application trace
* information using the usp_AppSession_* procedures and the
* AppSession and AppSessionTrace tables. It's called from
* usp_AppSession_Example.
*
* Published as Coding in SQL Newsletter Vol 3 #4 1/25/05
http://www.NovickSoftware.com/coding-in-sql.htm
****************************************************************/
DECLARE @myError
int
, @myRowcount int
, @TraceSource varchar(24)
, @TraceCategory varchar(16)
, @JobStartTime datetime
, @TraceMsgID int
-- The ID of a particular message
, @Msg nvarchar(3000)
SET NOCOUNT ON
SELECT @TraceSource = 'usp_AppSession_Example_Worker1'
, @TraceCategory = 'Detail'
-- The next line is the example meat of
the program.
SELECT @Result1 =
CONVERT(int,
RAND() * 10)
SELECT @myError = @@Error, @myRowCount
= @@RowCount
IF @myError != 0
BEGIN
-- Report the error
SET @Msg = 'Error in RAND
usage =' + convert(varchar,
@myError)
exec usp_AppSession_Trace @TraceMsgID
output, @TraceSesID, @TraceLevel
, 1, @Msg, @TraceSource, @TraceCategory
RAISERROR (@Msg, 16, 1)
WITH LOG
-- Suspenders and a belt!
END
ELSE BEGIN
-- Trace the result
SET @Msg = 'Worker1
Result1=' + convert(varchar,
@Result1)
exec usp_AppSession_Trace @TraceMsgID
output, @TraceSesID, @TraceLevel
, 3, @Msg, @TraceSource, @TraceCategory
END
RETURN @myError
GO
CREATE PROC
dbo.usp_AppSession_Example_Worker2
@TraceLevel Smallint = -1
-- 0=None, 1=Error, 2=Warning
, @TraceSesID int
-- AppSession.SessionID.
, @Result2 int OUTPUT
-- Example output
AS
/* This SP is an example of how to
write application trace
* information using the usp_AppSession_* procedures and the
* AppSession and AppSessionTrace tables. It's called from
* usp_AppSession_Example.
**
* Published as Coding in SQL Newsletter Vol 3 #4 1/25/05
http://www.NovickSoftware.com/coding-in-sql.htm
****************************************************************/
DECLARE @myError
int
, @myRowcount int
, @TraceSource varchar(24)
, @TraceCategory varchar(16)
, @JobStartTime datetime
, @TraceMsgID int
-- The ID of a particular message
, @Msg nvarchar(3000)
SET NOCOUNT ON
SELECT @TraceSource = 'usp_AppSession_Example_Worker2'
, @TraceCategory = 'Detail'
-- The next line is the example meat of
the program..
SELECT CONVERT(int,
RAND() * 10)
SELECT @myError = @@Error, @myRowCount
= @@RowCount
IF @myError != 0
BEGIN
-- Report the error
SET @Msg = 'Error in RAND
usage =' + convert(varchar,
@myError)
exec usp_AppSession_Trace @TraceMsgID
output, @TraceSesID, @TraceLevel
, 1, @Msg, @TraceSource, @TraceCategory
RAISERROR (@Msg, 16, 1)
WITH LOG
-- Suspenders and a belt!
END
ELSE BEGIN
-- Trace the result
SET @Msg = 'Worker2
Result2=' + convert(varchar,
@Result2)
exec usp_AppSession_Trace @TraceMsgID
output, @TraceSesID, @TraceLevel
, 3, @Msg, @TraceSource, @TraceCategory
END
RETURN @myError
GO
There’s a lot of code to absorb so let me make a couple of points:
- @TraceLevel and @TraceSesID must be passed to all lower level routines for them to function properly.
- The worker sprocs are responsible for reporting their own error messages. Therefore the top level sproc, usp_AppSession_Example, doesn’t report on the results of the detail operations, it only keeps track of the worst error that it’s encountered.
- The @RunningTraceLevel is always a positive constant. It represents the severity of the message as determined by the author of the procedure.
- In the worker sprocs, notice that when reporting an error the 1/Error is used and when reporting routine results 3/Informational is used.
- When there is an error, I often also use a RAISEERROR WITH LOG statement to ensure that the message is sent even if there is a ROLLBACK.
Once the example procedures are in place try out usp_AppSession_Example for a 10 second run using a trace level of 3.
DECLARE @RC int, @TID int
EXEC @RC = usp_AppSession_Example
'00:00:10' -- Duration
10 seconds
, 3 --
Trace Level Informational
, @TID OUTPUT --
AppSession.SessionID
PRINT 'RC='+ coalesce(convert(varchar(20),@RC), '<null>')
+ ' Session = '
+ coalesce(convert(varchar(20),@TID), '<null>')
GO
(Results)
15:28:35:917-usp_AppSession_Example-Testing dur=1900-01-01
00:00:10. Session=5
15:28:35:917-usp_AppSession_Example_W-Worker1 Result1=5
15:28:35:917-usp_AppSession_Example_W-Worker2 Result2=4
15:28:38:917-usp_AppSession_Example_W-Worker1 Result1=6
15:28:38:917-usp_AppSession_Example_W-Worker2 Result2=6
15:28:41:920-usp_AppSession_Example_W-Worker1 Result1=7
15:28:41:920-usp_AppSession_Example_W-Worker2 Result2=6
15:28:44:920-usp_AppSession_Example_W-Worker1 Result1=9
15:28:44:920-usp_AppSession_Example_W-Worker2 Result2=0
15:28:47:920-usp_AppSession_Example-Done Worker1 Total = 27 Worker2
Total = 16
RC=0 Session = 5
There are a couple of limitations that this system has that I’d like to overcome:
- The name of the program executing the trace call is truncated. That’s a problem because I use such long procedure names.
- If trace results are sent to a table they are backed out if a transaction is rolled back. This can make it difficult to have both robust transaction handling and trace messages. In these situations, if I can, I send the trace output to the messages and make sure that these are send to some type of log. SQL Server Agent does capture the messages in the step output.
In the next issue, I’ll show you the routines that I use to clean up at the end of a session. The sproc usp_AppSession_End records the duration of the session and any metrics that the program might want to store.
Transact-SQL User-Defined Functions has been published! Take a look at it now!
Do you have an interesting stored procedure, user-defined-function,
or other sample code? If you'd like to share them please send
them in an email to:
coding-in-sql@NovickSoftware.com
and they might be published in this newsletter. I try and
respond to every request that I get.
Thanks,
Andy
Andrew Novick
New Tips:Loading SQL Profiler trace (.trc) files with fn_trace_gettrace |
Upcoming
|
