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.

SQL Server – Extended Events – Querying Data – Day 1

Background

Once we have our Extended Events Session Setup and it is collecting data, we should occasionally check in and review the collected data.

 

Sample

XML Data

 

Query

Outline

We have a sample query below, here is what it does:

  1. XEL & XEM
    • It sets the @fileXEL variable to the folder and file signature for our XEL files
    • It sets the @fileXEM variable to the folder and file signature for our XEM files
  2. It creates a Common Table Expression (CTE)
    • invokes sys.fn_xe_file_target_read_file
      • Passes along the XEL and XEM file signatures
      • It discard records that have “UPDATE STATISTICS
  3. It uses XPATH and breaks the record using //event
  4. Parses data
    • XML Fragment
      • query(‘.’)
        • Sample data
          • <event name=”rpc_completed” package=”sqlserver” id=”64″ version=”1″ timestamp=”2017-04-01T16:14:45.363Z”><data name=”cpu”><value>0</value><text /></data></event>
    • timestamp
      • value(‘@timestamp’, ‘datetimeoffset’)
        • Sample Data
          • 2017-04-01 16:14:45.3630000 +00:00
    • collect_system_time
      • .query(‘/event/action[@name=”collect_system_time”]/value/text()’)
        • Sample Data
          • 131355368858528137
      • .query(‘/event/action[@name=”collect_system_time”]/text/text()’)
        • Sample Data
          • 2017-04-01T16:14:45.852Z
    • session_id
      • .query(‘/event/action[@name=”session_id”]/value/text()’)
        • Sample Data
          • 54
    • client_host_name
      • .query(‘/event/action[@name=”client_hostname”]/value/text()’)
        • Sample Data
          • LAB-DB-SQL
    • username
      • .query(‘/event/action[@name=”username”]/value/text()’)
        • Sample Data
          • tomw
    • client_app_name
      • .query(‘/event/action[@name=”client_app_name”]/value/text()’)
        • Sample Data
          • Report Server
    • sql_text
      • .query(‘/event/action[@name=”sql_text”]/value/text()’)

 

Code


declare @fileXEL sysname
declare @fileXEM sysname


--set @fileXEL = 'E:\Microsoft\SQLServer\ExtendedEvent\Events\Performance\Performance_0_131356693200370000.xel'
set @fileXEL = 'E:\Microsoft\SQLServer\ExtendedEvent\Events\Performance\Performance*.xel'
set @fileXEM = 'E:\Microsoft\SQLServer\ExtendedEvent\Events\Performance\Performance*.xem'

; with cte
(
	  [objectName] 
	, [eventData] 
)
as
(
	SELECT top 10 

		  [objectName] = tblFNXE.[object_name]
		, [eventData] = cast(tblFNXE.event_data as xml)

	FROM sys.fn_xe_file_target_read_file
		(
			  @fileXEL
			, @fileXEM
			, null
			, null
	   ) tblFNXE

	where tblFNXE.event_Data not like '%UPDATE STATISTICS%'

)
select 

		  [objectName] = cte.[objectName]

		, [eventData] = cast(cte.eventData as xml)
		, [XMLFragment] = [event].[node].query('.')

		--timestamp on root node
		, [tsAsDateTime] = [event].[node].value('@timestamp', 'datetimeoffset')		

		--collect system time
		, [systemTSAsValue] = ([event].[node].query('/event/action[@name="collect_system_time"]/value/text()'))
		, [systemTSAsText] = ([event].[node].query('/event/action[@name="collect_system_time"]/text/text()'))

		--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

SQL Server – Extended Events – Metadata

Background

In our last post, needed to back port an Extended Event Session developed in SQL Server 2014 to v2008/R2.

Unfortunately, the exported script did not work in our initial attempt to apply against the v2008-R2 Instance.

I thus had to go back and see which events and columns were availed in the earlier edition, v2008-R2.

 

Metadata

General ( Plumbing )

Here we cover plumbing stuff.

Generalized information that is applicable to the SQL Server Version.

Get List of Packages

Code



SELECT
		 [@@VERSION] = @@VERSION

SELECT 
		  [packageName] = tblPkg.[name]
		, [packageDescription] = tblPkg.[description]

FROM   sys.dm_xe_packages tblPkg

order by
		  tblPkg.[name] asc

 

Output

v2008/R2

v2014/R2

Explanation

  1. Compared to v2008/2008-R2, there are many more packages in v2014

 

 

Get List of Objects

Overview

Let us get objects that have “completed” in their name.

Code




DECLARE @packageName varchar(120)
DECLARE @objectName  varchar(120)

set @packageName = 'sqlserver'
set @objectName  = 'completed'

SELECT
		 [@@VERSION] = @@VERSION

SELECT 
		  [packageName] = tblPkg.[name]
		, [packageDescription] = tblPkg.[description]
		, [objectName] = tblObj.[name]
		, tblObj.[object_type]

