Tracing usage of trace flags
May 21st, 2015
Tracing usage of trace flags
May 21st, 2015
 
 

This morning at SQLintersection, I delivered my session "SQL Server Trace Flags : A Practical Guide" for the first time. I wanted to include the core links I talked about for getting more information about trace flags (including all of the undocumented ones that have even been uttered outside of Redmond):

I also had an excellent question from the audience:

How can I tell when another session has turned a trace flag on?

One way is to review the errorlog for DBCC TRACEON events:

EXEC sys.sp_readerrorlog 0, 1, N'DBCC TRACEON';

You will see something like this for each event:

2015-05-21 17:22:19.400 spid63 DBCC TRACEON 1200, server process ID (SPID) 63.
This is an informational message only; no user action is required.

Another is to use Extended Events (and you can customize the session to include a lot more additional information that is not included in the errorlog, especially if you are on 2012+):

CREATE EVENT SESSION TraceFlags ON SERVER 
ADD EVENT sqlserver.trace_flag_changed
(
  ACTION
  (
    sqlserver.session_id,
    sqlserver.sql_text
  )
) 
ADD TARGET package0.ring_buffer;
GO
ALTER EVENT SESSION TraceFlags ON SERVER STATE = START;

Now, turn a couple of trace flags on and off, e.g.:

DBCC TRACEON(1118);
GO
DBCC TRACEON(1200,-1);
GO
WAITFOR DELAY '00:00:01';
GO
DBCC TRACEOFF(1200,-1);
GO
DBCC TRACEOFF(1118);

Then we can query the ring buffer for information (don't expect this to return sub-second):

SELECT 
  dt     = d.value(N'(@timestamp)[1]', N'datetime2'),
  flag   = d.value(N'(data[@name="flag"]/value)[1]', N'int'),
  [type] = d.value(N'(data[@name="type"]/text)[1]', N'sysname'),
  [on]   = CASE d.value(N'(data[@name="new_value"]/value)[1]', 
           N'sysname') WHEN 1 THEN 0 ELSE 1 END,
  [sql]  = d.value(N'(action[@name="sql_text"]/value)[1]', 
           N'nvarchar(max)'),
  [spid] = d.value(N'(action[@name="session_id"]/value)[1]', N'int')
FROM 
(
  SELECT x = CONVERT(XML, t.target_data)
    FROM sys.dm_xe_sessions AS s
    INNER JOIN sys.dm_xe_session_targets AS t
    ON s.[address] = t.event_session_address
    WHERE s.name = N'TraceFlags'
    AND t.target_name = N'ring_buffer'
) AS t
CROSS APPLY x.nodes(N'RingBufferTarget/event') AS x(d)
ORDER BY dt DESC;

Results will look something like this:

dt                   flag  type     on  text                     spid
-------------------  ----  -------  --  -----------------------  ----
2015-05-21 21:18:42  1118  Session  0   DBCC TRACEOFF(1118);     63
2015-05-21 21:18:42  1200  Global   0   DBCC TRACEOFF(1200,-1);  63
2015-05-21 21:18:41  1200  Global   1   DBCC TRACEON(1200,-1);   63
2015-05-21 21:18:41  1118  Session  1   DBCC TRACEON(1118);      63

It's important to note that, whether you look in the error log or extended events, you won't always see closure statements – a session could turn on a trace flag, then close the query window. SQL Server doesn't issue a TRACEOFF event, and eventually (or immediately) that session_id will get reused – so be careful not to make assumptions about the trace flags currently enabled for a session – check connect_time in sys.dm_exec_connections or login_time in sys.dm_exec_sessions and discard any earlier events associated with that spid.

By: Aaron Bertrand

I am a passionate technologist with industry experience dating back to Classic ASP and SQL Server 6.5. I am a long-time Microsoft MVP, write at Simple Talk, SQLPerformance, and MSSQLTips, and have had the honor of speaking at more conferences than I can remember. In non-tech life, I am a husband, a father of two, a huge hockey and football fan, and my pronouns are he/him.