SQL Server – Extended Event – Data Storage – Change Folder / File Name

Background

Due to Storage Constraints having to change the folder that Extended Events are captured in.

 

GUI

I know it is not possible to do so via GUI.

As shown below, just as your author, the properties are dimmed.

 


Script

So let us script it

Outline

  1. Stop the Extended Event Session
  2. Drop the Extended Event Session target
    • In our case, we are using the adopted default target name of package0.event_file
  3. Add a new Target
    • Keeping everything from the old target
    • But, changing the targeted folder
  4. Restart the Extended Event Session

Code




	ALTER EVENT SESSION [performance]   
	ON SERVER  
	STATE = stop;  

	ALTER EVENT SESSION [performance]  
		ON SERVER 
		DROP TARGET package0.event_file;

	ALTER EVENT SESSION [performance]  
		ON SERVER 
		ADD TARGET package0.event_file
		(
			SET 
				  filename=N'C:\Microsoft\SQLServer\ExtendedEvents\TraceFiles\performance.xel'
				, max_file_size=(100)
				, max_rollover_files=(100)
		)

	ALTER EVENT SESSION [performance]   
	ON SERVER  
	STATE = start;  

GO 

Xpath Query – Compare Positional Versus Condition

Background

As always too much time on my hands.

I wanted to compare the query generated by XMLToolBox against one I tweaked gently.

Here is the post that introduces XMLToolBox.

 

Lab

Queries

XPath – Position


set nocount on;
go

declare @xml XML

set @xml=
'
<event name="sql_batch_completed" package="sqlserver" timestamp="2017-05-01T16:44:02.507Z">
  <data name="cpu_time">
    <value>250000</value>
  </data>
  <data name="duration">
    <value>226002957</value>
  </data>
  <data name="physical_reads">
    <value>16349</value>
  </data>
  <data name="logical_reads">
    <value>16197</value>
  </data>
  <data name="writes">
    <value>0</value>
  </data>
  <data name="row_count">
    <value>0</value>
  </data>
  <data name="result">
    <value>2</value>
    <text>Abort</text>
  </data>
  <data name="batch_text">
    <value>SELECT "dbo"."basetblb"."base_social" FROM "dbo"."basetblb" WHERE (("base_payroll_status" = ''A'' ) AND ("base_service_credit" &gt; 10 ) ) </value>
  </data>
  <action name="sql_text" package="sqlserver">
    <value>SELECT "dbo"."basetblb"."base_social" FROM "dbo"."basetblb" WHERE (("base_payroll_status" = ''A'' ) AND ("base_service_credit" &gt; 10 ) ) </value>
  </action>
  <action name="session_server_principal_name" package="sqlserver">
    <value>tracie</value>
  </action>
  <action name="session_id" package="sqlserver">
    <value>72</value>
  </action>
  <action name="server_principal_name" package="sqlserver">
    <value>tracie</value>
  </action>
  <action name="server_instance_name" package="sqlserver">
    <value>HRDBDEV</value>
  </action>
  <action name="is_system" package="sqlserver">
    <value>false</value>
  </action>
  <action name="database_name" package="sqlserver">
    <value>rbpivr1</value>
  </action>
  <action name="database_id" package="sqlserver">
    <value>10</value>
  </action>
  <action name="client_hostname" package="sqlserver">
    <value>WEBSERVER01</value>
  </action>
  <action name="client_app_name" package="sqlserver">
    <value>Microsoft® Windows® Operating System</value>
  </action>
  <action name="collect_system_time" package="package0">
    <value>2017-05-01T16:44:02.508Z</value>
  </action>
  <action name="attach_activity_id_xfer" package="package0">
    <value>E2EDC810-A11C-4C62-988D-2420F86D8EAD-0</value>
  </action>
  <action name="attach_activity_id" package="package0">
    <value>008E9A10-DF7E-4C85-9C85-95629D3B647F-1</value>
  </action>
</event>

'

select

		  [resultValueUsingPosition] 
			= cast
				(
					@xml.query('/event[@name="sql_batch_completed"]/data[7]/value/text()[1]' )
						as varchar(10)
				)

		, [resultTextUsingPosition] 
			= cast
				(
					@xml.query('/event[@name="sql_batch_completed"]/data[7]/text/text()[1]' )
						as varchar(30)
				)




 

