|
|
Trace Messages Part III: Ending Sessions and Adding Metrics
Volume 3 #5
February 1,
2005 Full TOC
by Andrew Novick
Sign up for this newsletter at:
http://www.novicksoftware.com/coding-in-sql/coding-in-sql-signup.htm
The
current theme is about application trace messages. The previous two
articles (Part
I and
Part II) described the AppSession and the AppSessionTrace tables
and the stored procedures that insert and update their rows. So far
we have:
·
Tables:
o
AppSession
o
AppSessionTrace
·
Procedures:
o
usp_AppSession_Create
o
usp_AppSession_SQLJOB
o
usp_AppSession_Trace
o
usp_AppSession_Example and its worker sprocs
When I started this
series I thought there were the only going to be three issues and I
could wrap it all up in this third issue. It turns out that there
is more code than I thought. I guess that's good news. So I've
split this issue into three parts. Part IV and Part V of the series
will cover retrieving the values out of the AppSession* tables
easily and the promised clean up stored procedure.
In order to better
organize the Newsletter issues, I've started an
Editorial Calendar.
In it I'm tracking the scheduled themes and planned issues.
You might want to take a look at it and make a suggestion for an
issue or a theme. Thanks.
In this issue we
complete the session by calling usp_AppSession_End. This procedure
handles two functions. First, it updates the AppSession table with
the final update date and duration for the session. Second, it
optionally writes a series of metrics to the AppSessionMeasurement
table. These metrics can be used to store numbers strings and dates
that define how the session performed. Here’s the CREATE FUNCTION
script for the table:
CREATE TABLE AppSessionMeasurement (
SessionID int NOT NULL ,
ParameterName varchar (32) NOT NULL ,
Measurement sql_variant NULL
)
Next we need the
usp_AppSession_End procedure:
CREATE PROCEDURE
dbo.usp_AppSession_End
@SessionID int
-- Session ID from usp_AppSession_Create
, @MeasurementList varchar(8000)
= NULL --
@Seperator
-- seperated List of
measurements.
, @MeasurementValues varchar(8000)
= NULL --
@Seperator
-- seperated list of values
, @Seperator char(1) = ','
-- charcter to seperate entries
-- in the two lists
/* Complete the AppSession and add measurements. Measurements
* can be any data type, but they're input as characters.
* those that are numeric are coverted to float and those
* that are dates are coverted to datetime. The rest remain
* varchar.
*
* Example:
Declare @SessionID int
, @User_Name varchar(20)
exec dbo.usp_AppSession_Create 0, 'SQLJOB', @@SPID, 'MyServer'
, 'usp_AppSession_End', 0, 'TestServer'
, 'TestUser'
, @SessionID OUTPUT
WAITFOR DELAY '00:00:05'
exec dbo.usp_AppSession_End @SessionID
, 'TESTSTRING|Test Date|Test Number|TEST Missing'
, 'My Measure|7/10/1956|17.234'
, '|' -- Pipe as seperator
SELECT * FROM AppSession WHERE SessionID = @SessionID
SELECT * from AppSessionMeasurement WHERE SessionID = @SessionID
*
* © 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 #5 2/2/05
http://www.NovickSoftware.com/coding-in-sql.htm
****************************************************************/
AS
SET NOCOUNT ON
-- enter the time completed,
duration is calculated.
UPDATE AppSession
SET LastUpDT =
getdate()
, DurationDUR = DATEADD (MilliSecond
,
DATEDIFF (millisecond
, CreatedDT
,
getdate()
)
, '00:00:00')
WHERE SessionID=@SessionID
IF @MeasurementList
IS NOT NULL
AND @MeasurementValues
is NOT NULL BEGIN
DECLARE @Measurements
TABLE (
RowNum int identity
(1,1) primary key
, MeasurementName
varchar(32)
)
Declare @Values
TABLE(
RowNum int identity
(1,1) primary key
, Value sql_variant
)
INSERT INTO @Measurements (MeasurementName)
SELECT Item
FROM dbo.udf_Txt_SplitTAB(@MeasurementList,
@Seperator)
INSERT INTO @Values (Value)
SELECT Item
FROM dbo.udf_Txt_SplitTAB(@MeasurementValues,
@Seperator)
DECLARE DTcursor
CURSOR
FOR SELECT RowNum,
Value
FROM @Values
DECLARE @Row
int, @Value
sql_variant
OPEN DTCursor
FETCH DTCUrsor
into @Row, @Value
WHILE @@Fetch_status = 0
BEGIN
-- Loop contents
IF 1=ISDATE(convert(varchar(255),
@Value)) BEGIN
UPDATE @Values
SET Value =
CONVERT(datetime,
@Value, 121)
WHERE RowNum = @Row
END
ELSE IF 1=ISNUMERIC
(convert(varchar(255),
@Value)) BEGIN
UPDATE @Values
SET Value =
Convert(float,
@Value)
WHERE RowNum = @Row
END
-- on to the next row.
FETCH DTCUrsor
into @Row, @Value
END --
WHILE LOOP
-- Clean up the cursor
CLOSE DTCursor
DEALLOCATE DTCursor
-- Now insert the values into
AppSessionMeasurement
INSERT INTO
AppSessionMeasurement
SELECT @SessionID
, M.MeasurementName
, V.Value
FROM @Measurements M
LEFT OUTER JOIN @Values
V
ON M.ROwNum =
V.RowNum
END
)
When calling usp_AppSession_End, the
measurements are optional. If you don’t have any, you don’t have to
supply any of these parameters and the call looks something like
this:
EXEC usp_AppSession_End @mySessionID
What sort of measurements or metrics do I
store? The answer is: It depends. Usually its simple things like
the number of rows processed. If I’m counting errors, I’ll often
add the number of errors encountered or the highest error number. The only dates that I usually
store are the dates that came from the procedure’s parameters. By
adding them to AppSessionMeasurement I can create a report that
shows both the input parameters to the procedures and its results.
To provide an example of how to use
usp_AppSession_End lets go back to usp_AppSession_Example from the
previous
issue. The final few lines of that sproc were:
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
These lines wrote a final message with the
totals for Worker1 and Worker2. The call to usp_AppSession_End was
postponed until this issue. Here’s a replacement for
usp_AppSession_Example showing how usp_AppSession_End might be
called with measurements:
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
SELECT * From AppSessionMeasurement 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,
@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 both
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 both
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
DECLARE @MeasureNames varchar(8000)
-- Names of the measurements
, @MeasureValues varchar(8000)
-- Corresponding Valeus
SELECT @MeasureNames =
'Worker1 Tot|Worker2 Tot|WorstError'
, @MeasureValues = CONVERT(VARCHAR,
@Worker1_Tot)
+ '|' + CONVERT(VARCHAR,
@Worker2_Tot)
+ '|' + CONVERT(VARCHAR,
@WorstError)
EXEC usp_AppSession_End @TraceSesID,
@MeasureNames
, @MeasureValues, '|'
RETURN @WorstError
Instead of a final trace message, the
usp_AppSession_Example ends with the creation of some measurement
parameters and a call to usp_AppSession_End. The number of
measurements that I might want to add is variable. Stored procedures
only take a fixed number of parameters. To bridge this gap I used two delimited
lists to pass the measurement names and values to
usp_AppSession_End. The final parameter is a delimiter. I use the
pipe character because it’s one characters rarely found in the
parameters.
Let's run the example batch from the header
comment of usp_AppSession_Example. It runs the store procedure and
then pulls the output from the AppSessionTrace and
AppSessionMeasurement tables:
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
SELECT * From AppSessionMeasurement WHERE SessionID = @TID
(Results)
11:35:23:080-usp_AppSession_Example-Testing dur=1900-01-01 00:00:10.
Session=31 – line wrapped
11:35:23:080-usp_AppSession_Example_W-Worker1 Result1=9
11:35:23:080-usp_AppSession_Example_W-Worker2 Result2=4
11:35:26:093-usp_AppSession_Example_W-Worker1 Result1=4
11:35:26:093-usp_AppSession_Example_W-Worker2 Result2=0
11:35:29:110-usp_AppSession_Example_W-Worker1 Result1=9
11:35:29:110-usp_AppSession_Example_W-Worker2 Result2=8
11:35:32:127-usp_AppSession_Example_W-Worker1 Result1=3
11:35:32:127-usp_AppSession_Example_W-Worker2 Result2=6
RC=0 Session = 31
TraceMessageID SessionID Source Category MsgDT
-------------- ----------- -------------------- ----------
----------
(0 row(s) affected)
SessionID ParameterName Measurement
----------- -------------------------------- -------------------
31 Worker1 Tot 25.0
31 Worker2 Tot 18.0
31 WorstError 0.0
(3 row(s) affected)
The trace output was sent to the SQL Query
Analyzer results pane so they're no rows in AppSessionTrace.
However, there are three entries in AppSessionMeasurement. Just as
expected.
While a store
procedure is in development I like to see the trace and measurement
values right away. To make my life easier I've written a store
procedure and user-defined function that retrieve them quickly
they'll be the subject of next issue.
As always, if you have comments about the
newsletter and in particular, the new direction that I’m planning on
taking, please let me know at
coding-in-sql@novicksoftware.com.
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
|
|