FROM   sys.dm_xe_packages tblPkg

INNER JOIN  sys.dm_xe_objects tblObj

	ON  tblPkg.[guid] = tblObj.[package_guid]

WHERE tblPkg.[name] = @packageName

AND   tblObj.[name] like '%'  + @objectName + '%'

order by
		  tblPkg.[name] asc
		, tblObj.[name]



 

Output

v2008/R2

 

v2014

 

Explanation

In v2008, v2008-R2, there are 5 events that have completed in their name.

In v2014, there are 12 events with same signature.

 

 

Get List of Event Columns

Code



DECLARE @packageName varchar(120)
DECLARE @objectName  varchar(120)

set @packageName = 'sqlserver'
--set @objectName  = 'sql_batch_completed'
set @objectName  = 'completed'

SELECT
		 [@@VERSION] = @@VERSION

SELECT 
		  [packageName] = tblPkg.[name]
		, [packageDescription] = tblPkg.[description]
		, [objectType] = tblObj.[object_type]
		, [objectName] = tblObj.[name]
		, [columnName] = tblObjCol.[name]
		, [typeName]   = tblObjCol.[type_name]
		--, tblObjCol.*

FROM   sys.dm_xe_packages tblPkg

INNER JOIN  sys.dm_xe_objects tblObj

	ON  tblPkg.[guid] = tblObj.[package_guid]

INNER JOIN sys.dm_xe_object_columns tblObjCol

	ON tblObj.name = tblObjCol.object_name

WHERE tblPkg.[name] = @packageName

AND   tblObj.[name] like '%' + @objectName + '%'

/*
	Exclude objects that start with file such as :
		a) file_read_completed 
		b) file_write_completed
*/
AND   tblObj.[name] not like 'file' + '%' + @objectName + '%'

/*
AND   tblObj.[name] in
		(
			  'rpc_completed'
			, 'sp_statement_completed'
			, 'sql_statement_completed'
		)
*/
order by
		  tblPkg.[name] asc
		, tblObj.[name]
		, tblObjCol.[column_type]
		, tblObjCol.[name]


Output

v2008/R2

 

 

v2014

Explanation

In v2008, v2008-R2, there are 33 event columns that have completed in their name.

In v2014, there are 132 columns with same signature.

 

Actual

Here we cover the sessions that are actually registered on the targeted instance.

Get List of Extended Event Sessions that are currently running

Code


SELECT
		  [session]
			= tblDMXES.[name]

		, [createTS]
			= convert(varchar(30), tblDMXES.[create_time], 100)
		
FROM sys.dm_xe_sessions AS tblDMXES

;

Output

 

 

Get Extended Event Sessions Targets

Code


select 
		  [session] = tblDMXES.[name]
		, [targetName] = tblDMXEST.target_name
		--, [packageGUID] = tblDMXEST.[target_package_guid]
		, [executionCount] = tblDMXEST.[execution_count]
		, [executionDurationInms] = tblDMXEST.[execution_duration_ms]
		--, tblDMXEST.*
		
from   sys.dm_xe_sessions AS tblDMXES

inner join sys.dm_xe_session_targets tblDMXEST

		on tblDMXES.address = tblDMXEST.event_session_address


 

Output

Get Extended Event Sessions Target Files

Get Extended Event Sessions Target Files – Vertical

Code


declare @session sysname

set @session = 'performance'

SELECT 
		  [session] = tblDMXES.[name]
		, [object]  = tblDMXESOC.[object_name]
		, [column]  = tblDMXESOC.column_name
		, [value]   = tblDMXESOC.column_value

FROM sys.dm_xe_sessions tblDMXES

JOIN sys.dm_xe_session_object_columns tblDMXESOC

    ON tblDMXES.[address] = tblDMXESOC.event_session_address

WHERE tblDMXESOC.[object_name] in
				(
					   'asynchronous_file_target' -- v2008, v2008-R2
					 , 'event_file' -- v2014
				)

AND	  (
			(
			       ( @session is null )
				or ( tblDMXES.[name] like @session + '%' )			
			)
	  )

ORDER BY
		  tblDMXES.[name]
		, tblDMXESOC.column_name


Output

Output – v2008/R2

Output – v2014

Explanation

  1. Object
    • In v2008-R2, Object name is asynchronous_file_target
    • In v2014, Object name is event_file

Get Extended Event Sessions Target Files – Horizontal

Code


declare @session sysname

set @session = 'performance'