XPath – Condition


set nocount on;
go

declare @xml XML

set @xml=
'
<event name="sql_batch_completed" package="sqlserver" timestamp="2017-05-01T16:44:02.507Z">
  <data name="cpu_time">
    <value>250000</value>
  </data>
  <data name="duration">
    <value>226002957</value>
  </data>
  <data name="physical_reads">
    <value>16349</value>
  </data>
  <data name="logical_reads">
    <value>16197</value>
  </data>
  <data name="writes">
    <value>0</value>
  </data>
  <data name="row_count">
    <value>0</value>
  </data>
  <data name="result">
    <value>2</value>
    <text>Abort</text>
  </data>
  <data name="batch_text">
    <value>SELECT "dbo"."basetblb"."base_social" FROM "dbo"."basetblb" WHERE (("base_payroll_status" = ''A'' ) AND ("base_service_credit" &gt; 10 ) ) </value>
  </data>
  <action name="sql_text" package="sqlserver">
    <value>SELECT "dbo"."basetblb"."base_social" FROM "dbo"."basetblb" WHERE (("base_payroll_status" = ''A'' ) AND ("base_service_credit" &gt; 10 ) ) </value>
  </action>
  <action name="session_server_principal_name" package="sqlserver">
    <value>tracie</value>
  </action>
  <action name="session_id" package="sqlserver">
    <value>72</value>
  </action>
  <action name="server_principal_name" package="sqlserver">
    <value>tracie</value>
  </action>
  <action name="server_instance_name" package="sqlserver">
    <value>HRDBDEV</value>
  </action>
  <action name="is_system" package="sqlserver">
    <value>false</value>
  </action>
  <action name="database_name" package="sqlserver">
    <value>rbpivr1</value>
  </action>
  <action name="database_id" package="sqlserver">
    <value>10</value>
  </action>
  <action name="client_hostname" package="sqlserver">
    <value>WEBSERVER01</value>
  </action>
  <action name="client_app_name" package="sqlserver">
    <value>Microsoft® Windows® Operating System</value>
  </action>
  <action name="collect_system_time" package="package0">
    <value>2017-05-01T16:44:02.508Z</value>
  </action>
  <action name="attach_activity_id_xfer" package="package0">
    <value>E2EDC810-A11C-4C62-988D-2420F86D8EAD-0</value>
  </action>
  <action name="attach_activity_id" package="package0">
    <value>008E9A10-DF7E-4C85-9C85-95629D3B647F-1</value>
  </action>
</event>

'



select

		  [resultValueUsingCondition] 
			= cast
				(
					@xml.query('/event[@name="sql_batch_completed"]/data[@name="result"]/value/text()[1]' )
						as varchar(10)
				)

		, [resultTextUsingCondition] 
			= cast
				(
					@xml.query('/event[@name="sql_batch_completed"]/data[@name="result"]/text/text()[1]' )
						as varchar(30)
				)


 

Compare Queries

Let us have the queries together and compare them.

 

Queried Together

Code



set nocount on;
go

declare @xml XML

