An XEvent a Day (6 of 31) – Targets Week – asynchronous_file_target

Yesterday’s post, Targets Week – ring_buffer, looked at the ring_buffer Target in Extended Events and how it outputs the raw Event data in an XML document.  Today I’m going to go over the details of the other Target in Extended Events that captures raw Event data, the asynchronous_file_target.

What is the asynchronous_file_target?

The asynchronous_file_target holds the raw format Event data in a proprietary binary file format that persists beyond server restarts and can be provided to another person via ftp or email for remote disconnected analysis of the events.  The asynchronous_file_target has two types of files that are associated with it, the log files which contain the Event data, and the metadata file which contains information about the Events contained in the log files, allowing correct parsing of the log files and the Events and associated Actions contained within them.  Depending on the options configured for the asynchronous_file_target, there may be multiple log files associated with a started Event Session, but there will only be one metadata file created for the duration of that Event Sessions collection.  Subsequent collections by the same Event Session, for example, stopping it and starting it again at a later time, will create a new metadata file associated with that collection by the Event Session.  These files exist as a set and must be maintained together for the log files to be read.

Configuration Options

The asynchronous_file_target like the ring_buffer, has configuration options that can be found in the sys.dm_xe_object_columns DMV.

-- 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 = 'asynchronous_file_target'

 

In SQL Server 2008, 2008R2, and SQL Server Denali CTP1, there are five configuration options for the asynchronous_file_target.  The filename specifies the path and name of the log files and is a required to add the asynchronous_file_target to an Event Session.  The max_file_size option functions the same as SQL Trace maxfilesize option, limiting the size of each file before rollover occurs.  The max_rollover_files option functions the same as the SQL Trace maxrolloverfiles option, specifying the number of rollover files to maintain in the file system, and can be used in conjunction with the max_file_size option to prevent the SQL Server from running out of disk space during Event collection.  The increment option is similar to the AutoGrowth settings for a database in SQL Server, and specifies the size in megabytes that the log files grow, allowing the files to grow incrementally and reducing the number of times a log file has to grow while Events are being dispatched and buffered to the Target.  The metadatafile option specifies the path and name of the metadata file for the target.

Notice that the only mandatory option for the file target is the filename for the log files.  When the asynchronous_file_target is used in an Event Session, if the metadatafile option is not explicitly set, the asynchronous_file_target will use the same path and filename specified in the filename option with a .xem extension for the metadata file automatically. 

Understanding the Target Data Format

Like the ring_buffer, the asynchronous_file_target stores Event data in its raw format.  Inside the log files, the Event data is maintained in a binary format that minimizes the amount of space necessary to store the Events, maximizing the number of Events that can be stored inside the log files.  Unlike the ring_buffer target however, the asynchronous_file_target is queried not through the sys.dm_xe_session_targets DMV, but through the sys.fn_xe_file_target_read_file() DMF.  The sys.fn_xe_file_target_read_file() DMF requires four input parameters; @path which is the path, filename, and extension mask to the log files, @mdpath which is the path, filename, and extension mask to metadata file, @initial_file_name which is the exact path and filename of a file to start reading from and when specified requires the final parameter @initial_offset which is the offset inside that file from which to begin reading the events.

The sys.fn_xe_file_target_read_file() DMF returns a single row for each instance of Event data that is contained inside of the log files being read.  The Event data is materialized into an XML document in the event_data column output by the DMF.when the Target information is queried using the sys.fn_xe_file_target_read_file() DMF, allowing it to be used for Event analysis.  Like the ring_buffer Target, the Event data returned by the sys.fn_xe_file_target_read_file() DMF is not schema bound, but it has exactly the same XML format as an individual <event> node in the ring_buffer Targets output making it very easy to parse the Events contained in either target with very similar XQuery’s.

Querying/Parsing the Target Data

Since the asynchronous_file_target returns the Event data as XML, we have to do the same type of XQuery work to retrieve the Event data from it as we did with the ring_buffer target from yesterday.  After reading yesterday’s post, Adam Machanic (Blog|Twitter) pointed out in a comment on Twitter that the slow XML parsing is an optimizer bug that is handled with a derived table in his Extended Events Code Generator.  Adam is absolutely correct, and if you attended my session on Extended Events this year at PASS you’d recall that I didn’t have performance issues in my demo’s for querying the Target data generated by my demo’s.  I used a very different parsing method in my PASS demo’s than I showed yesterday, and I plan to cover that method in a later post in this series already.  However, if you want to see the gist of how to work around the performance issue take a look at the code output by Adam’s code generator.

I am going to reuse yesterday’s demo as a basis for looking at the asynchronous_file_target for simplicity as well as to show the similarity of the XQuery used for querying the Event data.  The basic Event Session captures the error_reported Event and to trigger an error performs a SELECT against a non-existent table.