;with cteEventFile
(
	  [session]
	, [column] 
	, [value]  
)
as
(
	SELECT 
			    [session] = tblDMXES.[name]
			  , [column]  = tblDMXESOC.[column_name]
			  , [value]   = tblDMXESOC.[column_value]

	FROM sys.dm_xe_sessions tblDMXES

	JOIN sys.dm_xe_session_object_columns tblDMXESOC

		ON tblDMXES.[address] = tblDMXESOC.event_session_address


	WHERE tblDMXESOC.[object_name] in
					(
						   'asynchronous_file_target' -- v2008, v2008-R2
						 , 'event_file' -- v2014
					)


)
select 
			  [session]
			, [filename]
			, [metadatafile]
			, [maxFileSize] = max_file_size
			, [maxRollOverFiles] = max_rollover_files
			, increment


from   
		(
		
			select *

			from   cteEventFile cteEF

			WHERE  (

						(
							   ( @session is null )
							or ( cteEF.[session] like @session + '%' )			
						)
				  )

		) as [src]


PIVOT
	(
		MAX(value)
		FOR [column] in
				(
					  [filename]
					, metadatafile
					, max_file_size
					, max_rollover_files
					, increment
				)
	) tblPivot


Output

Output – v2008/R2

Output – v2014

List Event Predicates  ( Top Level )

Code



select 
		  [session] = tblDMXES.[name]
		, [eventName] = tblDMXESE.event_name
		, [eventPredicate] = tblDMXESE.event_predicate
		--, tblDMXESE.*
		
from   sys.dm_xe_sessions AS tblDMXES

inner join sys.dm_xe_session_events tblDMXESE

		on tblDMXES.[address] = tblDMXESE.[event_session_address]

Output

 

List Event Predicates  ( Detail )

 

View XML

Let us review the XML in the event predicate column.

We use the XPath Tester / Evaluator @ freeformatter.com ( Link )

 

XML Input & Xpath Expression

Once we pass in //leaf as the XPath expression, we get the output pasted below:

XPath Result

 

Code

Outline

It is easier to write the SQL Query along with its XPATH once we try things out in an Xpath Query tool.

Sample


; with cteEventPredicate
(
	  [session]
	, [eventName]
	, [eventPredicate]
)
as
(
	select 
		  [session] = tblDMXES.[name]
		, [eventName] = tblDMXESE.event_name
		, [eventPredicate] = cast(tblDMXESE.event_predicate as xml)
		--, tblDMXESE.*
		
	from   sys.dm_xe_sessions AS tblDMXES

	inner join sys.dm_xe_session_events tblDMXESE

			on tblDMXES.[address] = tblDMXESE.[event_session_address]

)
, cteClause
(
	  [session]
	, [eventName]
	, [attribute] 
	, [comparator] 
	, [value] 
)
as
(

	select 
			  cteEP.[session]
			, cteEP.[eventName]
			, [attribute] = leaves.leaf.value('(global/@name)[1]', 'varchar(100)') 
			, [comparator] = leaves.leaf.value('(comparator/@name)[1]', 'varchar(100)') 
			, [value] = leaves.leaf.value('(value)[1]', 'varchar(100)') 

	from   cteEventPredicate cteEP

	cross apply cteEP.eventPredicate.nodes( N'//leaf') as leaves(leaf)

)
select *

from   cteClause cteC

where  cteC.[attribute] is not NULL


Output

 

Dedicated

Dedicated to Microsoft for strong and fruitful commitment to their DB Products.

Sql Server – Extended Events – Creating in Later Edition and Applying Against 2008/2008R2

Background

Ungratefulness is a sad part of LIFE that it is hard to see and acknowledge.

 

Scenario

One of our databases there is a reporting table that contains aggregated data for transactions that occur each month.

Things are working, but since the person that designed the Application “walked“, we do not have an insight as when it is ran, who runs it, and where it is being ran.

The end of month was yesterday and I need to quickly see what I can find out.

 

Circumstances

Unfortunately, the SQL Instance is on v2008-R2 and that version does not have a GUI for Extended Event Management.

 

Client – SSMS

Object Explorer

Object Explorer Against v2014 Instance

 

 

Object Explorer Against v2008/R2 Instance

Comparison

When the targeted instance is on v2012 or higher SSMS, Extended Event Management functionality is visible under the SQL Instance \ Management node.

But when the SQL Instance is v2008 or v2008/R2, though Extended Event ( EE ) sub-component is available under the hood, it is not exposed via the SSMS GUI.

 

Work Around

Create Baseline

We created a simple package against our v2014 SQL Instance.

Once created, we asked SSMS to please script it for us.

To do so, please access “Management” \ “Extended Events” \ Sessions \ [session] \ “Script Session as” \ “Create To”

 

 

Generated Script


CREATE EVENT SESSION [thirdPartyAppRequest] ON SERVER 
ADD EVENT sqlserver.error_reported(
    ACTION(package0.collect_system_time,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.client_pid,sqlserver.database_id,sqlserver.database_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.username)
    WHERE ([package0].[greater_than_uint64]([sqlserver].[database_id],(4)) AND [package0].[equal_boolean]([sqlserver].[is_system],(0)))),