set @xml=
'
<event name="sql_batch_completed" package="sqlserver" timestamp="2017-05-01T16:44:02.507Z">
  <data name="cpu_time">
    <value>250000</value>
  </data>
  <data name="duration">
    <value>226002957</value>
  </data>
  <data name="physical_reads">
    <value>16349</value>
  </data>
  <data name="logical_reads">
    <value>16197</value>
  </data>
  <data name="writes">
    <value>0</value>
  </data>
  <data name="row_count">
    <value>0</value>
  </data>
  <data name="result">
    <value>2</value>
    <text>Abort</text>
  </data>
  <data name="batch_text">
    <value>SELECT "dbo"."basetblb"."base_social" FROM "dbo"."basetblb" WHERE (("base_payroll_status" = ''A'' ) AND ("base_service_credit" &gt; 10 ) ) </value>
  </data>
  <action name="sql_text" package="sqlserver">
    <value>SELECT "dbo"."basetblb"."base_social" FROM "dbo"."basetblb" WHERE (("base_payroll_status" = ''A'' ) AND ("base_service_credit" &gt; 10 ) ) </value>
  </action>
  <action name="session_server_principal_name" package="sqlserver">
    <value>tracie</value>
  </action>
  <action name="session_id" package="sqlserver">
    <value>72</value>
  </action>
  <action name="server_principal_name" package="sqlserver">
    <value>tracie</value>
  </action>
  <action name="server_instance_name" package="sqlserver">
    <value>HRDBDEV</value>
  </action>
  <action name="is_system" package="sqlserver">
    <value>false</value>
  </action>
  <action name="database_name" package="sqlserver">
    <value>rbpivr1</value>
  </action>
  <action name="database_id" package="sqlserver">
    <value>10</value>
  </action>
  <action name="client_hostname" package="sqlserver">
    <value>WEBSERVER01</value>
  </action>
  <action name="client_app_name" package="sqlserver">
    <value>Microsoft® Windows® Operating System</value>
  </action>
  <action name="collect_system_time" package="package0">
    <value>2017-05-01T16:44:02.508Z</value>
  </action>
  <action name="attach_activity_id_xfer" package="package0">
    <value>E2EDC810-A11C-4C62-988D-2420F86D8EAD-0</value>
  </action>
  <action name="attach_activity_id" package="package0">
    <value>008E9A10-DF7E-4C85-9C85-95629D3B647F-1</value>
  </action>
</event>

'

select

		  [resultValueUsingPosition] 
			= cast
				(
					@xml.query('/event[@name="sql_batch_completed"]/data[7]/value/text()[1]' )
						as varchar(10)
				)

		, [resultTextUsingPosition] 
			= cast
				(
					@xml.query('/event[@name="sql_batch_completed"]/data[7]/text/text()[1]' )
						as varchar(30)
				)




select

		  [resultValueUsingCondition] 
			= cast
				(
					@xml.query('/event[@name="sql_batch_completed"]/data[@name="result"]/value/text()[1]' )
						as varchar(10)
				)

		, [resultTextUsingCondition] 
			= cast
				(
					@xml.query('/event[@name="sql_batch_completed"]/data[@name="result"]/text/text()[1]' )
						as varchar(30)
				)

Query Plan Comparison – Query Inline

 

Query Plan Comparison – Side by Side

Using SQL Server Management Studio (SSMS) v2016, we can run both queries individually and compare the saved Query Plan

Image

Tabulated
Item Position  Condition
 Cached Plan Size  152 KB  192 KB
 CompileCPU  25  118
 CompileMemory  1736  2664
 CompileTime  25  118
 EstimatedSubtreeCost  806.458  410.401
 MemoryGrant  16128  17920
 OptimizationLevel  FULL  FULL
 RetrievedFromCache  true  true

 

 

Execution Time – Comparison

Image

 

Explanation
  1. Consistently the query with hardcoded position came in around 40 ms while the conditional one came in around 160ms

Summary

It appears from this one test, generated queries that rely on an element’s fixed position are less taxing on the system.

Interestingly, positional queries are costed higher.

On the other hand, queries generated via Conditions are likely less performant.

 

 

XPath Query Tools – XmlToolBox

Background

Lately I have been working more and more with Extended Events and prior to that Cached Plans exploration.

And, has both are stored as XML, it makes sense to see what tools are available for accurately querying XML data.

 

Body

Here is the collected event.


