Extended Events – Data Analysis – XML Indexes

Background

Once one starts looking at Extended Events and realize that data is stored in XML, one will likely think will it be beneficial to index the collected XML column.

 

 

Data Model

Image

 

Code

Steps

The basic steps is that we use sys.fn_xe_file_target_read_file to read the XML file and place it in the eventStaging table.

We then use XPath to parse data from the eventStaging table into the event table.

 

Load Data From Extended Event File Into Staging Table

Code



	truncate table [extendedEvent].[eventStaging];

	insert into [extendedEvent].[eventStaging] WITH (TABLOCK)
	(
		  [objectName]	
		, [eventData]	
	)
	SELECT
 
		  [objectName] = tblFNXE.[object_name]
		, [eventData] = cast(tblFNXE.event_data as xml)
 
	FROM sys.fn_xe_file_target_read_file
		(

				case
				when (@folderXEL like '%xel%') then @folderXEL
				else @folderXEL + '' + '*.xel'
				end

			, case
					when (@folderXEM is null) then null
					when (@folderXEM like '%xe%') then @folderXEM
					else isNull(@folderXEM, @folderXEL) + '' + '*.xem'
				end	

			, null

			, null

		) tblFNXE

Load Data From Staging Table into DB Column Table

Code




select top ( 
				  isNull(@maxNumberofRecords, 1E10)
			   )
 
			  [objectName] = isNull(cte.[objectName], '')
 
			, [eventData] = cast(cte.eventData as xml)
			--, [XMLFragment] = [event].[node].query('.')
 
 
			--collect system time
			, [systemTSAsUTC]
				= 	(
						[event].[node].value
							(
								'(action[@name="collect_system_time"])[1]'
								, 'datetime'
							)
					)

			-- collect system time to locale time
			, [systemTSAsLocale] 
				 = dateadd
					(
						  minute
						, @timeDifferenceBetweenUTCAndSystemTimeInMinutes
						, (
							[event].[node].value
							(
									'(action[@name="collect_system_time"])[1]'
								, 'datetime'
							)
						)
					)

			--is system
			, [isSystem] 
				= case 
						[event].[node].value
						(	
							  '(action[@name="is_system"])[1]'
							, 'char(10)'
						)
							when 'true' then 'Y'
							else 'N'
				end
				
			--session ID
			, [sessionID] 
				= [event].[node].value
				  (
					  '(action[@name="session_id"])[1]'
					, 'int'
				  )

			-- database name
			, [dbname] 
				= [event].[node].value
				  (
					  '(action[@name="database_name"])[1]'
					, 'sysname'
				  )
 
			-- client Host Name
			, [clientHostName] 
				= [event].[node].value
				  (
					  '(action[@name="client_hostname"])[1]'
					, 'sysname'
				  )
 
			-- username
			, [username] 
				= [event].[node].value
				  (
					  '(action[@name="session_server_principal_name"])[1]'
					, 'sysname'
				  )

			-- client App Name
			, [clientAppName] 
				= [event].[node].value
				  (
					  '(action[@name="client_app_name"])[1]'
					, 'sysname'
				  )
 
			-- SQL Text
			, [sqlText] 
				= [event].[node].value
				  (
					  '(action[@name="sql_text"])[1]'
					, 'nvarchar(max)'
				  )

			-- Result
			, [result]
				= [event].[node].value
				  (
					  '(data[@name="result"]/text/text())[1]'
					, 'sysname'
				  )

			-- Error Number
			, [errorNumber]
				= [event].[node].value
				  (
					  '(data[@name="error_number"])[1]'
					, 'int'
				  )

			-- severity
			, [severity]
				= [event].[node].value
				  (
					  '(data[@name="severity"])[1]'
					, 'int'
				  )
 
			-- Message
			, [message] 
				= [event].[node].value
				  (
					  '(data[@name="message"])[1]'
					, 'nvarchar(max)'
				  )


 			, [attachActivityID]
				= [event].[node].value
				  (
					  '(event/action[@name="attach_activity_id"]/value)[1]'
					, 'varchar(50)'
				  )


			--duration
			, [duration] 
				= [event].[node].value
				  (
					  '(data[@name="duration"]/value/text())[1]'
					, 'bigint'
				  )

			--cputime
			, [cputime] 
				= [event].[node].value
				  (
					  '(data[@name="cpu_time"]/value/text())[1]'
					, 'bigint'
				  )
	from   [extendedEvent].[eventStaging] cte
 
	cross apply cte.eventData.nodes(N'//event') event(node)