ADD EVENT sqlserver.rpc_completed(
    ACTION(package0.collect_system_time,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.client_pid,sqlserver.database_id,sqlserver.database_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.username)
    WHERE ([package0].[greater_than_uint64]([sqlserver].[database_id],(4)) AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) AND [sqlserver].[client_app_name]<>N'Report Server')),
ADD EVENT sqlserver.sp_statement_completed(SET collect_object_name=(1)
    ACTION(package0.collect_system_time,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.client_pid,sqlserver.database_id,sqlserver.database_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.username)
    WHERE ([package0].[greater_than_uint64]([sqlserver].[database_id],(4)) AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) AND [sqlserver].[client_app_name]<>N'Report Server')),
ADD EVENT sqlserver.sql_statement_completed(SET collect_statement=(1)
    ACTION(package0.collect_system_time,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.client_pid,sqlserver.database_id,sqlserver.database_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.username)
    WHERE ([package0].[greater_than_uint64]([sqlserver].[database_id],(4)) AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) AND [sqlserver].[client_app_name]<>N'Report Server')) 
ADD TARGET package0.ring_buffer
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=ON,STARTUP_STATE=OFF)
GO



Apply Script Against v2008-R2 SQL Instance

Errors

 

Error # Error Text Response
 Msg 25623  The event action name, “sqlserver.database_name”, is invalid, or the object could not be found
 sql_server.database_name is not exposed in v2008/R2.
Please use sql_server.database_id
 Msg 25623  The event action name, “sqlserver.server_principal_name”, is invalid, or the object could not be found   sql_server.server_principal_name is not exposed in v2008/R2.
Please use sql_server.username
 Msg 25629  For event, “sqlserver.sp_statement_completed”, the customizable attribute, “collect_object_name”, does not exist.  Comment this out “SET collect_object_name=(1)

 

 

Cleaned Up Script For v2008-R2 SQL Instance

Script


declare @extendedEvent sysname

set @extendedEvent = 'thirdPartyAppRequestScripted'

if exists
(

	select *

	from    sys.server_event_sessions tblSSES

	where   tblSSES.[name] = @extendedEvent

)
begin

	print 'Drop XE ' + @extendedEvent

	DROP EVENT SESSION [thirdPartyAppRequestScripted] 
		ON SERVER 

end



CREATE EVENT SESSION [thirdPartyAppRequestScripted] ON SERVER 
ADD EVENT sqlserver.error_reported
(
    ACTION
	(
		  package0.collect_system_time
		, sqlserver.client_app_name
		, sqlserver.client_hostname
		, sqlserver.client_pid
		, sqlserver.database_id
	--	, sqlserver.database_name
	--	, sqlserver.server_principal_name
		, sqlserver.session_id
		, sqlserver.sql_text
		, sqlserver.username
	)
    WHERE 
	(
		    [package0].[greater_than_uint64]([sqlserver].[database_id],(4)) 
		AND [package0].[equal_boolean]([sqlserver].[is_system],(0))
	)
)

, ADD EVENT sqlserver.rpc_completed
(
    ACTION
	(
		  package0.collect_system_time
		, sqlserver.client_app_name
		, sqlserver.client_hostname
		, sqlserver.client_pid
		, sqlserver.database_id
		--, sqlserver.database_name
		--, sqlserver.server_principal_name
		, sqlserver.session_id
		, sqlserver.sql_text
		, sqlserver.username
	)
    WHERE 
	(
		    [package0].[greater_than_uint64]([sqlserver].[database_id],(4)) 
		AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) 
		AND [sqlserver].[client_app_name]<>N'Report Server'
	)

)	

, ADD EVENT sqlserver.sp_statement_completed
   (
	
	--Msg 25629, Level 16, State 1, Line 2
	-- For event, "sqlserver.sp_statement_completed", the customizable attribute, "collect_object_name", does not exist
	--SET collect_object_name=(1)
    
	ACTION
	(
		  package0.collect_system_time
		, sqlserver.client_app_name
		, sqlserver.client_hostname
		, sqlserver.client_pid
		, sqlserver.database_id
		--, sqlserver.database_name
		--, sqlserver.server_principal_name
		, sqlserver.session_id
		, sqlserver.sql_text
		, sqlserver.username
	)
    
	WHERE 
	(
		    [package0].[greater_than_uint64]([sqlserver].[database_id],(4)) 
		AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) 
		AND [sqlserver].[client_app_name]<>N'Report Server'
	)
	
)	


, ADD EVENT sqlserver.sql_statement_completed
	(
		
		--SET collect_statement=(1)
		
		ACTION
		(
			  package0.collect_system_time
			, sqlserver.client_app_name
			, sqlserver.client_hostname
			, sqlserver.client_pid
			, sqlserver.database_id
			--, sqlserver.database_name
			--, sqlserver.server_principal_name
			, sqlserver.session_id
			, sqlserver.sql_text
			, sqlserver.username
		)
		WHERE 
		(
				 [package0].[greater_than_uint64]([sqlserver].[database_id],(4))
			 AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) 
			 AND [sqlserver].[client_app_name]<>N'Report Server')
		) 


