An XEvent a Day (10 of 31) – Targets Week – etw_classic_sync_target

Yesterday’s post, Targets Week – pair_matching, looked at the pair_matching Target in Extended Events and how it could be used to find unmatched Events.  Today’s post will cover the etw_classic_sync_target Target, which can be used to track Events starting in SQL Server, out to the Windows Server OS Kernel, and then back to the Event completion in SQL Server.

What is the etw_classic_sync_target Target?

The etw_classic_sync_target Target is the target that hooks Extended Events in SQL Server into Event Tracing for Windows (ETW).  Event Tracing for Windows is a general purpose, high speed tracing mechanism provided by the Windows Server OS that allows for in-depth analysis and correlation of events from multiple applications, as well as the Windows Kernel.  ETW was first introduced in Windows Server 2000, was then expanded on in Windows Server 2003, and Windows Server 2008 and Windows Server 2008 R2 built significantly on the ETW tracing available in the OS.  For a background on ETW as a concept, I’d recommend that you read Event Tracing: Improve Debugging And Performance Tuning With ETW.

It might surprise you to know that ETW integration with SQL Server wasn’t entirely new in Extended Events.  The first integration with ETW actually occurred in SQL Server 2005 and was talked about on the SQL Query Processing Team’s blog post Using ETW for SQL Server 2005 back in 2006.  The ETW integration in SQL Server 2005 was trace based integration, and is similar to as well as different from the ETW integration that exists through Extended Events.  There are two providers available currently in ETW in the Windows Server OS, a classic provider (Windows Server 2000 and newer), and a manifest based provider (Windows Vista and Server 2008 and newer) (http://msdn.microsoft.com/en-us/library/aa363668(VS.85).aspx#providers).  The etw_classic_sync_target uses the classic provider for buffering events to ETW to ensure that backwards compatibility is maintained for the supported Operating Systems that SQL Server can run on.

Unlike the other targets available in Extended Events, the output of the etw_classic_sync_target is not available inside of SQL Server through a DMV or even by querying a DMF, since the events are buffered to ETW which is an OS based mechanism.  Currently, there can only be one ETW Session for Extended Events at a time, and that session is named XE_DEFAULT_ETW_SESSION.  The XE_DEFAULT_ETW_SESSION is created the first time a ETW Target is registered in an Event Session and is reused by subsequent Event Sessions that register an ETW Target in SQL Server.  If multiple Event Sessions utilize the etw_classic_sync_target on a server, even if they exist in multiple instances of SQL Server, the Events fired by the Event Sessions all use the XE_DEFAULT_ETW_SESSION session in ETW.  This makes isolation of Events to single instance impossible under the current design unless the Event Sessions are run independently instead of concurrently.

Unlike the other Targets available in Extended Events, the ETW session created the first time that the etw_classic_sync_target is registered in an active Event Session is not removed when the etw_classic_sync_target is dropped from the Event Session, or when the Event Session is stopped.  The only way to remove the XE_DEFAULT_ETW_SESSION is with command line commands to one of the ETW consumers available in Window; either logman or xperf if installed.  Also in contrast to the other targets, the XE_DEFAULT_ETW_SESSION requires manual flushing to ensure that Events are processed before removing the XE_DEFAULT_ETW_SESSION ETW session in the OS.  

Configuration Options

There are five configuration options for the etw_classic_sync_target Target in Extended Events.  All of the configuration options are optional.  The default_etw_session_logfile_path can be used to specify the path to the log file created by the ETW Session for logging the Events.  Once this file path has been set, it can not be changed while the XE_DEFAULT_ETW_SESSION ETW session exists in Windows, the default file location is %TEMP%\XEEtw.etl.  If you are utilizing the etw_classic_sync_target Target in multiple Event Sessions or multiple Instance of SQL Server on the same OS, it is important to maintain consistency in the definition of this option.  The default_etw_session_buffer_size_kb specifies the default size of the in-memory buffers for the ETW session, the default buffer size is 128KB.  The default_etw_session_logfile_size_mb specifies the size of the file used to store the events sent to the ETW session, the default size is 20MB.  The retries option specifies the number of attempts that the Extended Event Engine will retry publishing the events to the ETW Session if the initial attempt to publish the events fails, the default value is 0 retry attempts, meaning that the Event will be dropped if they fail on the first attempt.  The default_xe_session_name specifies the name of the ETW session to create in the ETW subsystem for the Event Session, the default is XE_DEFAULT_ETW_SESSION.

-- Target Configurable Fields
SELECT 
   oc.name AS column_name,
   oc.column_id,
   oc.type_name,
   oc.capabilities_desc,
   oc.description
FROM sys.dm_xe_packages AS p
JOIN sys.dm_xe_objects AS o 
    ON p.guid = o.package_guid
JOIN sys.dm_xe_object_columns AS oc 
    ON o.name = oc.OBJECT_NAME 
   AND o.package_guid = oc.object_package_guid
WHERE(p.capabilities IS NULL OR p.capabilities & 1 = 0)
  AND (o.capabilities IS NULL OR o.capabilities & 1 = 0)
  AND o.object_type = 'target'
  AND o.name = 'etw_classic_sync_target'

Understanding the Target Data Format

Unlike the other Targets in Extended Events, that etw_classic_sync_target Target data format depends on a number of factors, specifically on which ETW consumer, and what options are specified for the consumer for exporting the information into a user consumable format.  To be perfectly honest as much as I have played with the etw_classic_sync_target, I have yet to figure out all of the possible options for consuming the ETW session data that can be generated.  There are a number of available tools for consuming ETW session data, including logman, tracerpt, and xperf. 

A wide variety of output formats is possible including text, CSV, and XML, and when using Windows Vista or Windows Server 2008 as the system of analysis, xperfview can be be used to provide a graphical output of the ETW session data from from the .etl file.  For this reason I will not attempt to cover all of the formats available for consuming ETW session information, but will instead leave that up to the reader to investigate.

Querying/Parsing the Target Data

One of the topics not yet covered in this series is the fact that inside of Extended Events in SQL Server, every Event has an associated Channel and Keyword associated with it that maps to a Channel and Keyword in ETW.  Inside of ETW, the channel defines the intended audience for the Event, and the Keyword provides an application specific grouping of events.  This information can be queried from the sys.dm_xe_object_columns DMV by joining it to the sys.dm_xe_map_values DMV as follows:

-- Event ETW Keyword/Channel pairings
SELECT 
    package_name,
    object_name,
    CHANNEL as channel_name,
    KEYWORD as keyword_name
FROM
(
SELECT 
    p.name AS package_name, 
    o.name AS object_name,
    oc.name AS column_name,
    mv1.map_value
FROM sys.dm_xe_packages p
JOIN sys.dm_xe_objects o
    ON p.guid = o.package_guid
JOIN sys.dm_xe_object_columns oc
    ON o.package_guid = oc.object_package_guid
        AND o.name = oc.object_name
LEFT JOIN sys.dm_xe_map_values mv1 
    on oc.type_name = mv1.name 
        and oc.column_value = mv1.map_key
WHERE oc.name IN ('CHANNEL', 'KEYWORD')
    -- Filter out private internal use only objects
  AND (p.capabilities IS NULL OR p.capabilities & 1 = 0)
  AND (o.capabilities IS NULL OR o.capabilities & 1 = 0)
  AND (oc.capabilities IS NULL OR oc.capabilities & 1 = 0)
) AS tab
PIVOT
( 
    MAX(map_value)
    FOR column_name IN ([CHANNEL], [KEYWORD])
) as pvt
ORDER BY CHANNEL, KEYWORD, package_name, object_name

 

When planning Event Sessions in general, using the Channels and Keywords of Events to identify events of interest can be very useful, especially when first learning Extended Events.  In relation to ETW, they provide the integration

 

IF EXISTS(SELECT * 
         FROM sys.server_event_sessions 
         WHERE name='etw_test_session') 
    DROP EVENT SESSION [etw_test_session] ON SERVER; 
CREATE EVENT SESSION [etw_test_session] 
ON SERVER 
ADD EVENT sqlserver.file_read( 
     ACTION (sqlserver.database_id, sqlserver.session_id)), 
ADD EVENT sqlserver.file_read_completed( 
     ACTION (sqlserver.database_id, sqlserver.session_id)), 
ADD EVENT sqlos.async_io_requested( 
     ACTION (sqlserver.database_id, sqlserver.session_id)), 
ADD EVENT sqlos.async_io_completed( 
     ACTION (sqlserver.database_id, sqlserver.session_id)), 
ADD EVENT sqlos.wait_info( 
     ACTION (sqlserver.database_id, sqlserver.session_id)), 
ADD EVENT sqlserver.sql_statement_starting( 
     ACTION (sqlserver.database_id, sqlserver.plan_handle, 
            sqlserver.session_id, sqlserver.sql_text)), 
ADD EVENT sqlserver.sql_statement_completed( 
     ACTION (sqlserver.database_id, sqlserver.plan_handle, 
            sqlserver.session_id, sqlserver.sql_text)) 
-- ADD ETW target 
ADD TARGET package0.etw_classic_sync_target (
       SET default_etw_session_logfile_path = N'C:\SQLBlog\sqletwtarget.etl')
WITH (MAX_MEMORY = 4096KB, 
     EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS, 
     MAX_DISPATCH_LATENCY = 5 SECONDS, 
     MAX_EVENT_SIZE = 4096KB, 
     MEMORY_PARTITION_MODE = PER_CPU, 
     TRACK_CAUSALITY = ON, 
     STARTUP_STATE = OFF) 
GO

This Event Session will capture SQL statements from start to complete as well as the file read operations performed by the database engine to satisfy the request.  To get the OS Kernel information using ETW we will need to start a Kernel

logman start "NT Kernel Logger" /p "Windows Kernel Trace" (process,thread,disk) /o C:\SQLBlog\systemevents.etl /ets

With the NT Kernel Logger started and capturing kernel level process, thread, and disk events into the systemevents.etl file, we can now start our Extended Events Session in SQL Server, and run our test workload.  To ensure that we get physical reads from disk the following example will clear the Buffer Cache before starting the Event Session.

USE [AdventureWorks2008] 
GO 
-- Clear the Buffer Cache to force reads from Disk 
DBCC DROPCLEANBUFFERS 
GO 

-- Start the Event Session so we capture the Events caused by running the test 
ALTER EVENT SESSION etw_test_session 
ON SERVER 
STATE=START 
GO 

If you run this on a SQL Server where you use a minimal privilege AD Account for the SQL Server Service Account, you will get an error similar to the following:

Msg 25641, Level 16, State 0, Line 2

For target, "CE79811F-1A80-40E1-8F5D-7445A3F375E7.package0.etw_classic_sync_target", the parameter "default_etw_session_logfile_path" passed is invalid.  The operating system returned error 5 (ACCESS_DENIED) while creating an ETW tracing session.  Ensure that the SQL Server startup account is a member of the ‘Performance Log Users’ group and then retry your command.

If this occurs, the Service Account does not have sufficient privileges to use the ETW provider, and it will be necessary to add the SQL Service Account to the Performance Log Users group on the SQL Server and then restart the SQL Server Database Engine service for the permissions change to take effect.  (Yet another pre/post Installation Checklist item that needs to be performed!)  Once the Event Session is started, we can run a query to generate some Events and cause physical reads to occur from disk.

-- Run the Simple SELECT against AdventureWorks 
SELECT SUM(TotalDue), SalesPersonID 
FROM Sales.SalesOrderHeader 
GROUP BY SalesPersonID 
GO 

Once the query completes we can stop our Event SessionWith we can stop the NT Kernel Logger using the logman utility again:

logman update "NT Kernel Logger" /fd /ets

logman stop "NT Kernel Logger" /ets

With the Kernel Logger stopped, we can then stop our Event Session inside of SQL Server:

---- Start the Event Session so we capture the Events caused by running the test 
ALTER EVENT SESSION etw_test_session 
ON SERVER 
STATE=STOP

However, even though we stopped the Event Session in SQL Server, the XE_DEFAULT_ETW_SESSION still exists in the Windows OS.

logman query -ets

Or if you are using Windows Server 2008/2008R2, the Performance Monitor can show you the Event Session:

In either case we need to flush the buffers for the XE_DEFAULT_ETW_SESSION and in this case stop it.

logman update XE_DEFAULT_ETW_SESSION /fd /ets

logman stop XE_DEFAULT_ETW_SESSION /ets

With the two ETW sessions stopped, we can now use tracerpt to merge the trace files together and output them to a CSV file. 

(Note: The following commands are specific to Windows Server 2008/2008R2 if you are using Windows Server 2003, tracerpt does not have a –of option and will output the merged results in CSV format by default.  The default in Windows Server 2008/2008R2 is XML format.)

tracerpt C:\SQLBlog\systemevents.etl C:\SQLBlog\sqletwtarget.etl -o C:\SQLBlog\ETW_Merged.csv -of CSV

With the results merged in a CSV there are a number of options available for how to work with the data.  If we just open up the CSV file and look at scroll down through the information we can see that the SQL Server async_io_requested Events that lead to file_read events, the setting of wait_info Event and the subsequent Kernel level DiskIO Read Event.

As cool as this seems like it is, if you have done any work with ETW in Windows, you know that the future is even brighter than this simple example begins to touch on.  The Windows Performance Analyzer and xperf offer a way to read ETW trace files and generate a graphical presentation of the information held within them.  For example if we use xperf to view the Kernel Logger file:

However, the Kernel Logger uses the newer Manifest based provider in Windows Server 2008 and 2008R2, and since SQL Server 2008 Extended Events uses the classic provider, xperf doesn’t recognize the Event names for the Events contained in the ETW trace file, and instead you get a bunch of Guid’s that require manual deciphering.

 

If you happen to be running SQL Server 2008/2008R2 on Windows Server 2003, which I happen to be in most of my demonstration VM’s that I use for speaking (Windows Server 2003 takes significantly less disk space than 2008 and its at a premium on my laptops 120GB SSD), the sqletwtarget.etl and systemevents.etl files generated by this demo will have the same version and xperf can be used to open both files together and merge their respective Event Views:

The ProviderIds window is not expanded here, but it has the same Guids that the first example had.  Keep in mind that the above merged view came from a different system than the original two xperf views, but they used the same exact demo to generate.

Considerations for Usage

I have often commented in presentations that the etw_classic_sync_target Target is not something that the average DBA is going to make meaningful use of in troubleshooting problems with SQL Server.  At PASS this year, I had some eyebrows raised when I mentioned this in my presentation on Extended Events, but I stand by that statement, even after trying to brush up on ETW for this blog post, I’ve ran into numerous complications associated with actually consuming the ETW session information, that required that I perform further research to figure things out.  There is certainly meaningful information available through the use of the etw_classic_sync_target Target with Extended Events, when merged with Kernel level tracing as demonstrated later in this blog post.  However, when focusing on general troubleshooting, the etw_classic_sync_target should not be considered the target of choice.

What’s next?

Now that we have looked at all of the Targets currently available in Extended Events, in the next post we’ll look at how to utilize multiple targets in an Event Session to simplify the troubleshooting of problems in SQL Server.