SQL Server-Side Trace…with an example using Sage 500 ERP
February 5, 2012 Leave a comment
This topic has been written about many times. I am writing this post with a focus on Sage 500 ERP. The reason I am focusing on this as an example is that I have done quite a bit of work recently with some Sage 500 ERP customers and partners only to discover that most of them were using SQL Profiler on a system already experiencing severe pressures. Yet it needed to be done to satisfy the needs of Sage Support in order to provide more information on a support case.
SQL Profiler, also know as a Client-Side Trace, only adds to the pressure. An article by Andrew Kelly from 2008 does a nice job of explaining some the differences between the two and why you would choose over the other. The article can be found at http://www.sqlmag.com/article/performance/sql-server-profiler-or-server-side-trace-.
We are now going to concentrate on Server-Side Trace for the rest of this post. This is still relevant with most of the Sage 500 ERP and Sage X3 ERP implementations and would most likely be a benefit to you, at least that has been my experience over the past few months. I say that because we will discuss another technology feature that was introduced in SQL Server 2008 is Extended Events. This feature has been greatly expanded in the upcoming version, SQL Server 2012. If you want to read more about this feature this is a good starting point http://msdn.microsoft.com/en-us/library/dd822788(v=SQL.100).aspx. Jonathan Kehayias has many blog posts on this subject matter and is probably the industry expert on this topic in my opinion.
We will cover some foundation related to Trace Events and Trace Columns. This will provide you with resources and knowledge you will need to work with Server-Side Trace.
One way to approach this is to use SQL Profiler to configure your trace then you can do a File->Export->Script Trace Definition to write out the SQL Script that you can use to perform a Server-Side Trace. This can be a great way to get familiar with and transition from what you have been doing for probably many years.
Complete list of events
http://msdn.microsoft.com/en-us/library/ms186265.aspx
You can also select the Trace Events with the following syntax.
1: -- Trace Events
2: SELECT e.trace_event_id,
3: e.category_id,
4: e.name as traceeventname,
5: cat.name as categoryname,
6: cat.type
7: FROM sys.trace_events e
8: INNER JOIN sys.trace_categories AS cat ON e.category_id = cat.category_id
9: ORDER BY e.category_id, e.trace_event_id
Complete list of columns
http://msdn.microsoft.com/en-us/library/ms190762.aspx
You can also select the Trace Columns by Trace Event with the following syntax.
1: SELECT e.Trace_Event_ID,
2: e.name AS Event_Descr,
3: c.trace_column_id,
4: c.name AS Column_Descr,
5: c.type_name,
6: c.is_filterable
7: FROM sys.trace_events e
8: INNER JOIN sys.trace_event_bindings b
9: ON b.trace_Event_ID = e.Trace_Event_ID
10: INNER JOIN sys.trace_columns c
11: ON b.trace_column_id = c.trace_column_id
The Server-Side Trace consists, for the most part, of four components to get a trace running. The four components are:
- sp_trace_create – http://msdn.microsoft.com/en-us/library/ms190362.aspx
The procedure takes 5 parameters. One of which is an Output. It is used to create the trace definition.
TraceID – ID of the trace, this is an Output parameter and will provide the TraceIDOptions – several different options that can be set (refer to the link above for more details)
TraceFile – physical file name of the trace file you will write to
MaxFileSize – size of the file, once the file reaches this size it will close the file and create subsequent files
StopTime – used to specify a time to stop the trace
FileCount – used to specify the maximum number of trace files (optional0
The procedure takes 4 parameters. It is used to specify what event and what column to capture.
TraceID – ID of the trace
EventID – ID of the event you wish to capture
ColumnID – ID of the column you wish to capture
On – this will set the event on or off
This procedure takes 5 parameters. It is used to determine what to include and/or exclude from the collection.
TraceID – ID of the trace
ColumnID – ID of the column you wish to set the filter on
LogicalOperator – specify the type of operation, AND or OR
ComparisonOperator – specify the operand type (e.g. =, <>, >, <, >=, <=, like, not like)
Value – value used for the comparison
This procedure takes 2 parameters. It is used to change the status of the trace event. The close will also delete the trace definition. This delete does not delete the trace files that were created.
TraceID – ID of the trace
Status – stop(0), start(1) and close(2) trace, you must stop a trace in order to close a trace
So how do we use these commands. Well let’s answer some questions that I had while I was first starting out.
How do I create a trace?
You need to make sure that the folder exists for the tracefile and the SQL Server Service account user has permissions to write to that folder. It goes without saying but you should also make sure that you have ample disk space where the tracefile is about to write as well.
First you need to declare your variables.
1: -- Declare variables
2: DECLARE @rc INT
3: DECLARE @TraceID INT
4: DECLARE @maxFileSize bigint
5: DECLARE @fileName NVARCHAR(128)
6: DECLARE @on bit
7: DECLARE @stoptime DATETIME
Then you need to provide default values for these variables. Remember TraceID is an OUTPUT during the create phase so it will be assigned later.
1: -- Set values
2: SET @maxFileSize = 5
3: SET @fileName = N'C:\Perflogs\MyTrace'
4: SET @on = 1
5: SET @stoptime = DATEADD(hour,3,GETDATE())
Create the trace definition and verify that it was successful.
1: -- Create trace
2: EXEC @rc = sp_trace_create @TraceID output, 2, @fileName,
3: @maxFileSize, @stoptime
4:
5: -- If error end process
6: IF (@rc != 0) GOTO error
7:
8: /*
9: THIS WILL BE WHERE YOU PLACE YOUR CODE
10: THAT WILL SET THE EVENTS TO COLLECT AND
11: FILTER DATA FOR YOUR TRACE
12: */
13:
14:
15: -- Start the trace
16: EXEC sp_trace_setstatus @TraceID, 1
17:
18: -- display trace id for future references
19: SELECT TraceID=@TraceID
20: GOTO finish
21:
22: -- error trap
23: error:
24: SELECT ErrorCode=@rc
25:
26: -- exit
27: finish:
28: GO
Define the events and data to collect. Here are few that you would normally configure in SQL Profiler that Sage always requests. In the example below, using the first execution line from row 3, this is basically asking for the Event “RPC:Completed” which is event 10, column 1 which is “TextData” and set the event definition to 1 meaning on. See Image 1 below for how to discover this information.
1:
2: -- RPC:Completed
3: exec sp_trace_setevent @TraceID, 10, 1, @on
4: exec sp_trace_setevent @TraceID, 10, 6, @on
5: exec sp_trace_setevent @TraceID, 10, 9, @on
6: exec sp_trace_setevent @TraceID, 10, 10, @on
7: exec sp_trace_setevent @TraceID, 10, 11, @on
8: exec sp_trace_setevent @TraceID, 10, 12, @on
9: exec sp_trace_setevent @TraceID, 10, 13, @on
10: exec sp_trace_setevent @TraceID, 10, 14, @on
11: exec sp_trace_setevent @TraceID, 10, 15, @on
12: exec sp_trace_setevent @TraceID, 10, 16, @on
13: exec sp_trace_setevent @TraceID, 10, 17, @on
14: exec sp_trace_setevent @TraceID, 10, 18, @on
15: exec sp_trace_setevent @TraceID, 10, 27, @on
16:
17: -- SQL:BatchCompleted
18: exec sp_trace_setevent @TraceID, 12, 1, @on
19: exec sp_trace_setevent @TraceID, 12, 6, @on
20: exec sp_trace_setevent @TraceID, 12, 9, @on
21: exec sp_trace_setevent @TraceID, 12, 10, @on
22: exec sp_trace_setevent @TraceID, 12, 11, @on
23: exec sp_trace_setevent @TraceID, 12, 12, @on
24: exec sp_trace_setevent @TraceID, 12, 13, @on
25: exec sp_trace_setevent @TraceID, 12, 14, @on
26: exec sp_trace_setevent @TraceID, 12, 15, @on
27: exec sp_trace_setevent @TraceID, 12, 16, @on
28: exec sp_trace_setevent @TraceID, 12, 17, @on
29: exec sp_trace_setevent @TraceID, 12, 18, @on
30: exec sp_trace_setevent @TraceID, 12, 27, @on
31:
32: -- SP:Completed
33: exec sp_trace_setevent @TraceID, 43, 1, @on
34: exec sp_trace_setevent @TraceID, 43, 6, @on
35: exec sp_trace_setevent @TraceID, 43, 9, @on
36: exec sp_trace_setevent @TraceID, 43, 10, @on
37: exec sp_trace_setevent @TraceID, 43, 11, @on
38: exec sp_trace_setevent @TraceID, 43, 12, @on
39: exec sp_trace_setevent @TraceID, 43, 13, @on
40: exec sp_trace_setevent @TraceID, 43, 14, @on
41: exec sp_trace_setevent @TraceID, 43, 15, @on
42: exec sp_trace_setevent @TraceID, 43, 16, @on
43: exec sp_trace_setevent @TraceID, 43, 17, @on
44: exec sp_trace_setevent @TraceID, 43, 18, @on
45: exec sp_trace_setevent @TraceID, 43, 27, @on
46: exec sp_trace_setevent @TraceID, 43, 34, @on
47: exec sp_trace_setevent @TraceID, 43, 35, @on
48:
49: -- SP:StmtStarting
50: exec sp_trace_setevent @TraceID, 44, 1, @on
51: exec sp_trace_setevent @TraceID, 44, 3, @on
52: exec sp_trace_setevent @TraceID, 44, 12, @on
53: exec sp_trace_setevent @TraceID, 44, 14, @on
54: exec sp_trace_setevent @TraceID, 44, 22, @on
55: exec sp_trace_setevent @TraceID, 44, 26, @on
56: exec sp_trace_setevent @TraceID, 44, 27, @on
57: exec sp_trace_setevent @TraceID, 44, 34, @on
58: exec sp_trace_setevent @TraceID, 44, 35, @on
59:
60: -- SQL:BatchStarting
61: exec sp_trace_setevent @TraceID, 13, 1, @on
62: exec sp_trace_setevent @TraceID, 13, 3, @on
63: exec sp_trace_setevent @TraceID, 13, 12, @on
64: exec sp_trace_setevent @TraceID, 13, 14, @on
65: exec sp_trace_setevent @TraceID, 13, 26, @on
66: exec sp_trace_setevent @TraceID, 13, 27, @on
67: exec sp_trace_setevent @TraceID, 13, 35, @on
68:
69: -- Exec Prepared SQL
70: exec sp_trace_setevent @TraceID, 72, 1, @on
71: exec sp_trace_setevent @TraceID, 72, 6, @on
72: exec sp_trace_setevent @TraceID, 72, 9, @on
73: exec sp_trace_setevent @TraceID, 72, 10, @on
74: exec sp_trace_setevent @TraceID, 72, 11, @on
75: exec sp_trace_setevent @TraceID, 72, 12, @on
76: exec sp_trace_setevent @TraceID, 72, 13, @on
77: exec sp_trace_setevent @TraceID, 72, 14, @on
78: exec sp_trace_setevent @TraceID, 72, 15, @on
79: exec sp_trace_setevent @TraceID, 72, 16, @on
80: exec sp_trace_setevent @TraceID, 72, 17, @on
81: exec sp_trace_setevent @TraceID, 72, 18, @on
82: exec sp_trace_setevent @TraceID, 72, 27, @on
83: exec sp_trace_setevent @TraceID, 72, 34, @on
84: exec sp_trace_setevent @TraceID, 72, 35, @on
85:
86:
87: -- Execution Warnings
88: exec sp_trace_setevent @TraceID, 67, 1, @on
89: exec sp_trace_setevent @TraceID, 67, 8, @on
90: exec sp_trace_setevent @TraceID, 67, 10, @on
91: exec sp_trace_setevent @TraceID, 67, 11, @on
92: exec sp_trace_setevent @TraceID, 67, 12, @on
93: exec sp_trace_setevent @TraceID, 67, 14, @on
94: exec sp_trace_setevent @TraceID, 67, 27, @on
95: exec sp_trace_setevent @TraceID, 67, 31, @on
96: exec sp_trace_setevent @TraceID, 67, 35, @on
97:
Image 1 – This shows you how to select information for the event and column.
1: -- Get trace Event and Column details for event 10 RPC:Completed
2: SELECT e.Trace_Event_ID,
3: e.name AS Event_Descr,
4: c.trace_column_id,
5: c.name AS Column_Descr,
6: c.type_name,
7: c.is_filterable
8: FROM sys.trace_events e
9: INNER JOIN sys.trace_event_bindings b
10: ON b.trace_Event_ID = e.Trace_Event_ID
11: INNER JOIN sys.trace_columns c
12: ON b.trace_column_id = c.trace_column_id
13: WHERE e.Trace_Event_ID = 10
Now if you wish to set filters on the information you wish to collect would do that next. I have some specific filters created plus there are a few commented out just for examples. Make sure to visit the setfilter link above to get a more detailed understanding on this subject as you may not get the results you were hoping just because of how this is configured.
1: -- Set Filters
2: DECLARE @DB_ID int
3: SET @DB_ID = DB_ID('MAS500_app')
4: -- Creates a filter for only the database MAS500_app
5: EXEC sp_trace_setfilter @TraceID, 3, 0, 0, @DB_ID -- 3 : DatabaseID
6: -- Creates a filter to include only if column TextData contains tsoSalesOrder
7: EXEC sp_trace_setfilter @TraceID, 1, 0, 6, N'%tsoSalesOrder%' -- 1 : TextData, The 6 means LIKE
8: -- Creates a filter to exclude application SQL Profiler and SQL Agent
9: EXEC sp_trace_setfilter @TraceID, 10, 0, 7, N'SQL Profiler%' -- The 7 means NOT LIKE
10: EXEC sp_trace_setfilter @TraceID, 10, 0, 7, N'SQL Agent%' -- The 7 means NOT LIKE
11:
12: -- Some addtional filter examples that might be useful
13: -- To set a filter at the Server level instead of or in addtition to the database
14: --EXEC sp_trace_setfilter @TraceID, 8, 0, 0, 'SERVERNAME' -- 8 : HostName
15: -- This means to include if the ObjectName is equal to the passed in value
16: --EXEC sp_trace_setfilter @TraceID, 34, 0, 0, 'spsoCreateSalesOrder' -- 34 : ObjectName
17: -- This means that TextData will = the value passed in
18: --EXEC sp_trace_setfilter @TraceID, 1, 0, 0, 'Timeout getting Lock' -- 1 : TextData
Now start the Trace.
1: -- Start the trace
2: EXEC sp_trace_setstatus @TraceID, 1
I already covered the error trap and exit logic in the Create Trace segment above but I will provide you with this code again just for clarity sake.
1: -- display trace id for future references
2: SELECT TraceID=@TraceID
3: GOTO finish
4:
5: -- error trap
6: error:
7: SELECT ErrorCode=@rc
8:
9: -- exit
10: finish:
11: GO
How do I find out about my traces(s)?
To get a list of all the running traces on the server use the following statement. This will also show the SQL Server Default trace which is always traceid 1.
1: SELECT * FROM :: fn_trace_getinfo(default)
To look at the filters that are applied to a trace.
1: SELECT * FROM :: fn_trace_getfilterinfo(default)
To look at information about the events being traced by a trace use the following select.
1: SELECT * FROM :: fn_trace_geteventinfo(default)
We covered this already but I am providing these commands again just for clarity sake and a simple point of reference for you related to the setstatus procedure.
1: -- To start a trace
2: sp_trace_setstatus traceid, 1 -- TraceId would be the value of the trace
3: -- To stop a trace
4: sp_trace_setstatus traceid, 0 -- TraceId would be the value of the trace
5: -- To close and delete a trace
6: sp_trace_setstatus traceid, 2 -- TraceId would be the value of the trace
What do I do with my trace now that I am done?
Well you have several options available to you. You can simply open the trace file with SQL Profiler and scroll through it like you might have done in the past or you can load it into a SQL table so you can run queries against it.
The following code snippets show you how you can load data into a new table or an existing table from a trace file.
1: -- Load into a new table (need to type in the name created above)
2: SELECT * INTO master..TraceTable_RKL
3: FROM ::fn_trace_gettable('c:\Perflogs\MyTrace.trc', DEFAULT)
4:
5: -- Load into an existing table (need to type in the name created above)
6: INSERT INTO master..TraceTable_RKL
7: SELECT * FROM ::fn_trace_gettable('C:\Perflogs\MyTrace.trc', DEFAULT)
Once you have the data loaded into a table you can look at it just like it is any other table.
1: -- Look at data in table
2: SELECT * FROM master..TraceTable_RKL
Don’t forget to cleanup the table when you are finished.
1: -- cleanup the table
2: drop table master..TraceTable_RKL
Can I look at the details/contents of the Trace File?
Well yes you can.
1: -- View the contents of the trace file without loading into a table
2: -- or using SQL Profiler
3: SELECT * FROM ::fn_trace_gettable('C:\Perflogs\MyTrace.trc', DEFAULT)
I hope you found this useful. Thanks for stopping by. Until next time…