ADD TARGET package0.ring_buffer

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

if exists
(

	select *

	from    sys.server_event_sessions tblSSES

	where   tblSSES.[name] = @extendedEvent

)
begin

	print 'Created XE ' + @extendedEvent

end


For Persistency

Script

    ADD TARGET package0.event_file 
     ( 
          SET 
              filename='E:\Microsoft\SQLServer\ExtendedEvent\Events\Performance\Performance'
            , max_file_size=(100) 
            , max_rollover_files=(100) 
     )
 

 

Error Message

Error # Error Text Response
Msg 25623  The target name, “package0.event_file”, is invalid, or the object could not be found
 It seems package0.event_file is not supported.
Msg 25641  For target, “package0.asynchronous_file_target”, the parameter “filename” passed is invalid.
The operating system returned error 2 while creating the file ‘T:\Microsoft\SQLServer\ExtendedEvent\Events\Performance\Performance.xel’.
Verify that the path exists and that the SQL Server startup account has access to the location.
 Change targeted folder name to a directory that exists and that the Service Account has access to.
 Msg 25641  For target, “package0.asynchronous_file_target”, the parameter “metadatafile” passed is invalid.
The operating system returned error 2 while creating the file ‘J:\Microsoft\SQLServer\ExtendedEvent\Events\Performance\Performance.xem’.
Verify that the path exists and that the SQL Server startup account has access to the location.
 Change metadatafile’s directory to one that exists and SQL Server Account has access to.

 

 

Script ( Revised )



ADD TARGET package0.asynchronous_file_target

(
   SET 
             filename='E:\Microsoft\SQLServer\ExtendedEvent\Events\Performance\Performance.xel'
	   , metadatafile='E:\Microsoft\SQLServer\ExtendedEvent\Events\Performance\Performance.xem'
	   , max_file_size=(100)
 	   , max_rollover_files=(100)

)


 

Full SQL

Script


declare @extendedEvent sysname

set @extendedEvent = 'thirdPartyAppRequestScripted'

if exists
(

	select *

	from    sys.server_event_sessions tblSSES

	where   tblSSES.[name] = @extendedEvent

)
begin

	print 'Drop XE ' + @extendedEvent

	DROP EVENT SESSION [thirdPartyAppRequestScripted] 
		ON SERVER 

end



CREATE EVENT SESSION [thirdPartyAppRequestScripted] ON SERVER 
ADD EVENT sqlserver.error_reported
(
    ACTION
	(
		  package0.collect_system_time
		, sqlserver.client_app_name
		, sqlserver.client_hostname
		, sqlserver.client_pid
		, sqlserver.database_id
	--	, sqlserver.database_name
	--	, sqlserver.server_principal_name
		, sqlserver.session_id
		, sqlserver.sql_text
		, sqlserver.username
	)
    WHERE 
	(
		    [package0].[greater_than_uint64]([sqlserver].[database_id],(4)) 
		AND [package0].[equal_boolean]([sqlserver].[is_system],(0))
	)
)

, ADD EVENT sqlserver.rpc_completed
(
    ACTION
	(
		  package0.collect_system_time
		, sqlserver.client_app_name
		, sqlserver.client_hostname
		, sqlserver.client_pid
		, sqlserver.database_id
		--, sqlserver.database_name
		--, sqlserver.server_principal_name
		, sqlserver.session_id
		, sqlserver.sql_text
		, sqlserver.username
	)
    WHERE 
	(
		    [package0].[greater_than_uint64]([sqlserver].[database_id],(4)) 
		AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) 
		AND [sqlserver].[client_app_name]<>N'Report Server'
	)

)	

, ADD EVENT sqlserver.sp_statement_completed
   (
	
	--Msg 25629, Level 16, State 1, Line 2
	-- For event, "sqlserver.sp_statement_completed", the customizable attribute, "collect_object_name", does not exist
	--SET collect_object_name=(1)
    
	ACTION
	(
		  package0.collect_system_time
		, sqlserver.client_app_name
		, sqlserver.client_hostname
		, sqlserver.client_pid
		, sqlserver.database_id
		--, sqlserver.database_name
		--, sqlserver.server_principal_name
		, sqlserver.session_id
		, sqlserver.sql_text
		, sqlserver.username
	)
    
	WHERE 
	(
		    [package0].[greater_than_uint64]([sqlserver].[database_id],(4)) 
		AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) 
		AND [sqlserver].[client_app_name]<>N'Report Server'
	)
	
)	


