May
31
2016

Extended Events File Target Reader

It’s been some time since I started with my first SQL-G Hack, and I think those are precisely the kind of posts you might want to find when searching for a specific problem you have right now.

It’s true that most of the time your answer is posted already in StackOverflow, but that’s another story.

This time I wanted to post this stored procedure that might help people start using more Extended Events, because, to be honest, I still find easier jump onto SQL Profiler when it’s something about checking some sort of activity or what happens in the database when I click that button (and I don’t have any developer handy) in the application.

But the output is not very friendly and once you have a target, you cannot change it, and persisting the information in a file happens to be binary, and using T-SQL you can only see it as XML and everyone hates XML, specially when you have to query it 🙂

So the other day I had to do exactly this and I ended up writing a query that reads from the file, parses the XML and PIVOT the results to get meaningful data to look at. Then I said to myself… never again, so I kept writing to have a more flexible one, so I don’t have to do it again for good.

 
First things first

So I’m going to show you how I did create my Extended Events session to track “What I do” on my SQL Server instance. You may want to customize the output file path and [server_principal_name]

CREATE EVENT SESSION [What I do] ON SERVER 

ADD EVENT sqlserver.rpc_completed(SET collect_statement=(1)
    ACTION(package0.collect_system_time,sqlserver.client_hostname,sqlserver.database_name,sqlserver.query_plan_hash
			,sqlserver.server_principal_name,sqlserver.session_id)),

ADD EVENT sqlserver.sql_statement_completed(SET collect_parameterized_plan_handle=(0),collect_statement=(1)
    ACTION(package0.collect_system_time,sqlserver.client_hostname,sqlserver.database_name,sqlserver.query_plan_hash
			,sqlserver.server_principal_name,sqlserver.session_id)
    WHERE ([sqlserver].[server_principal_name]=N'SQLDoubleG')) 

ADD TARGET package0.event_file(SET filename=N'C:\Program Files\Microsoft SQL Server\MSSQL12.MSSQL2014\MSSQL\Log\WhatIdo.xel')

WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB
		,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=ON,STARTUP_STATE=OFF)
GO

There are a couple of events I’m interested on, [rpc_completed] and [sql_statement_completed], that’s enough for my purpose, but you can choose whatever you feel like, it shouldn’t be any problem if you want to go for something different.

 
The tools

Thankfully SQL Server is full of tools, so good news is there is a function we can call to read the target file, sys.fn_xe_file_target_read_file bad news though is that all the meat inside a XML column.

Once I’ve started my session, I run a few commands.

USE AdventureWorks2014

SELECT TOP 100 * FROM Person.Address

SELECT TOP 100 * FROM Person.Person

SELECT TOP 100 * FROM Production.Product

I stopped it and find the file in location specified, please note that there is a suffix in addition to the given name.

So if we see the file using the function, it looks like

SELECT *
FROM sys.fn_xe_file_target_read_file(N'C:\Program Files\Microsoft SQL Server\MSSQL12.MSSQL2014\MSSQL\Log\WhatIdo_0_131086770842200000.xel', null, null, null);

01_fn_xe_file_target_read_file

Not very useful I guess, the information we are looking for is contained in XML

 
The XML

The XML that contains the information we want to analyse might look like the one below.

<event name="rpc_completed" package="sqlserver" timestamp="2016-05-25T19:11:24.230Z">
  <data name="cpu_time">
    <value>0</value>
  </data>
  <data name="duration">
    <value>3633</value>
  </data>
  <data name="physical_reads">
    <value>0</value>
  </data>
  <data name="logical_reads">
    <value>24</value>
  </data>
  <data name="writes">
    <value>0</value>
  </data>
  <data name="result">
    <value>0</value>
    <text>OK</text>
  </data>
  <data name="row_count">
    <value>1</value>
  </data>
  <data name="connection_reset_option">
    <value>0</value>
    <text>None</text>
  </data>
  <data name="object_name">
    <value>sp_executesql</value>
  </data>
  <data name="statement">
    <value>exec sp_executesql N'SELECT