<event name="sql_batch_completed" package="sqlserver" timestamp="2017-05-01T16:44:02.507Z">
  <data name="cpu_time">
    <value>250000</value>
  </data>
  <data name="duration">
    <value>226002957</value>
  </data>
  <data name="physical_reads">
    <value>16349</value>
  </data>
  <data name="logical_reads">
    <value>16197</value>
  </data>
  <data name="writes">
    <value>0</value>
  </data>
  <data name="row_count">
    <value>0</value>
  </data>
  <data name="result">
    <value>2</value>
    <text>Abort</text>
  </data>
  <data name="batch_text">
    <value>SELECT "dbo"."basetblb"."base_social" FROM "dbo"."basetblb" WHERE (("base_payroll_status" = 'A' ) AND ("base_service_credit" &gt; 10 ) ) </value>
  </data>
  <action name="sql_text" package="sqlserver">
    <value>SELECT "dbo"."basetblb"."base_social" FROM "dbo"."basetblb" WHERE (("base_payroll_status" = 'A' ) AND ("base_service_credit" &gt; 10 ) ) </value>
  </action>
  <action name="session_server_principal_name" package="sqlserver">
    <value>tracie</value>
  </action>
  <action name="session_id" package="sqlserver">
    <value>72</value>
  </action>
  <action name="server_principal_name" package="sqlserver">
    <value>tracie</value>
  </action>
  <action name="server_instance_name" package="sqlserver">
    <value>HRDBDEV</value>
  </action>
  <action name="is_system" package="sqlserver">
    <value>false</value>
  </action>
  <action name="database_name" package="sqlserver">
    <value>rbpivr1</value>
  </action>
  <action name="database_id" package="sqlserver">
    <value>10</value>
  </action>
  <action name="client_hostname" package="sqlserver">
    <value>WEBSERVER01</value>
  </action>
  <action name="client_app_name" package="sqlserver">
    <value>Microsoft® Windows® Operating System</value>
  </action>
  <action name="collect_system_time" package="package0">
    <value>2017-05-01T16:44:02.508Z</value>
  </action>
  <action name="attach_activity_id_xfer" package="package0">
    <value>E2EDC810-A11C-4C62-988D-2420F86D8EAD-0</value>
  </action>
  <action name="attach_activity_id" package="package0">
    <value>008E9A10-DF7E-4C85-9C85-95629D3B647F-1</value>
  </action>
</event>

 

Googled

Googled on XML Query XPath and found many tools.

In this post we will discuss XMLToolBox.

 

XMLToolBox

I liked XMLToolBox has unlike many other tools one does not have to start with a query, just paste the the XML body unto the canvas, and point at the XML element or attribute you want to generate the query on.

 

Usage

Here is what happens when we :

  1. Copy and paste the XML noted above unto the XML field textarea
  2. Find the result element and click on the text element

Analysis

Here is the generated Xpath:

/event[@name=”sql_batch_completed”]/data[7]/text/text()

 

Interpretation

  1. Parse using event ( /event )
  2. Look for the attribute name matching sql_batch_completed
  3. Transverse to the 7th data element
  4. Find the text element within the the 7th element and return the text portion of that element

 

Summary

XMLToolBox is easy to use and capable.

Unfortunately, it lacks flexibility because it is based on the position of elements.

If the schema changes a bit, the XPath might return the wrong element as it would refer to the original position.

 

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.

Extended Events – Lock Timeouts

Background

Back to Extended Events, let us start looking at what we have been collecting.

 

Lock Timeouts

We are noticing quite a bit of lock timeouts, and so created an Extended Event Trace to collect them.

Outline

Saved events are saved in binary files.

We need the SQL Engine to extract the compressed XML files and parse its data into elements and attributes.

Query

Table Value Function – extendedEvent.itvf_EventsReview

Script


use master
go

if schema_id('extendedEvent') is null
begin

	exec('create schema [extendedEvent] authorization [dbo]');

end
go


/*

	drop function [extendedEvent].[itvf_EventsReviewFull]

*/

if object_id('[extendedEvent].[itvf_EventsReview]') is null
begin

	exec('create function [extendedEvent].[itvf_EventsReview]() returns table return select [shell] = 1/0 ')

end
go

alter function [extendedEvent].[itvf_EventsReview] 
(
	  @folderXEL sysname
	, @folderXEM sysname = null
	, @maxNumberofRecords int = 1E6
)
returns table