, ADD EVENT sqlserver.sql_statement_completed
	(
		
		--SET collect_statement=(1)
		
		ACTION
		(
			  package0.collect_system_time
			, sqlserver.client_app_name
			, sqlserver.client_hostname
			, sqlserver.client_pid
			, sqlserver.database_id
			--, sqlserver.database_name
			--, sqlserver.server_principal_name
			, sqlserver.session_id
			, sqlserver.sql_text
			, sqlserver.username
		)
		WHERE 
		(
				 [package0].[greater_than_uint64]([sqlserver].[database_id],(4))
			 AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) 
			 AND [sqlserver].[client_app_name]<>N'Report Server')
		) 


ADD TARGET package0.ring_buffer

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

if exists
(

	select *

	from    sys.server_event_sessions tblSSES

	where   tblSSES.[name] = @extendedEvent

)
begin

	print 'Created XE ' + @extendedEvent

end


if exists
(

	select *

	from    sys.server_event_sessions tblSSES

	where   tblSSES.[name] = @extendedEvent

)
begin

	print 'Start XE ' + @extendedEvent

	ALTER EVENT SESSION [thirdPartyAppRequestScripted] 
		ON SERVER 
			STATE=START;

end



Dedicated

Dedicated to ATL, I85 has enough going on already.

Have hard weeks and months ahead.

And, to Microsoft for making our lives a lot easier.

 

SQL Server – “Lock Timeouts” – Identify Using “Extended Events”

Background

In this exercise we will create an Extended Event from Scratch and see if are able to successfully monitor “Lock Requests” timeout.

 

Previous Posts

  1. SQL Server – “Lock Timeouts” – ErrorLog
    Link
  2. SQL Server – Identify Lock TimeOuts via Extended Events ( from converted Trace File )
    Link
  3. SQL Server – “Lock Timeouts” – Trigger Timeouts – SSMS – Table Designer
    Link
  4. SQL Server – “Lock Timeouts” – Identifying through SQL Server Profiler
    Link

 

 

Prerequisite

v2008-R2+

Extended Events was introduced with SQL Server 2008, the GUI came a release later, v2008-R2 to be exact.

And, so your SSMS client to be on at least v2008/R2 and your targeted Server should be on v2008.

 

Design Extended Event

Create new Extended Event

Initiate Wizard

Initiate a new Extended Event Session Creation by selecting the SQL Instance, accessing Object Explorer and traversing the tree “Management“\ “Extended Events” \ “Sessions“.  Right click on the Sessions node and from the drop-down menu select “New Session Wizard“.

Image

 

Screen Shot

Image

Introduction
Image

 

 

Set Session Properties
Outline
  1. Session name :- lockTimeOut
  2. Schedule
    • Start the event session at server startup
      • Off
        • For now we will choose not to affect the Trace to happen at startup
Image

 

Choose Templates
Outline
  1. Use this event session template: Query Detail Tracking
    • This template collects detailed statement and error information.
      • What MSFT says
        • You can use this template to track each statement has executed on your system as a result of query batches or stored procedures and then track errors back to the specific statement that caused them.
        • This template also collects the query hash and query plan hash for every statement it tracks.
        • All statement events are collected in this session so collection size may be very large.
        • To reduce the collection size consider using the Query Detail Sampling template, which already includes a filter.
    • Might want to use Query Detail Sampling template
      • Events are only collected from 20% of the active sessions on the server at any given time.
      • You can change the sampling rate by modifying the filter for the event session.
Image

 

Select Events to Capture
Outline
  1. Error Reported
  2. Lock Cancel
  3. Lock Deadlock
  4. Lock Deadlock Chain
  5. Lock Timeout
  6. Lock Timeout Greater Than
  7. RPC Completed
  8. SQL batch Completed
  9. XML Deadlock Report
Tabulate
Event Event Detail Explanation  Link
Error Reported Occurs when an error is reported.  Link
 Lock Cancel Occurs when the request for a lock was canceled, such as when the query requesting the lock was canceled. Use this event to monitor locks. The Lock:Cancel event class indicates that acquisition of a lock on a resource has been canceled; for example, due to a query being canceled.  Link
 Lock Deadlock  Occurs when an attempt to acquire a lock is canceled for the victim of a deadlock. The Lock:Deadlock Chain event class is produced for each participant in a deadlock.

Use the Lock:Deadlock Chain event class to monitor when deadlock conditions occur. This information is useful to determine if deadlocks are significantly affecting the performance of your application, and which objects are involved. You can examine the application code that modifies these objects to determine if changes to minimize deadlocks can be made.

 Link
 Lock Deadlock Chain  Occurs when an attempt to acquire a lock generates a deadlock. This event is raised for each participant in the deadlock.  The Lock:Deadlock Chain event class is produced for each participant in a deadlock.
