Stairway to Server-side Tracing

Stairway to Server-side Tracing - Level 4: How to Create and View Default and black box Trace Data

,

If you’ve ever watched a CSI television show episode, you know that forensic evidence is crucial in solving mysteries. Forensic data, together with skillful analysis, is often the key to identifying the root cause of problems that would otherwise remain unresolved. This Stairway article will show how to manage the pre-configured default and black box SQL Server traces and analyze collected data in several scenarios.

The Default Trace

The default trace is so named because it is on by default when SQL Server is installed. Unlike user-defined traces, the default trace is managed using sp_configure rather than sp_trace* stored procedures. The SQL Server Management Studio GUI does not provide a method to turn the default trace off or on. I suspect this was a conscious design decision by Microsoft to encourage DBAs to leave the default trace enabled at all times and to ensure this valuable data are collected even in environments with no formal DBA. The default trace is very lightweight so there is rarely a need to disable it. The T-SQL script in Listing 1 displays the current default trace enabled setting and toggles the value.

-- 'default trace enabled' is an advanced configuration option
EXEC sp_configure 
    'show advanced options' ,1;
RECONFIGURE ;

-- show current default trace setting
EXEC sp_configure 
    'default trace enabled';

-- turn off default trace
EXEC sp_configure 
    'default trace enabled', 0; 
RECONFIGURE ;

-- turn on default trace
EXEC sp_configure 
    'default trace enabled' ,1; 
RECONFIGURE ;

Listing 1: Display and toggle ‘default trace enabled’ configuration option

The definition of the default trace is predetermined and cannot be modified. The default trace definition specifies the trace file rollover option with a maximum of 5 files and a file size of 20MB. These trace file properties limit default trace data to no more than 100MB of disk space. Default trace files are created in the log folder for the SQL Server instance, each with the file name “log” followed by an integer uniqueifier and “.trc” extension (e.g. “C:\Program Files\Microsoft SQL Server\MSSQL10_50.MSSQLSERVER\MSSQL\LOG\log_183.trc”).

The first article in this Stairway included a query to list the events collected by the default trace along with the individual event columns. The listing in Figure 1 summarizes the dozens of events captured by the default trace. These events typically occur infrequently during normal workloads so the overhead of default trace data collection is negligible.

Event CategoryEvent Class
DatabaseData File Auto Grow
DatabaseData File Auto Shrink
DatabaseDatabase Mirroring State Change
DatabaseLog File Auto Grow
DatabaseLog File Auto Shrink
Errors and WarningsErrorLog
Errors and WarningsHash Warning
Errors and WarningsMissing Column Statistics
Errors and WarningsMissing Join Predicate
Errors and WarningsSort Warnings
Full textFT:Crawl Aborted
Full textFT:Crawl Started
Full textFT:Crawl Stopped
ObjectsObject:Altered
ObjectsObject:Created
ObjectsObject:Deleted
PerformancePlan Guide Unsuccessful
Security AuditAudit Add DB User Event
Security AuditAudit Add Login to Server Role Event
Security AuditAudit Add Member to DB Role Event
Security AuditAudit Add Role Event
Security AuditAudit Addlogin Event
Security AuditAudit Backup/Restore Event
Security AuditAudit Change Audit Event
Security AuditAudit Change Database Owner
Security AuditAudit Database Scope GDR Event
Security AuditAudit DBCC Event
Security AuditAudit Login Change Property Event
Security AuditAudit Login Failed
Security AuditAudit Login GDR Event
Security AuditAudit Schema Object GDR Event
Security AuditAudit Schema Object Take Ownership Event
Security AuditAudit Server Alter Trace Event
Security AuditAudit Server Starts And Stops
ServerServer Memory Change

Figure 1: Events collected by the default trace

Viewing and Analyzing Default Trace Data

Data collected by the default trace can be viewed using Profiler (FileàOpenàTrace File) or the fn_trace_gettable T-SQL function (discussed in

Level 2 of this Stairway). Personally, I usually use fn_trace_gettable to import trace data into a denormalized table for adhoc querying and filtering. The script in Listing 2 imports all available default trace files from the log folder of the default instance into a temporary table along with the event class and subclass names obtained from the sys.trace_events and sys.trace_subclass_valuescatalog views.

SELECT  te.name AS EventClassName
       ,tsv.subclass_name AS EventSubClassName
       ,t.*
INTO    #DefaultTraceData
FROM    fn_trace_gettable('C:\Program Files\Microsoft SQL Server\MSSQL10.MSSQLSERVER\MSSQL\Log\log.trc',
                          DEFAULT) AS t
        JOIN sys.trace_events AS te ON te.trace_event_id = t.EventClass
        LEFT JOIN sys.trace_subclass_values AS tsv 
             ON tsv.trace_event_id = t.EventClass
               AND tsv.subclass_value = t.EventSubClass ;

Listing 2: Import default trace data into temp table

Once imported, the trace data can be easily queried for particular events of interest. The query in Listing 3 reports file auto-grow events along with the relevant data columns. A SQL Server DBA best practice is to size database files appropriately for anticipated needs and specify auto-grow only as a safety net. This practice avoids physical file fragmentation and the overhead of expansion during normal operation. Since auto-grow events for both data and log files are captured by the default trace, it’s is easy determine if and when file growths occur so that the files can be expanded proactively in anticipation of future needs.