-- Create an Event Session to capture Errors Reported
CREATE EVENT SESSION DemoPersistedEvents
ON SERVER
ADD EVENT sqlserver.error_reported
ADD TARGET package0.ring_buffer,
ADD TARGET package0.asynchronous_file_target(
     SET filename='D:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Log\DemoPersistedEvents.xel')
WITH (MAX_DISPATCH_LATENCY = 1 SECONDS)
GO
-- Alter the Event Session and Start it.
ALTER EVENT SESSION DemoPersistedEvents
ON SERVER
STATE=START
GO
-- SELECT from a non-existent table to create Event
SELECT *
FROM master.schema_doesnt_exist.table_doesnt_exist
GO
-- Drop the Event to halt Event collection
ALTER EVENT SESSION DemoPersistedEvents
ON SERVER
DROP EVENT sqlserver.error_reported
GO

The first thing we need to know to query our asynchronous_file_target is the filename and metafilename for the files that we want to query from.  If the event session is active and running, we can get this information by querying the Active Session DMV’s.

SELECT 
    soc.column_name,
    soc.column_value
FROM sys.dm_xe_sessions s
JOIN sys.dm_xe_session_object_columns soc
    ON s.address = soc.event_session_address
WHERE s.name = 'DemoPersistedEvents'
  AND soc.object_name = 'asynchronous_file_target'

Notice that the metatdatafile option is NULL, meaning that we were lazy and didn’t explicitly define the metadata file information in our Event Session so now we have to figure it out in order to query the target data from the log files.  One way to find the information would be to open up the path on the server to the log file that was specified:

Notice that the Extended Events Engine automatically created a metadata file with the same name as the log file, but a different extension, .xem.  Also notice that the file names for both the log file and the metadata file have changed from what was actually defined in the Event Session.  The Engine adds a _0_ and a long integer value that represents the number of milliseconds between January 1, 1600 and the date and time that the file was generated by the Extended Events Engine.  Subsequent files will have a different long integer value that is larger in value allowing you to easily sort the log files from oldest to newest or vice versa.  To query the data contained in the log files, you have two options.  First you can explicitly provide the filenames as shown above, or you can use wildcards in the names and the engine will find the correct matching files and begin reading them.

DECLARE @path nvarchar(260), @mdpath nvarchar(260)

-- Get the log file name and substitute * wildcard in
SELECT 
    @path = LEFT(column_value, LEN(column_value)-CHARINDEX('.', REVERSE(column_value))) 
        + '*' 
        + RIGHT(column_value, CHARINDEX('.', REVERSE(column_value))-1)
FROM sys.dm_xe_sessions s
JOIN sys.dm_xe_session_object_columns soc
    ON s.address = soc.event_session_address
WHERE s.name = 'DemoPersistedEvents'
  AND soc.object_name = 'asynchronous_file_target'
  AND soc.column_name = 'filename'

-- Get the metadata file name and substitute * wildcard in 
SELECT 
    @mdpath = LEFT(column_value, LEN(column_value)-CHARINDEX('.', REVERSE(column_value))) 
        + '*' 
        + RIGHT(column_value, CHARINDEX('.', REVERSE(column_value))-1)
FROM sys.dm_xe_sessions s
JOIN sys.dm_xe_session_object_columns soc
    ON s.address = soc.event_session_address
WHERE s.name = 'DemoPersistedEvents'
  AND soc.object_name = 'asynchronous_file_target'
  AND soc.column_name = ' metadatafile'

-- Set the metadata filename if it is NULL to the log file name with xem extension
SELECT @mdpath = ISNULL(@mdpath, 
                        LEFT(@path, LEN(@path)-CHARINDEX('*', REVERSE(@path))) 
                        + '*xem')

-- Query the Event data from the Target.
SELECT
    module_guid,
    package_guid,
    object_name,
    event_data,
    file_name,
    file_offset
FROM sys.fn_xe_file_target_read_file(@path, @mdpath, null, null)

 

 

The DMF outputs the module_guid, package_guid, and object_name associated with the Event, the event_data as a XML document, but in string format requiring that it be CAST/CONVERT’d to XML for parsing, the file_name of the log file that the Event data was read from and the file_offset inside the file for the event.  Using a CAST to XML and performing a CROSS APPLY of the <event> nodes and the same XQuery’s as in yesterday’s post we can query the Event data from the asynchronous_file_target.

-- Query the Event data from the Target.
SELECT 
    n.value('(@name)[1]', 'varchar(50)') AS event_name,
    n.value('(@package)[1]', 'varchar(50)') AS package_name,
    n.value('(@id)[1]', 'int') AS id,
    n.value('(@version)[1]', 'int') AS version,
    DATEADD(hh, 
            DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
            n.value('(@timestamp)[1]', 'datetime2')) AS [timestamp],
    n.value('(data[@name="error"]/value)[1]', 'int') as error,
    n.value('(data[@name="severity"]/value)[1]', 'int') as severity,
    n.value('(data[@name="duration"]/value)[1]', 'int') as state,
    n.value('(data[@name="user_defined"]/value)[1]', 'varchar(5)') as user_defined,
    n.value('(data[@name="message"]/value)[1]', 'varchar(max)') as message