Use the Lock:Deadlock Chain event class to monitor when deadlock conditions occur. This information is useful to determine if deadlocks are significantly affecting the performance of your application, and which objects are involved. You can examine the application code that modifies these objects to determine if changes to minimize deadlocks can be made.
 Link
 Lock Timeout Occurs when a request for a lock times out because another transaction holds a blocking lock on the required resource. The time-out duration is determined by the @@LOCK_TIMEOUT system function. Use this event to help troubleshoot blocking issues. The Lock:Timeout event class indicates that a request for a lock on a resource, such as a page, has timed out because another transaction is holding a blocking lock on the required resource. Time-out is determined by the @@LOCK_TIMEOUT system function and can be set with the SET LOCK_TIMEOUT statement.

Use the Lock:Timeout event class to monitor when time-out conditions occur. This information is useful to determine if time-outs are significantly affecting the performance of your application, and which objects are involved. You can examine the application code that modifies these objects to determine if changes to minimize time-outs can be made.

 Link
 Lock Timeout Greater Than 0  Occurs when a request for a lock times out because of a blocking lock that is being held by a different resource. This event is identical to lock_timeout, but excludes cases in which the time-out value is 0, such as when lock probes are used. Time-outs with a duration of 0 do not necessarily indicate a blocking problem.  The Lock:Timeout (timeout > 0) event class indicates that a request for a lock on a resource, such as a page, has timed out because another transaction is holding a blocking lock on the required resource. This event class behaves the same as the Lock:Timeout event class, except it does not include any events where the timeout value is 0.
Include the Lock:Timeout (timeout > 0) event class in traces where you are using lock probes or other processes that have timeout values of zero. This allows you to see where actual time-outs are occurring without seeing time-out values of zero.
 Link
 RPC Completed  Occurs when a remote procedure call has completed.  The RPC:Completed event class indicates that a remote procedure call has been completed.  Link
 SQL Batch completed  Occurs when a Transact-SQL batch has finished executing.  The SQL:BatchCompleted event class indicates that the Transact-SQL batch has completed.  Link
 XML Deadlock Report  Produces a deadlock report in XML format.

 

 

Image

 

Capture Global Fields
Outline
  1. client app name
  2. client hostname
  3. collect system time
  4. database id
  5. database name
  6. is system
  7. server instance name
  8. server principal name
  9. session id
  10. session server principal name
  11. sql text
Image

 

Set Session Event Filters
Outline

Once we have the Session created, we will come back and add filtering elements.

Image

 

Specify Session Data Storage
Outline

Again we will come back and persistence once we have had things running for a while…

Image

 

Summary
Outline

We get a nice summary of our choices in tree view.  And, can click and review each choice.

Image

 

Create Event Session
Outline

The Wizard submits the SQL for creating the Session to the SQL Engine and it works behind the scene to create the event.

Image

 

Edit Extended Event

Initiate Wizard

Outline

Access the list of Extended Event Sessions by selecting the SQL Instance, accessing Object Explorer and traversing the tree “Management“\ “Extended Events” \ “Sessions“.

Review the list of existing Extended Event Sessions and right clicking on the one you will like to edit.

From the drop-down menu, select “Properties“.

Image

 

Edit Session Wizard

Session Properties – General

Outline

  1. Session Name :- lockTimeOut
  2. Template :- <Blank>
  3. Start the event Session at server startup
    • Checkbox that can be turned on or off
    • Indicates whether Session should be scheduled to start upon SQL Instance restart
  4. Start event session once Session is initially created
  5. Watch live data on screen at is captured
  6. Causality Tracking
    • very important as it allows to tie seemingly independent events will likely sources
    • AI Stuff
Image

 

Session Properties – Events

Outline

  1. Session Name :- lockTimeOut
  2. Template :- <Blank>
  3. Start the event Session at server startup
    • Checkbox that can be turned on or off
    • Indicates whether Session should be scheduled to start upon SQL Instance restart
  4. Start event session once Session is initially created
  5. Watch live data on screen at is captured
  6. Causality Tracking
    • very important as it allows to tie seemingly independent events will likely sources
    • AI Stuff
Image

 

Session Properties – Events

Outline

  1. This is the most important screen
  2. We add in events and leave out those not pertinent to our current use case
  3. And, can click the “Configure” button to add filtering to
Image

Session Properties – Selected Events – Configure

Event – “Error Reported”
Outline

The configure screen allows us to choose the fields we want to collect, and the filtering predicates.

Global Fields
Tabulate

We chose to follow the following fields for all events:

  1. client app name
  2. client hostname
  3. collect system time
  4. database id
  5. database name
  6. is system
  7. server instance name
  8. server principal name
  9. session id
  10. session server principal name
  11. sql text

 

Global Fields – Image

Filter Predicates
Filter Predicates – Matrix
Error Number Message Explanation
 2528  DBCC execution completed. If DBCC printed error messages, contact your system administrator.
 5701  Changed database context to ‘%.*ls’.
 5703  Changed language setting to %.*ls.

 

 