return

	with cte
	(
		  [objectName] 
		, [eventData] 
	)
	as
	(
		SELECT
 
			  [objectName] = tblFNXE.[object_name]
			, [eventData] = cast(tblFNXE.event_data as xml)
 
		FROM sys.fn_xe_file_target_read_file
			(
				  @folderXEL + '\' + '*.xel'
				, isNull(@folderXEM, @folderXEL) + '\' + '*.xem'
				, null
				, null
		   ) tblFNXE
	)
	select top ( 
				  @maxNumberofRecords
			   )
 
			  [objectName] = isNull(cte.[objectName], '')
 
			, [eventData] = cast(cte.eventData as xml)
			--, [XMLFragment] = [event].[node].query('.')
 
			--timestamp on root node
			--, [tsAsDateTimeUTC] 
			--	= [event].[node].value('@timestamp', 'datetimeoffset')     
 
			--collect system time
			, [systemTSAsValueUTC]
				 = cast
				   (
						cast
						(
								([event].[node].query('/event/action[@name="collect_system_time"]/value/text()'))
									as varchar(60)
						)
						as datetime
					)

			-- collect system time to locale time
			, [systemTSAsLocale] 
				 = cast
				   (
						cast
						(

							dateadd
							(
								 minute
							   , [dbo].[udfn_getTimeDifferenceBetweenUTCAndSystemTimeInMinutes]() * -1
 							   , cast
								 (
								   cast
								   (
									  ([event].[node].query('/event/action[@name="collect_system_time"]/value/text()')) 
									   as varchar(60)
								   )
								   as datetime
								)
							)
							as varchar(40)
					)
					as datetime
				)

			--is system
			, [isSystem] 
				= case 
						cast
						(
							([event].[node].query('/event/action[@name="is_system"]/value/text()'))
							as varchar(5)
                        )
						when 'true' then 'Y'
						else 'N'
                  end
				
			--session ID
			, [sessionID] 
				= cast
					(	
						cast
						(
							[event].[node].query('/event/action[@name="session_id"]/value/text()')
							as varchar(60)
						)
						as int
					)

 
			-- client Host Name
			, [clientHostName] 
				= cast
					(
						[event].[node].query('/event/action[@name="client_hostname"]/value/text()')
						as sysname
					)
 
			-- username
			, [username] 
				--= [event].[node].query('/event/action[@name="username"]/value/text()')
				= cast
					(
						[event].[node].query('/event/action[@name="session_server_principal_name"]/value/text()')
						as sysname
					)

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

			, [errorNumber]
				 = cast
					(
						[event].[node].value('(/event/data[@name="error_number"]/value)[1]', 'int')
						as int
					)

			, [result]
				 = cast
					(
						[event].[node].value('(/event/data[@name="result"]/text)[1]', 'nvarchar(30)')
						 as nvarchar(30)
					)

			-- Message
			, [message] 
				= cast
					(
						[event].[node].value('(/event/data[@name="message"]/value)[1]', 'nvarchar(4000)')
						as nvarchar(600)
					)
 
	from   cte
 
	cross apply cte.eventData.nodes(N'//event') event(node)


go


grant select on [extendedEvent].[itvf_EventsReview] to [public]
go

Invoke


select *

from   [extendedEvent].[itvf_EventsReview] 
	(
	    'C:\Assist\ExtendedEvents\TraceFiles\Prod'
	  , 'C:\Assist\ExtendedEvents\TraceFiles\Prod'
	  , default
       )

 

Output

lockTimeouts_20170411_0802PM

 

Persist Data

It is a lot less expensive to parse the XML data once and store the extracted data into an actual SQL Server table.

All queries will thereafter query the relational table.

Relational Table

extendedEvent.events

Create Table

if schema_id('extendedEvent') is null
begin

	exec('create schema [extendedEvent] authorization [dbo]; ')

end
go

if object_id('[extendedEvent].[events]') is null
begin

	create table [extendedEvent].[events]
	(

		  [id]							   bigint		not null identity(1,1)

		, [objectName]                     nvarchar(120) not null 
		, [eventData]                      xml not null 
		, [systemTSAsValueUTC]             datetime not null 
		, [systemTSAsLocale]               datetime not null 
		, [isSystem]                       varchar(1)  null 
		, [sessionID]                      int not null 
		, [clientHostName]                 sysname not null 
		, [username]                       sysname not null 
		, [clientAppName]                  sysname not null 
		, [sqlText]                        nvarchar(max)  not null 
		, [errorNumber]                    int null 
		, [result]                         nvarchar(600)  null 
		, [message]                        nvarchar(1200) null 


	)

end
go

if not exists
(
	select *
	from   sys.objects tblSO
	where   tblSO.parent_object_id = object_id('[extendedEvent].[events]')
)
begin

	alter table [extendedEvent].[events]
		add constraint [PK_ExtendedEvent.events]
			primary key
				(
					  [systemTSAsLocale] 
					, [objectName]
					, [sessionID]
					, [id]
				)
end
go