Benchmark

XML Indexes

Statistics I/O & Timing

Image

Trial #1

Trial #2

Trial #3

Tabulate

 

Trial# Step IO Stats Time Taken
#1  
Import data from xml file into staging table  182 secs.
 Table ‘xml_index_nodes_373576369_256000’. Scan count 0, logical reads 24969927, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
 Table ‘Worktable’. Scan count 3, logical reads 268066, physical reads 0, read-ahead reads 0, lob logical reads 143904, lob physical reads 0, lob read-ahead reads 5.
 Table ‘eventStaging’. Scan count 0, logical reads 167819, physical reads 0, read-ahead reads 0, lob logical reads 4, lob physical reads 0, lob read-ahead reads 0.
Copy Data from staging table to actual table  207 secs.
 Table ‘eventFile’. Scan count 0, logical reads 72752, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
 Table ‘event’. Scan count 0, logical reads 420862, physical reads 0, read-ahead reads 0, lob logical reads 1, lob physical reads 0, lob read-ahead reads 0.
 Table ‘Worktable’. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 3400, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
 Table ‘xml_index_nodes_373576369_256000’. Scan count 3707011, logical reads 15613316, physical reads 0, read-ahead reads 0, lob logical reads 1, lob physical reads 0, lob read-ahead reads 0.
 Table ‘Worktable’. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
 Table ‘eventStaging’. Scan count 0, logical reads 109128, physical reads 0, read-ahead reads 0, lob logical reads 3, lob physical reads 0, lob read-ahead reads 2.
#2  
Import data from xml file into staging table  169 secs.
Table ‘xml_index_nodes_373576369_256000’. Scan count 0, logical reads 24969927, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table ‘Worktable’. Scan count 3, logical reads 268066, physical reads 0, read-ahead reads 0, lob logical reads 143904, lob physical reads 0, lob read-ahead reads 5.
Table ‘eventStaging’. Scan count 0, logical reads 167819, physical reads 0, read-ahead reads 0, lob logical reads 4, lob physical reads 0, lob read-ahead reads 0.
Copy Data from staging table to actual table  196 secs.
 Table ‘eventFile’. Scan count 0, logical reads 72752, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob
Table ‘event’. Scan count 0, logical reads 420862, physical reads 0, read-ahead reads 0, lob logical reads 1, lob physical reads 0, lob read-ahead reads 0.
Table ‘Worktable’. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 3400, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table ‘xml_index_nodes_373576369_256000’. Scan count 3707011, logical reads 15613315, physical reads 0, read-ahead reads 0, lob logical reads 1, lob physical reads 0, lob read-ahead reads 0.
Table ‘Worktable’. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
 Table ‘eventStaging’. Scan count 0, logical reads 109128, physical reads 0, read-ahead reads 0, lob logical reads 3, lob physical reads 0, lob read-ahead reads 2.
#3  
Import data from xml file into staging table  169 secs.
Table ‘xml_index_nodes_373576369_256000’. Scan count 0, logical reads 24969927, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table ‘Worktable’. Scan count 3, logical reads 268066, physical reads 0, read-ahead reads 0, lob logical reads 143904, lob physical reads 0, lob read-ahead reads 5.
Table ‘eventStaging’. Scan count 0, logical reads 167819, physical reads 0, read-ahead reads 0, lob logical reads 4, lob physical reads 0, lob read-ahead reads 0.
Copy Data from staging table to actual table  199 secs.
Table ‘Worktable’. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table ‘eventFile’. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table ‘event’. Scan count 0, logical reads 428556, physical reads 0, read-ahead reads 0, lob logical reads 1, lob physical reads 0, lob read-ahead reads 0.
Table ‘xml_index_nodes_373576369_256000’. Scan count 3707011, logical reads 15613333, physical reads 0, read-ahead reads 0, lob logical reads 1, lob physical reads 0, lob read-ahead reads 0.
Table ‘Worktable’. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
 Table ‘eventStaging’. Scan count 1, logical reads 12130, physical reads 0, read-ahead reads 0, lob logical reads 3, lob physical reads 0, lob read-ahead reads 2.

 

 