Filter Predicates – Image

 

Image – Error Reported – Error Number – 2528

Image – Error Reported – Error Number – 5701

 

Image – Error Reported – Error Number – 5703

Event – “lock cancel”,” lock deadlock”, “lock deadlock chain”, “lock timeout”, “lock timeout greater than”, “xml deadlock report”
Outline

This event captures Lock Requests that are cancelled.

We did not make any changes, but ensured that the request’s SQL text is captured, as well.

Event Fields – Tabulate

Here are specific fields that are captured

  1. database id
  2. mode
  3. object id
  4. resource 0, resource 1, resource 2
  5. resource description

 

Event Fields – Image

 

Watch Live Data

Events

 

Event – Lock Timeout

Outline

Raised when “Lock Timeout” occurs…

Image

Tabulated

 

Error Number Sample Explanation
 Associated Object ID  110623437 Issue object_schema_name({Associated Object ID}, Database_ID) to get schema nameIssue object_name({Associated Object ID}, Database_ID) to get Object Name
 Client Hostname  […DADENIJI-…]
 Database ID  7  Database D
 Database Name
 Database Name ( Action )  DBLab  Issue db_name([Database ID]) if null
 Duration  29999000  Value is is microseconds ( 30 seconds )
 Is System  False  Is request targeting a system or user object
 Mode  SCH_M  Schema Modification
 Object ID  110623437 Please see explanation for “Associated ID“, but replace “Associated Object ID” with Object ID
 Owner Type  Transaction
 Client Hostname  […DADENIJI-…]  Client’s workstation name
 Resource_0  110623437 Search for guide and code on the Net on how to find Resource Name when one has Resource  ID
 Resource Type  OBJECT  Resource Type granularity
 Server Instance Name  [DADENIJI\v2014]  SQL Instance Sever Name
 Server Principal Name  [Domain Name]\dadeniji Login Name
 Session Server Principal Name  [Domain Name]\dadeniji Same as Login name, except when in the middle of an “Execute As Login” code block
 SQL Text  ALTER TABLE dbo.person ADD   gender char(1) NULL  Underlying SQL

 

 

 

Event – Lock Timeout Greater Than 0

Outline

Raised when “Lock Timeout greater than 0” occurs…

Please keep in mind that Lock TimeOut is raise anytime that Lock Request Timed Out; while Lock Timeout only occurs when a time limit has been set on how long to wait.

In our scenario, we raised Lock Timeout greater than 0, as well.

 

Event – Error Reported

Outline

Raised when “Lock Timeout” occurs…

Image

Tabulated

Error Number Sample Explanation
Client Application Name  Microsoft SQL Server Management Studio Application Name
 Client Hostname  […DADENIJI-…]
Collect System Time  2017-03-31 12:41 PM System Time
 Database ID  7  Database D
 Database Name
 Database Name ( Action )  DBLab  Issue db_name([Database ID]) if null
Error Number  1222  Lock request time out period exceeded.
 Is System  False  Is request targeting a system or user object
 Message message Lock request time out period exceeded.
Severity  16 Please seek out extended documentation to get insight on the various severity levels
 SQL State  56  ???
 User Defined  false  SQL Server supports User defined errors.  If the error is triggered by the user through raiserror or  throw, this flag is set to true
 SQL State  56  ???
 User Defined  false  SQL Server supports User defined errors.  If the error is triggered by the user through raiserror or  throw, this flag is set to true

 

 

 

Event – SQL Batch Completed

Outline

Raised once the SQL Batch completes.

In our case, we are only capturing the ones that fail.

Image

 

Tabulated

Error Number Sample Explanation
 Batch Text ALTER TABLE dbo.person ADD   gender char(1) NULL
Client Application Name  Microsoft SQL Server Management Studio Application Name
 Client Hostname  […DADENIJI-…]
Collect System Time  2017-03-31 12:41 PM System Time
CPU Time  0 How much time the system has spent on the batch.
Please keep in mind this is different than the time expended wait time.
 Database ID  7  Database D
 Database Name
 Database Name ( Action )  DBLab  Issue db_name([Database ID]) if null
 Duration  30001486 30001486 is 30 million micro-seconds
30001 is 30 thousand milli-seconds
or 30 seconds
 Is System  False  Is request targeting a system or user object
Logical Reads 0  How much Logical Reads has been engaged
Physical Reads 0  How much physical Reads has been engaged
Result Error Has we said all of events will be Error
Row Count  false Aggregated Number of Records affected
SQL Text ALTER TABLE dbo.person ADD   gender char(1) NULL SQL Text
Writes  0 Measurement of Writes

 

 

 

Summary

We will let things run for a while.

Watch thing through Live Data.

And, come back and configure persisting of events.

And, in another post review and analysis of the saved events.