FROM 
(SELECT
    CAST(event_data AS XML) AS event_data
 FROM sys.fn_xe_file_target_read_file(@path, @mdpath, null, null)
) as tab
CROSS APPLY event_data.nodes('event') as q(n)

Like the ring_buffer Target, the asynchronous_file_target also has an entry in sys.dm_xe_session_targets, but instead of returning the Event data, it returns information about the targets operation.

select 
    target_data.value('(FileTarget/@truncated)[1]', 'int') as truncated,
    target_data.value('(FileTarget/Buffers/@logged)[1]', 'int') as logged,
    target_data.value('(FileTarget/Buffers/@dropped)[1]', 'int') as dropped
FROM
(SELECT CAST(target_data AS XML) AS target_data
FROM sys.dm_xe_sessions AS s 
JOIN sys.dm_xe_session_targets AS t 
    ON t.event_session_address = s.address
WHERE s.name = 'DemoPersistedEvents'
  AND t.target_name = 'asynchronous_file_target'
) as tab

The file_name and file_offset information in the the sys.fn_xe_file_target_read_file output can be used to perform differential reads from the asynchronous_file_target.  To demonstrate this we can create an Event Session that will capture a lot of Events in a short period of time.

(Note: I wouldn’t create an unfiltered Event Session on the starting and completed events like this on a production server without first evaluating its potential impact.  While this should be safe, if it causes you a problem, its your server not mine.)

IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name='FileTargetDemo')
    DROP EVENT SESSION [FileTargetDemo] ON SERVER;
CREATE EVENT SESSION [FileTargetDemo]
ON SERVER
ADD EVENT sqlserver.sql_statement_starting,
ADD EVENT sqlserver.sql_statement_completed,
ADD EVENT sqlserver.sp_statement_starting,
ADD EVENT sqlserver.sp_statement_completed,
ADD EVENT sqlserver.rpc_starting,
ADD EVENT sqlserver.rpc_completed,
ADD EVENT sqlserver.module_start,
ADD EVENT sqlserver.module_end
ADD TARGET package0.asynchronous_file_target(
     SET filename='D:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Log\FileTargetDemo.xel', 
         metadatafile='D:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Log\FileTargetDemo.xem',
         max_file_size = 5,
         max_rollover_files = 5)
WITH(MAX_DISPATCH_LATENCY = 5SECONDS)
GO

-- Start the Event Collection
ALTER EVENT SESSION [FileTargetDemo]
ON SERVER
STATE=STOP
GO

-- Take a pause and allow events to be generated


-- Query the target data from the files.
SELECT 
    object_name,
    CAST(event_data as xml) as event_data,
    file_name, 
    file_offset
FROM sys.fn_xe_file_target_read_file('D:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Log\FileTargetDemo*xel', 
            'D:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Log\FileTargetDemo*xem', 
            null,
            null)

If you scroll through the output to where the file_offset changes, you can grab the file_name and file_offset for the last event in the first file_offset.

Then requery the target passing that file_name and file_offset into the @initial_file_name and @intitial_offset parameters of the sys.fn_xe_file_target_read_file DMF to have the DMF begin reading from the last entry of the provided offset forward.

-- Query the target data from the files.
SELECT 
    object_name,
    CAST(event_data as xml) as event_data,
    file_name, 
    file_offset
FROM sys.fn_xe_file_target_read_file('D:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Log\FileTargetDemo*xel', 
            'D:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Log\FileTargetDemo*xem',             
            'D:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\Log\FileTargetDemo_0_129360796797990000.xel',
            0)

If you’ve run the demo’s in this blog post to this point, don’t forget to cleanup the system.

IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name='FileTargetDemo')
    DROP EVENT SESSION [FileTargetDemo] ON SERVER;
GO
IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name='DemoPersistedEvents')
    DROP EVENT SESSION [DemoPersistedEvents] ON SERVER;
GO

Considerations for Usage

The asynchronous_file_target will probably be the preferred target for most people interested in performing long term analysis of Events collected, or performing short term analysis using an Event Session that is expected to generate a large number of events and event loss due to the FIFO nature of the ring_buffer is not acceptable.  However, there are a couple of considerations associated with this target.  The first is that the log files and metadata file are a set, and have to be maintained together.  If you send someone a log file without the metadata file, they won’t be able to read the information contained in the log file.  The second consideration associated with this target is that the only way to read the information contained inside of the log files, as of the date of this blog post being published, is to copy them to a system that is running SQL Server 2008 or 2008R2 and query the files using the there is no way to retrieve the information contained inside of the log files, without querying the sys.fn_xe_file_target_read_file() DMF using TSQL. 

What’s next?

Now that we have looked at the asynchronous_file_target Target, in the next post we’ll look at the bucketizer Targets which can be used to group occurrences of Events based on the Event data being returned.