session.name AS [Name],
''XEStore[@Name='' + quotename(CAST(SERVERPROPERTY(N''ServerName'') AS sysname),'''''''') + '']'' + ''/Session[@Name='' + quotename(session.name,'''''''') + '']'' AS [Urn],
session.startup_state AS [AutoStart],
running.create_time AS [StartTime],
(CASE WHEN (running.create_time IS NULL) THEN 0 ELSE 1 END) AS [IsRunning]
FROM
sys.server_event_sessions AS session
LEFT OUTER JOIN sys.dm_xe_sessions AS running ON running.name = session.name
WHERE
(session.name=@_msparam_0)and((CAST(SERVERPROPERTY(N''ServerName'') AS sysname)=@_msparam_1))
ORDER BY
[Name] ASC',N'@_msparam_0 nvarchar(4000),@_msparam_1 nvarchar(4000)',@_msparam_0=N'What I do',@_msparam_1=N'DESKTOP-P6AOTMB\MSSQL2014'</value>
  </data>
  <data name="data_stream">
    <value />
  </data>
  <data name="output_parameters">
    <value />
  </data>
  <action name="session_id" package="sqlserver">
    <value>51</value>
  </action>
  <action name="server_principal_name" package="sqlserver">
    <value>SQLDoubleG</value>
  </action>
  <action name="query_plan_hash" package="sqlserver">
    <value>0</value>
  </action>
  <action name="database_name" package="sqlserver">
    <value>master</value>
  </action>
  <action name="client_hostname" package="sqlserver">
    <value>DESKTOP-P6AOTMB</value>
  </action>
  <action name="collect_system_time" package="package0">
    <value>2016-05-25T19:11:24.229Z</value>
  </action>
  <action name="attach_activity_id_xfer" package="package0">
    <value>B05B6BEA-DA76-4283-94EC-4EEAAF43EA87-0</value>
  </action>
  <action name="attach_activity_id" package="package0">
    <value>33E553E3-FF64-4A8D-BD2F-1C061195AB96-1</value>
  </action>
</event>

Using SQL Server, we can query our XML column to get all the juice, but first we have to convert it to XML because it comes as plain text. So we can use a temporary table to do the trick.

IF OBJECT_ID('tempdb..#ExEvent') IS NOT NULL DROP TABLE #ExEvent

SELECT IDENTITY(INT,1,1) AS RowId, object_name AS event_name, CONVERT(XML,event_data) AS event_data
	INTO #ExEvent
FROM sys.fn_xe_file_target_read_file(N'C:\Program Files\Microsoft SQL Server\MSSQL12.MSSQL2014\MSSQL\Log\WhatIdo_0_131086770842200000.xel', null, null, null);

 
Parsing the XML

Once we have the table, we can start querying the XML to extract all that info

SELECT RowId
		, event_name
		, T2.Loc.query('.').value('(/action/@name)[1]', 'varchar(max)')AS att_name
		, T2.Loc.query('.').value('(/action/value)[1]', 'varchar(max)')AS att_value
	FROM   #ExEvent
	CROSS APPLY event_data.nodes('/event/action') as T2(Loc) 
	WHERE T2.Loc.query('.').value('(/action/@name)[1]', 'varchar(max)') 
		IN ('client_hostname', 'collect_system_time', 'database_name', 'query_plan_hash'
			, 'server_principal_name', 'session_id')

I just picked up a few columns I am interested on, but there are some others you can check.

The thing is that as you’ve seen above there are 2 different elements in the XML, the <data> and <action>, so I’ll have to do more magic to get all of them.

SELECT RowId
		, event_name
		, T3.Loc.query('.').value('(/data/@name)[1]', 'varchar(max)') AS att_name
		, T3.Loc.query('.').value('(/data/value)[1]', 'varchar(max)') AS att_value
	FROM   #ExEvent
	CROSS APPLY event_data.nodes('/event/data') as T3(Loc) 
	WHERE T3.Loc.query('.').value('(/data/@name)[1]', 'varchar(max)') 
		IN ('collect_statement', 'connection_reset_option', 'cpu_time', 'data_stream', 'duration'
			, 'last_row_count', 'line_number', 'logical_reads', 'object_name', 'offset'
			, 'offset_end', 'output_parameters', 'parameterized_plan_handle', 'physical_reads'
			, 'result', 'row_count', 'statement', 'writes')

