SQL Server – Reporting Services – Error – “Invalid or Expired Session”

Background

Reviewing collected “Extended Events” and noticed a recurring error.

Error

Image

Tabulated

  1. Message :- Invalid or Expired Session: [session id]
  2. Event Name :- error_reported
  3. Error Number :- 50000
  4. Severity :- 16
  5. session_server_principal_name :- Web Site’s Application Pool Identity
  6. server_principal_name :-
  7. is_system :- false
  8. database name :- ReportServer
  9. client_app_name :- Report Server

TroubleShooting

Database

ReportServerTempDB

Table

ReportServerTempDB.dbo.SessionData
Reviewing date of entries
Reviewing date of entries – SQL

SELECT

        [ExpirationMin] 
		  = min 
				(
					[Expiration]
				)
      
      , [ExpirationMax] 
		= max 
			(
				[Expiration]
			)
      
      , [durationBetweenMinAndMax]
			= datediff
				(
					  minute
					, min ([Expiration])
					, max ([Expiration]) 
				)

      , [durationBetweenMinAndCurrent] 
		  = datediff
				(
					  minute
					, min ([Expiration])
					, getdate() 
				)

      , [durationBetweenMaxAndCurrent] 
		= datediff
			(
				  minute
				, max ([Expiration])
				, getdate() 
			)

FROM [dbo].[SessionData] tblSD


Explanation
  1. The entries returned will have duration reflecting the settings set for session recycling.

Remediate

Configuration

Configuration Files

rsreportserver.config

Item :- Configuration \ CleanupCycleMinutes
Default

The default setting for CleanupCycleMinutes is 10.

This translates to entries in the ReportServerTempDB been pruned every 10 minutes.

Revised

Please increase timeout.

Doing so will mean that records are recycled less frequently.

Image – Default

 

Image – Revised

Explanation

Change CleanupCycleMinutes from 10 minutes to 180 minutes, 3 hours.

SQL Server – Extended Event – Metadata – Get Current Target File

Background

For some optimization work that we are doing, I will like to know the name of the Extended Events’ Engine currently targeted file.

 

Code

Guide

As always we know that Microsoft exposes a lot of metadata via Dynamic Management Views.

The specific ones that we will use are:

  1. sys.dm_xe_sessions
    • Currently executing Extended Event Sessions
  2. sys.dm_xe_session_targets
    • Targets for currently executing sessions

SQL



SELECT
		  [extendedEvent]
			= tblXES.[name]

		, [executionCount]
			= tblXEST.execution_count

		, [executionDuration]
			= tblXEST.execution_duration_ms

		, [targetData]
			= tblXEST.target_data

		, [fileCurrent]
			= cast(tblXEST.target_data as xml).value('(//File/@name)[1]','nvarchar(255)')

FROM sys.dm_xe_sessions AS tblXES

INNER JOIN sys.dm_xe_session_targets AS tblXEST

    ON tblXES.[address] = tblXEST.[event_session_address]

where 
	(

		( tblXEST.target_name = 'event_file' )

	)


Output

Sample Output

 

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.