if not exists
(
	select *
	from   sys.indexes tblSI
	where  tblSI.object_id = object_id('[extendedEvent].[events]')
	and    tbLSI.[name] = 'INDX_ObjectName'
)
begin

	create index [INDX_ObjectName]
	on [extendedEvent].[events]
	(
		  [objectName]
		, [isSystem]
	)

end
go



Load Table

set nocount on;
go

use [AdminDB]
go

truncate table [extendedEvent].[events]
go

insert into [extendedEvent].[events]
(
       [objectName]
      ,[eventData]
      ,[systemTSAsValueUTC]
      ,[systemTSAsLocale]
      ,[isSystem]
      ,[sessionID]
      ,[clientHostName]
      ,[username]
      ,[clientAppName]
      ,[sqlText]
      ,[errorNumber]
      ,[result]
      ,[message]
)
select 
       [objectName]
      ,[eventData]
      ,[systemTSAsValueUTC]
      ,[systemTSAsLocale]
      ,[isSystem]
      ,[sessionID]
      ,[clientHostName]
      ,[username]
      ,[clientAppName]
      ,[sqlText]
      ,[errorNumber]
      ,[result]
      ,[message]
from   [master].[extendedEvent].[itvf_EventsReview] 
	(
		  'C:\Assist\ExtendedEvents\TraceFiles\Prod'
		, 'C:\Assist\ExtendedEvents\TraceFiles\Prod'
		, default
	)

Analyze Data
Script
; with cteCategory
as
(
	select 
			  tblEE.objectName
			, [count] = count(*)

	from   [extendedEvent].[events] tblEE

	group by
			  tblEE.objectName
)
select 
		  tblEE.objectName
		, tblEE.isSystem
		, tblEE.[sqlText]
		, tblEE.[message]		    
		, [count] = count(*)
		, [%] =
				cast
				(
					(
						  ( count(*) * 100)
						/ tblEEC.[count]
					)
					as decimal(6, 2)
				)
			

from   [extendedEvent].[events] tblEE

inner join cteCategory tblEEC

	on tblEE.[objectName] = tblEEC.[objectName]

group by
		  tblEE.objectName
		, tblEE.isSystem
		, tblEE.[sqlText]    
		, tblEE.[message]
		, tblEEC.[count]

order by
	      count(*) desc
		, tblEE.objectName
		, tblEE.isSystem
		, tblEE.[sqlText]    

Output

Explanation
  1. Lock TimeOut
    • 60% of the timeouts are system timeouts
      • They have is System=true
      • Username is sa
    • 36% of the timeouts are user and application timeouts attributed to HangFire
      • An easy way to perform background processing in .NET and .NET Core applications.
        No Windows Service or separate process required.

        Backed by persistent storage. Open and free for commercial use.
        Link
  2. Error Reported
    • Cannot drop the table ‘#CourseSequence’, because it does not exist or you do not have permission.
    • Invalid or Expired Session: nvjpqa3efiy3nrajzhpf1kud
    • The query processor ran out of internal resources and could not produce a query plan.
      This is a rare event and only expected for extremely complex queries or queries that reference a very large number of tables or partitions. Please simplify the query. If you believe you have received this message in error, contact Customer Support Services for more information.

Transact SQL – Time Difference between System Time and UTC

Background

SQL Server is starting to use UTC/GMT time more and more.

And, it is a good thing.

 

Where is GMT/UTC Used?

For instance GMT /UTC is the only time used in Extended Events.

 

Sample XML Payload

Image

Explanation

The time the event was raise is available :-

  1. timestamp
  2. collect_system_time

 

Convert UTC Time to System Time

Get Number of Minutes between GMT/UTC Time and our system’s time

Outline

  1. Get current date & time
  2. Get UTC Date & time
  3. Use datediff and get difference in minutes

Function – Scaler

dbo.udfn_getTimeDifferenceBetweenUTCAndSystemTimeInMinutes


use [master]
go