SELECT  EventClassName
       ,DatabaseName
       ,FileName
       ,IntegerData * 8 AS IncreasedSizeInKB
       ,ApplicationName
       ,StartTime
       ,EndTime
       ,Duration / 1000 AS DurationMicroseconds
FROM    #DefaultTraceData
WHERE   EventClassName IN ( 'Data File Auto Grow', 'Log File Auto Grow' ) ;

Listing 3: Query to display captured file auto grow events

The default trace captures several events of the errors and warnings category that indicate performance concerns. The query in Listing 4 displays hash and sort warning events. A hash warning occurs when hash partitions are written to disk (work tables in tempdb) due to insufficient memory. This event usually happens because SQL Server underestimated hash table memory requirements due to statistics on indexes and columns that were missing or stale. Frequent hash warnings can not only affect performance of the problem queries, but overall server performance may be impacted due to memory and tempdb contention.

Similarly, a sort warning occurs when a query sort operator cannot be performed in memory. A sort warning with event sub class “Multiple” is of particular concern because multiple passes over the data were needed to perform the sort operation. Avoiding hash and sort warnings can be as simple as creating or updating statistics. In other cases, query and index tuning may be needed to mitigate such warnings.

SELECT  EventClassName
       ,EventSubClassName
       ,DatabaseName
       ,ApplicationName
       ,StartTime
       ,IntegerData
FROM    #DefaultTraceData
WHERE   EventClassName IN ( 'Hash Warning', 'Sort Warnings' ) ;

Listing 4: Query to display captured hash and sort warning events

The Blackbox Trace

You may have guessed from the name that a blackbox trace captures details of recent SQL Server activity, analogous to an aircraft flight recorder. A blackbox trace is not used routinely. The typical use of a blackbox trace is to gather activity information that precedes a reoccurring problem, such as a sporadic SQL Server access violation or service interruption. The recent activity leading up to the problem may help DBAs or support engineers identify the root cause.

The blackbox trace is a pre-defined unfiltered trace that includes the events listed in Figure 2. Filters and other events cannot be specified. A blackbox trace is created using sp_trace_create with option value 8 (TRACE_PRODUCE_BLACKBOX). The blackbox trace option can’t be combined with other trace options and includes trace file rollover. A trace file name is not specified because the black box trace file name is predetermined (N'%SQLDIR%\MSSQL\DATA\blackbox.trc').

RPC starting
Batch starting
Exception
Attention

Figure 2: Blackbox trace events

Unless otherwise specified, the blackbox trace rollover file count is 2 and the max file size is 5MB. Listing 5 shows a script to create and start a black box trace with the default file size and rollover file count. Like other traces, a blackbox trace is started, stopped and deleted using sp_trace_setstatus with status values 1, 0 and 2 respectively. Be prepared to stop the blackbox trace soon after the targeted problem event (e.g. server crash, unresponsiveness) so that recently collected data is not lost due to subsequent activity that causes file rollovers. Data from the blackbox trace may be viewed using Profiler or fn_trace_gettable as I described previously for the default trace, but changing the file location to the blackbox trace file in the data folder.

DECLARE @TraceID INT ;
EXEC sp_trace_create 
    @traceid = @TraceID OUTPUT
   ,@options = 8 ;
SELECT  @TraceID ;
EXEC sp_trace_setstatus 
    @TraceID ,1 ;

Listing 5: Create and start black box trace with default 5MB file size and 2 rollover files

Remember that the blackbox trace is unfiltered and includes potentially high-frequency events (RPC and Batch starting). Although the collected information is potentially invaluable for troubleshooting purposes, be aware that the overhead of collecting voluminous against a busy OLTP server may be considerable. Use a blackbox trace with caution against very busy servers and consider specifying a file size and/or number of rollover files greater than the default to ensure forensic data leading up to the problem event are not lost. Listing 6 shows a black-box trace create script with a file size of 100MB and rollover file count of 10, thus providing up to 1GB of the most recently collected black-box trace data.

DECLARE @TraceID INT ;
DECLARE @maxfilesize2 bigint ;
SET @maxfilesize2 = 100 ;
EXEC sp_trace_create 
    @traceid = @TraceID OUTPUT
    ,@options = 8
    ,@tracefile = NULL
    ,@maxfilesize = @maxfilesize2
    ,@stoptime = NULL
    ,@filecount = 10 ;
SELECT  @TraceID ;
EXEC sp_trace_setstatus 
    @TraceID
    ,1 ;

Listing 6: Create and start black box trace with 100MB file size and 10 rollover files

Summary

The pre-defined default and blackbox traces provide forensics for proactive analysis and troubleshooting. Both are created and managed using T-SQL rather than a GUI, yet are easy to administer using simple T-SQL scripts. In the next article of this Stairway, I’ll discuss techniques on how to view and manage SQL traces.

This article is part of the parent stairway Stairway to Server-side Tracing

Rate

You rated this post out of 5. Change rating

Share

Share

Rate

You rated this post out of 5. Change rating