Each of those queries above will return a list of actions and events respectively along the current value for each time the event was triggered during the session.

02_select_cross_apply_nodes

Still not very useful, I’d rather see this like one event one line, so another top favourite for each DBA, PIVOT!!! there we go

SELECT RowId, event_name, [client_hostname], [collect_system_time], [database_name], [query_plan_hash], [server_principal_name], [session_id]					
	FROM (
			SELECT RowId
					, event_name
					, T2.Loc.query('.').value('(/action/@name)[1]', 'varchar(max)')AS att_name
					, T2.Loc.query('.').value('(/action/value)[1]', 'varchar(max)')AS att_value
			FROM   #ExEvent
			CROSS APPLY event_data.nodes('/event/action') as T2(Loc) 
			WHERE T2.Loc.query('.').value('(/action/@name)[1]', 'varchar(max)') 
				IN ('client_hostname', 'collect_system_time', 'database_name', 'query_plan_hash', 'server_principal_name', 'session_id')
		) AS SourceTable
			PIVOT(
				MAX(att_value)
				FOR att_name IN ([client_hostname], [collect_system_time], [database_name], [query_plan_hash], [server_principal_name], [session_id])
		) AS PivotTable

03_PIVOT
That looks much better, thanks!

 
Final output

But to get all information I have used 2 different queries, so now if you were wondering why I generated an IDENTITY column, this is why, so I can join both, <data> and <action> and generate a unique row per event in the file.

Let’s go for it!

SELECT ISNULL(t_action.RowId, t_data.RowId) AS RowId
		, ISNULL(t_action.event_name, t_data.event_name) AS event_name
		, t_action.[client_hostname], t_action.[collect_system_time], t_action.[database_name], t_action.[query_plan_hash], t_action.[server_principal_name], t_action.[session_id]
		, t_data.[collect_statement], t_data.[connection_reset_option], t_data.[cpu_time], t_data.[data_stream], t_data.[duration], t_data.[last_row_count], t_data.[line_number], t_data.[logical_reads], t_data.[object_name], t_data.[offset], t_data.[offset_end], t_data.[output_parameters], t_data.[parameterized_plan_handle], t_data.[physical_reads], t_data.[result], t_data.[row_count], t_data.[statement], t_data.[writes]
	FROM (
			SELECT RowId, event_name, [client_hostname], [collect_system_time], [database_name], [query_plan_hash], [server_principal_name], [session_id]					
				FROM (
						SELECT RowId
								, event_name
								, T2.Loc.query('.').value('(/action/@name)[1]', 'varchar(max)')AS att_name
								, T2.Loc.query('.').value('(/action/value)[1]', 'varchar(max)')AS att_value
						FROM   #ExEvent
						CROSS APPLY event_data.nodes('/event/action') as T2(Loc) 
						WHERE T2.Loc.query('.').value('(/action/@name)[1]', 'varchar(max)') 
							IN ('client_hostname', 'collect_system_time', 'database_name', 'query_plan_hash', 'server_principal_name', 'session_id')
					) AS SourceTable
						PIVOT(
							MAX(att_value)
							FOR att_name IN ([client_hostname], [collect_system_time], [database_name], [query_plan_hash], [server_principal_name], [session_id])
					) AS PivotTable
			) AS t_action
		
		-- Full outer because it might be no events selected only the payload
		FULL OUTER JOIN (
			SELECT RowId, event_name, [collect_statement], [connection_reset_option], [cpu_time], [data_stream], [duration], [last_row_count], [line_number], [logical_reads], [object_name], [offset], [offset_end], [output_parameters], [parameterized_plan_handle], [physical_reads], [result], [row_count], [statement], [writes]
				FROM (
						SELECT RowId
								, event_name
								, T3.Loc.query('.').value('(/data/@name)[1]', 'varchar(max)') AS att_name
								, T3.Loc.query('.').value('(/data/value)[1]', 'varchar(max)') AS att_value

							FROM   #ExEvent
							CROSS APPLY event_data.nodes('/event/data') as T3(Loc) 
							WHERE T3.Loc.query('.').value('(/data/@name)[1]', 'varchar(max)') 
								IN ('collect_statement', 'connection_reset_option', 'cpu_time', 'data_stream', 'duration', 'last_row_count', 'line_number', 'logical_reads', 'object_name', 'offset', 'offset_end', 'output_parameters', 'parameterized_plan_handle', 'physical_reads', 'result', 'row_count', 'statement', 'writes')
						) AS SourceTable
							PIVOT (
							MAX(att_value)
								FOR att_name IN ([collect_statement], [connection_reset_option], [cpu_time], [data_stream], [duration], [last_row_count], [line_number], [logical_reads], [object_name], [offset], [offset_end], [output_parameters], [parameterized_plan_handle], [physical_reads], [result], [row_count], [statement], [writes])
						) AS PivotTable

			) AS t_data
			ON t_data.RowId = t_action.RowId