/*
	drop function [dbo].[fn_getTimeDifferenceBetweenUTCAndSystemTimeInMinutes]
*/
if object_id('[dbo].[udfn_getTimeDifferenceBetweenUTCAndSystemTimeInMinutes]') is null
begin

	exec('create FUNCTION [dbo].[udfn_getTimeDifferenceBetweenUTCAndSystemTimeInMinutes]()
			returns smallint 
			as 
			begin  
				return 1/0
			end
		')

end
go
ALTER FUNCTION [dbo].[udfn_getTimeDifferenceBetweenUTCAndSystemTimeInMinutes]
(
)
RETURNS smallint
AS
BEGIN

	declare @iTimeDifference   int
	declare @datetimeNowSystem datetime
	declare @datetimeNowUTC	   datetime


	set @datetimeNowSystem = getdate()
	set @datetimeNowUTC = GETUTCDATE()

	set @iTimeDifference
			= datediff
				(
					  minute
					, @datetimeNowSystem
					, @datetimeNowUTC
				)

	return ( @iTimeDifference )


    RETURN (@iTimeDifference);
END
go

grant exec on [dbo].[udfn_getTimeDifferenceBetweenUTCAndSystemTimeInMinutes] to [public]
go


Review Extended Events

Code


declare @extendedEvent sysname

declare @OSDrive		varchar(80)
declare @folderBase		varchar(200)
declare @folder			varchar(200)
declare @filename		varchar(200)

declare @filenameXEL	varchar(200)
declare @filenameXEM	varchar(200)


set @extendedEvent = 'performance'

set @OSDrive = 'E:'
set @OSDrive = 'L:'

--set @folderBase = '\Microsoft\SQLServer\ExtendedEvent\Events\'
set @folderBase = '\Microsoft\SQLServer\ExtendedEvents\TraceFiles'

set @folder = @OSDrive + @folderBase + '\' 
set @filename = @folder + @extendedEvent 


set @filenameXEL = @filename + '*.xel'
set @filenameXEM = @filename + '*xem'

 
; with cte
(
      [objectName] 
    , [eventData] 
)
as
(
    SELECT top 1000
 
          [objectName] = tblFNXE.[object_name]
        , [eventData] = cast(tblFNXE.event_data as xml)
 
    FROM sys.fn_xe_file_target_read_file
        (
              @filenameXEL
            , @filenameXEM
            , null
            , null
       ) tblFNXE
)
select
 
          [objectName] = cte.[objectName]
 
        , [eventData] = cast(cte.eventData as xml)
        , [XMLFragment] = [event].[node].query('.')
 
        --timestamp on root node
        , [tsAsDateTimeUTC] = [event].[node].value('@timestamp', 'datetimeoffset')     
 
        --collect system time
        , [systemTSAsValueUTC] = ([event].[node].query('/event/action[@name="collect_system_time"]/value/text()'))
        --, [systemTSAsTextUTC] = ([event].[node].query('/event/action[@name="collect_system_time"]/text/text()'))

        , [systemTSAsValueSystem] 
		= 
			convert
				(  
					  varchar(30)
					, dateadd
					(
					     minute
					   , [dbo].[udfn_getTimeDifferenceBetweenUTCAndSystemTimeInMinutes]() * -1
 					   , cast
					     (
						   cast
						   (
							  ([event].[node].query('/event/action[@name="collect_system_time"]/value/text()')) 
							   as varchar(60)
						   )
						   as datetime
					    )
					)
					, 100
				)
				
        --session ID
        , [sessionID] = [event].[node].query('/event/action[@name="session_id"]/value/text()')
 
        -- client Host Name
        , [clientHostName] = [event].[node].query('/event/action[@name="client_hostname"]/value/text()')
 
        -- username
        , [username] = [event].[node].query('/event/action[@name="username"]/value/text()')
 
        -- client App Name
        , [clientAppName] = [event].[node].query('/event/action[@name="client_app_name"]/value/text()')
 
        -- SQL Text
        , [sqlText] = [event].[node].query('/event/action[@name="sql_text"]/value/text()')
 
from   cte
 
cross apply cte.eventData.nodes(N'//event') event(node)


 

Output

 

Explanation

  1. GTM/UTC Time
    • tsAsDateTimeUTC
      • 2017-04-11 12:00:01.9150000 +00:00
    • systemTSAsValueUTC
      • 2017-04-11T12:00:01.916Z
  2. System Time
    • systemTSAsValueSystem
      • Apr 11 2017  5:00AM

Microsoft MDW – Message 50000

Background

As we discussed in the last couple of weeks, we are deploying Extended Events, starting to collect data and will soon start analyzing the data we collect.

 

Extended Events

Watch Live Data

Here is what things look like when we choose to “Watch Live Data“…

Image

Tabulated

  1. Database Name :- MDW
  2. Error Number :- 50000
  3. message :- insert into [space_utilization_internal]: 0 rows, 0 ms

 

Query Extended Events

Here is what things look like when we queried against the event files

Image

Textual

  1. Error Number :- 50000
  2. Message :- Insert into [databases_internal]
  3. Database :- MDW
  4. sql_text :- EXEC [sysutility_ucp_staging].sp_copy_live_table_data_into_cache_tables
  5. client_app_name :- SQLAgent – TSQL JobStep (Job 0xABCC37BF7D1A73418A87DBE3482B046A : Step 1)

 

SQL Server Agent

sysutility_get_views_data_into_cache_tables

SQL Server Agent History

Image

 

Textual


Date 4/10/2017 4:45:00 PM
Log Job History (sysutility_get_views_data_into_cache_tables)

Step ID 1
Job Name sysutility_get_views_data_into_cache_tables
Step Name Insert latest data from live tables into cache tables
Duration 00:00:00
Sql Severity 0
Sql Message ID 50000
Message
Executed as user: NT AUTHORITY\SYSTEM. sp_get_consistent_batches: 13 ms [SQLSTATE 01000] (Message 50000) Insert into [computers_internal]: 0 rows, 0 ms [SQLSTATE 01000] (Message 50000) Insert into [dacs_internal]: 0 rows, 0 ms [SQLSTATE 01000] (Message 50000) Insert into [volumes_internal]: 0 rows, 0 ms [SQLSTATE 01000] (Message 50000) Insert into [smo_servers_internal]: 0 rows, 0 ms [SQLSTATE 01000] (Message 50000) Insert into [databases_internal]: 0 rows, 0 ms [SQLSTATE 01000] (Message 50000) Insert into [filegroups_internal]: 0 rows, 0 ms [SQLSTATE 01000] (Message 50000) Insert into [datafiles_internal]: 0 rows, 0 ms [SQLSTATE 01000] (Message 50000) Insert into [logfiles_internal]: 0 rows, 0 ms [SQLSTATE 01000] (Message 50000) Discover unavailable databases: 0 rows, 0 ms [SQLSTATE 01000] (Message 50000) Insert into [cpu_utilization_internal]: 0 rows, 0 ms [SQLSTATE 01000] (Message 50000) Insert into [space_utilization_internal]: 0 rows, 0 ms [SQLSTATE 01000] (Message 50000) Update statistics: 43 ms [SQLSTATE 01000] (Message 50000). The step succeeded.

 

Job Steps

Image

Job Step – Insert latest data from live tables into cache tables

Image

Code

EXEC [sysutility_ucp_staging].sp_copy_live_table_data_into_cache_tables

 

Stored Procedure – [sysutility_ucp_staging].[sp_copy_live_table_data_into_cache_tables]

Image

Code

RAISERROR ('sp_get_consistent_batches: %d ms', 0, 1, @task_elapsed_ms);

RAISERROR ('Insert into [computers_internal]: %d rows, %d ms', 0, 1, @row_count, @task_elapsed_ms);

RAISERROR ('Insert into [volumes_internal]: %d rows, %d ms', 0, 1, @row_count, @task_elapsed_ms);

RAISERROR ('Insert into [smo_servers_internal]: %d rows, %d ms', 0, 1, @row_count, @task_elapsed_ms);

RAISERROR ('Insert into [datafiles_internal]: %d rows, %d ms', 0, 1, @row_count, @task_elapsed_ms);

RAISERROR ('Insert into [cpu_utilization_internal]: %d rows, %d ms', 0, 1, @row_count, @task_elapsed_ms);

RAISERROR ('Insert into [space_utilization_internal]: %d rows, %d ms', 0, 1, @row_count, @task_elapsed_ms);

RAISERROR ('Update statistics: %d ms', 0, 1, @task_elapsed_ms);

 

Conclusion

Microsoft chose to use raiserror to display formatted log messages.

Log messages in this case means number of records affected and time taken.