Query Plan

Insert Data from Extended Event Into Staging DB

Image

Explanation
  1. Maintaining XML Indexes is most expensive
    • Clustered Index Insert (xml_index_nodes_*)
  2. Table Spools
    • Reading File from XML File into staging table
    • Prepare data in preparation for XML Index maintenance

 

No XML Indexes

Image

Trial #1

Trial #2

Trial #3

Tabulate

 

Trial# Step IO Stats Time Taken
#1  
Import data from xml file into staging table  41 secs.
Table ‘eventStaging’. Scan count 0, logical reads 167819, physical reads 0, read-ahead reads 0, lob logical reads 1, lob physical reads 0, lob read-ahead reads 0.
 Table ‘Worktable’. Scan count 1, logical reads 74512, physical reads 0, read-ahead reads 0, lob logical reads 143904, lob physical reads 0, lob read-ahead reads 5.
Copy Data from staging table to actual table  178 secs.
 Table ‘Worktable’. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
 Table ‘eventFile’. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table ‘event’. Scan count 0, logical reads 428556, physical reads 0, read-ahead reads 0, lob logical reads 1, lob physical reads 0, lob read-ahead reads 0.
Table ‘eventStaging’. Scan count 1, logical reads 12130, physical reads 0, read-ahead reads 0, lob logical reads 77, lob physical reads 0, lob read-ahead reads 2.
#2  
Import data from xml file into staging table  19 secs.
Table ‘eventStaging’. Scan count 0, logical reads 167819, physical reads 0, read-ahead reads 0, lob logical reads 1, lob physical reads 0, lob read-ahead reads 0.
Table ‘Worktable’. Scan count 1, logical reads 74512, physical reads 0, read-ahead reads 0, lob logical reads 143904, lob physical reads 0, lob read-ahead reads 5.
Copy Data from staging table to actual table  137 secs.
Table ‘Worktable’. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table ‘eventFile’. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table ‘event’. Scan count 0, logical reads 428556, physical reads 0, read-ahead reads 0, lob logical reads 1, lob physical reads 0, lob read-ahead reads 0.
Table ‘eventStaging’. Scan count 1, logical reads 12130, physical reads 0, read-ahead reads 0, lob logical reads 77, lob physical reads 0, lob read-ahead reads 2.
#3  
Import data from xml file into staging table  35 secs.
Table ‘eventStaging’. Scan count 0, logical reads 167819, physical reads 0, read-ahead reads 0, lob logical reads 1, lob physical reads 0, lob read-ahead reads 0.
Table ‘Worktable’. Scan count 1, logical reads 74511, physical reads 0, read-ahead reads 0, lob logical reads 143904, lob physical reads 0, lob read-ahead reads 5.
Copy Data from staging table to actual table  115 secs.
Table ‘Worktable’. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table ‘eventFile’. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table ‘event’. Scan count 0, logical reads 428556, physical reads 0, read-ahead reads 0, lob logical reads 1, lob physical reads 0, lob read-ahead reads 0.
Table ‘eventStaging’. Scan count 1, logical reads 12130, physical reads 0, read-ahead reads 0, lob logical reads 77, lob physical reads 0, lob read-ahead reads 2.

 

 

 

Summary

Having XML Indexes on the staging table resulted in much more IO.

We ran two trials and timed 182 and 169 seconds.

Without indexes, our timing was 41 and 19 seconds.

Querying the XML Column was only slightly more performant with Indexes.

Leave a Reply

Please log in using one of these methods to post your comment:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s