And finally we can get some meaningful info, just one line per event and all the columns where had defined for the session.

04_PIVOT_and_JOINS

Yes! that works!

 
The SQL-G Hack!

Hopefully you have read all the process through and you have now a better understanding of how painful it was. But that’s what this post is for, to relieve the pain 🙂

Using DMV’s we can see how any session is defined hence dynamically we can do all the hard work and leave for us just analysing the results. Cool, innit?

USE [DBA]
GO
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
IF OBJECT_ID('dbo.sqlg_ExtendedEventFileReader') IS NULL EXECUTE sp_executesql N'CREATE PROCEDURE dbo.sqlg_ExtendedEventFileReader AS RETURN'
GO
-- =============================================
-- Author:      Raul Gonzalez @SQLDoubleG
-- Create date: 25/05/2016
-- Description: Returns the content of a Extended Event target file in a table format according to the current definition of the session
--
-- Remarks: 
--              - The session must exist in the server and so must the file in a place we can access
--              - Depending on the amount of data this process may take very long, it is recommended not to use in production systems
--              - You can offload this task by generating the query using the parameter @debugging = 1 and copying the file to another server.
--
-- Parameters:
--              - @sessionName  -> name of the extended event session
--              - @filePath     -> full path (including name) of the target file
--              - @debugging    -> will print the statement or execute it
--
-- Log History: 
--              25/05/2016 RAG - Created
--              31/03/2017 RAG - Allow 'xml_deadlock_report' events to be returned in a way you can copy/paste and save as (.xdl) file
--									for further analysis.
--              07/06/2017 RAG - Added event_timestamp column
--              08/06/2017 RAG - Return all events that return XML in XML format
--
-- Copyright:   (C) 2016 Raul Gonzalez (@SQLDoubleG http://www.sqldoubleg.com)
--
--              THIS CODE AND INFORMATION ARE PROVIDED "AS IS" WITHOUT WARRANTY OF 
--              ANY KIND, EITHER EXPRESSED OR IMPLIED, INCLUDING BUT NOT LIMITED 
--              TO THE IMPLIED WARRANTIES OF MERCHANTABILITY AND/OR FITNESS FOR A
--              PARTICULAR PURPOSE.
--
--              THE AUTHOR SHALL NOT BE LIABLE TO YOU OR ANY THIRD PARTY FOR ANY INDIRECT, 
--              SPECIAL, INCIDENTAL, PUNITIVE, COVER, OR CONSEQUENTIAL DAMAGES OF ANY KIND
--
--              YOU MAY ALTER THIS CODE FOR YOUR OWN *NON-COMMERCIAL* PURPOSES. YOU MAY
--              REPUBLISH ALTERED CODE AS LONG AS YOU INCLUDE THIS COPYRIGHT AND GIVE DUE CREDIT. 
--
-- =============================================
ALTER PROCEDURE dbo.sqlg_ExtendedEventFileReader
    @sessionName    SYSNAME       
    , @filePath     NVARCHAR(512) 
    , @debugging    BIT             = 0 -- Set to 0 to run the query, otherwise PRINT the statement
AS
   
DECLARE @sql				NVARCHAR(MAX)
  
DECLARE @actionsList		NVARCHAR(MAX)
DECLARE @actionsListFilter	NVARCHAR(MAX)
DECLARE @actionsListColumns	NVARCHAR(MAX)
  
DECLARE @eventsList			NVARCHAR(MAX)
DECLARE @eventsListFilter	NVARCHAR(MAX)
DECLARE @eventsListColumns	NVARCHAR(MAX)
   
-- Get actions from the Session
SET @actionsList		= (SELECT STUFF((SELECT DISTINCT ', ' + QUOTENAME(a.name)
                                FROM sys.server_event_sessions AS s
                                    LEFT JOIN sys.server_event_session_events AS e
                                        ON e.event_session_id = s.event_session_id
                                    INNER JOIN sys.server_event_session_actions AS a
                                        ON a.event_id = e.event_id
                                            AND e.event_session_id = a.event_session_id 
                                WHERE s.name = @sessionName
                            FOR XML PATH('')), 1, 2, ''))
   
SET @actionsListFilter	= REPLACE(REPLACE(@actionsList, '[', ''''), ']', '''')
SET @actionsListColumns = REPLACE(@actionsList, '[', 't_action.[')
   
-- Get Payload 
-- This to return events that return XML in XML format, just for the final query
SET @eventsListColumns	= (SELECT STUFF(
								(SELECT DISTINCT ', ' + 
										CASE WHEN c.type_name = 'XML' THEN 'CONVERT(XML, ' + QUOTENAME(c.name) + ') AS ' + QUOTENAME(c.name)
											ELSE 't_data.' + QUOTENAME(c.name)
										END
									FROM sys.server_event_sessions AS s
										LEFT JOIN sys.server_event_session_events AS e
											ON e.event_session_id = s.event_session_id
										LEFT JOIN sys.dm_xe_objects AS o
											ON o.name = e.name
										LEFT JOIN sys.dm_xe_object_columns AS c
											ON c.object_name = o.name
									WHERE s.name = @sessionName
										AND c.column_type <> 'readonly'
										AND ISNULL(column_value, 'true') = 'true'
								FOR XML PATH('')), 1, 2, ''))

SET @eventsList			= (SELECT STUFF(
								(SELECT DISTINCT ', ' + QUOTENAME(c.name)
									FROM sys.server_event_sessions AS s
										LEFT JOIN sys.server_event_session_events AS e
											ON e.event_session_id = s.event_session_id
										LEFT JOIN sys.dm_xe_objects AS o
											ON o.name = e.name
										LEFT JOIN sys.dm_xe_object_columns AS c
											ON c.object_name = o.name
									WHERE s.name = @sessionName
										AND c.column_type <> 'readonly'
										AND ISNULL(column_value, 'true') = 'true'
								FOR XML PATH('')), 1, 2, ''))
   
SET @eventsListFilter   = REPLACE(REPLACE(@eventsList, '[', ''''), ']', '''')
   
SET @sql = N'
   
IF OBJECT_ID(''tempdb..#ExEvent'') IS NOT NULL DROP TABLE #ExEvent
   
SELECT IDENTITY(INT,1,1) AS RowId, object_name AS event_name, CONVERT(XML,event_data) AS event_data
    INTO #ExEvent
FROM sys.fn_xe_file_target_read_file(N''' + @filePath + ''', null, null, null);
   
--=======================================================================================================
-- Usually here I would remove events I am not interested on, because the next query can take very long
--
--SELECT TOP 100 * FROM #ExEvent ORDER BY event_name
--
-- DELETE #ExEvent
--WHERE event_name [NOT] IN (N''rpc_completed'')
--=======================================================================================================
   
SELECT ISNULL(t_action.RowId, t_data.RowId) AS RowId
        , ISNULL(t_action.event_name, t_data.event_name) AS event_name
        , ISNULL(t_action.event_timestamp, t_data.event_timestamp) AS event_timestamp
        , ' + @actionsListColumns + N'
        , ' + @eventsListColumns + N'
    FROM (
            SELECT RowId, event_name, event_timestamp, ' + @actionsList + N'                 
                FROM (
                    SELECT RowId
                            , event_name
                            , T1.Loc.query(''.'').value(''(/event/@timestamp)[1]'', ''varchar(max)'') AS event_timestamp
                            , T2.Loc.query(''.'').value(''(/action/@name)[1]'', ''varchar(max)'')AS att_name
                            , T2.Loc.query(''.'').value(''(/action/value)[1]'', ''varchar(max)'')AS att_value
						FROM   #ExEvent
							CROSS APPLY event_data.nodes(''/event'') as T1(Loc) 
							CROSS APPLY event_data.nodes(''/event/action'') as T2(Loc) 
						WHERE T2.Loc.query(''.'').value(''(/action/@name)[1]'', ''varchar(max)'') 
							IN (' + @actionsListFilter  + N')
                    ) AS SourceTable
                        PIVOT(
                            MAX(att_value)
                            FOR att_name IN (' + @actionsList + N')
                    ) AS PivotTable
            ) AS t_action
           
        -- Full outer because it might be no events selected only the payload
        FULL OUTER JOIN (
            SELECT RowId, event_name, event_timestamp, ' + @eventsList + N'
                FROM (
                    SELECT RowId
                            , event_name
                            , T1.Loc.query(''.'').value(''(/event/@timestamp)[1]'', ''varchar(max)'') AS event_timestamp
                            , T3.Loc.query(''.'').value(''(/data/@name)[1]'', ''varchar(max)'') AS att_name
                            , CASE 
									-- deadlock report in xml to allow it to be saved as xdl
									WHEN event_name = ''xml_deadlock_report'' 
										THEN CONVERT(NVARCHAR(MAX), event_data.query(''/event/data/value/deadlock'')) 
									-- rest of events that return xml
									WHEN event_name IN (SELECT object_name FROM sys.dm_xe_object_columns
															WHERE type_name = ''xml'' AND name NOT IN (''xml_deadlock_report''))
										THEN CONVERT(NVARCHAR(MAX), event_data.query(''/event'')) 
									-- rest of events
									ELSE T3.Loc.query(''.'').value(''(/data/value)[1]'', ''varchar(max)'') 
								END AS att_value
                        FROM   #ExEvent
							CROSS APPLY event_data.nodes(''/event'') as T1(Loc) 
							CROSS APPLY event_data.nodes(''/event/data'') as T3(Loc) 
                        WHERE T3.Loc.query(''.'').value(''(/data/@name)[1]'', ''varchar(max)'') 
                            IN (' + @eventsListFilter  + N')
                        ) AS SourceTable
                            PIVOT (
                            MAX(att_value)
                                FOR att_name IN (' + @eventsList + N')
                        ) AS PivotTable
            ) AS t_data
            ON t_data.RowId = t_action.RowId
'
   
IF @debugging = 1 
    SELECT CONVERT(XML, @sql)
ELSE
    EXECUTE sp_executesql @sql
GO

And that was all folks! Hope you find it useful and any feedback is always welcome.

8 comments
  1. Pedro says:

    Really cool! I have just tested and works fine. Thanks Raul!

    • Raul says:

      Thanks Pedro! glad you like it. Just be aware of the overhead if you want to query multiple files or they’re very long.

      You can offload it by generating the query and tweaking it for your needs, maybe to output to a physical table instead of temporary?

      Cheers!

  2. Theo Ekelmans says:

    Man…. was i ever struggling with decoding extended event XML, and your article made it much clearer to me by showing how you worked to decodeing it.

    Read, copy steps, experiment by taking code apart…. thinking, failing, correcting, adding to the framework, adapting to suit my own needs…. *smiling wide*… posting this thanks!

  3. phú says:

    thank so much, your articles is awsome

  4. Robert Sievers says:

    Absolutely love this stored procedure. I made what I feel is an improvement. If you want to see the execution plan, you can pull the XML fragment from the full XML of the query_post_execution_showplan event as follows.

    WHEN event_name = ”xml_deadlock_report”
    THEN CONVERT(NVARCHAR(MAX), event_data.query(”/event/data/value/deadlock”))
    WHEN event_name = ”query_post_execution_showplan”
    THEN CONVERT(NVARCHAR(MAX), event_data.query(”/event/data[@name=”showplan_xml”]/value/*”))
    — rest of events that return xml
    WHEN event_name IN (SELECT object_name FROM sys.dm_xe_object_columns
    WHERE type_name = ”xml” AND name NOT IN (”xml_deadlock_report”,”query_post_execution_showplan”))

Leave a Reply

Your email address will not be published. Required fields are marked *