Closure
Closure
Home » Databases » Microsoft SQL Server » How we collect blocking queries via Extended Event and how we read its data

How we collect blocking queries via Extended Event and how we read its data

How we collect blocking queries via Extended Event and how we read its data
, , , , , Leave a comment
How we collect blocking queries via Extended Event and how we read its data
Latest posts by Stratos Matzouranis (see all)

In older article we had seen how we create Extended Event to see long-running queries. In this article we will build Extended Event that records the blockings.

All we need to do is create it with a T-SQL command. After it is created, it will record in the path that we have declared to it in an XML file all the queries that lasted more than 1 second.

To create the Extended Event

We must not forget to change the path to the one where we want the data to be stored.

Then we execute it in a simple query window.

CREATE EVENT SESSION [BlockedProcessReport] ON SERVER 
ADD EVENT sqlserver.blocked_process_report 
ADD TARGET package0.event_file(SET filename=N'D:\Xevents\blockings.xel',max_file_size=(20),max_rollover_files=(50))
WITH (MAX_MEMORY=8192 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=ON)
GO

alter event session BlockedProcessReport on server state=start;
go

But for it to work, we must have changed the parameter blocked process threshold which defines how long blockings will be reported by alerts, profilers and extended events related to blocking. Setting its value to 10 it will only record blockings that lasted longer than 10 seconds. With the default value of 0 it will not record anything. Accepts values from 5 seconds and above.

To apply this change, we run the following in a query window on the instance:

EXEC sp_configure 'show advanced options', 1;
RECONFIGURE WITH OVERRIDE;
EXEC sp_configure 'blocked process threshold (s)', 10;
RECONFIGURE WITH OVERRIDE;

How do we read the results?

In the path we defined during its creation XEvent a .xel and a .xem file were created. Through the dynamic view sys.fn_xe_file_target_read_file with parameters these files we result in all the XML file with the information.

But since it is impractical to read an XML by eye, the file must somehow be filtered into a more readable form.

So I sat down and made a query that does this job.

For starters, through the name we created, Xevent finds the path that is dynamically located and defines it as a parameter in the query.

Then we define the XML as one Common Table Expression. By doing SELECT we can get the value from each property we need.

In the where statement we can filter specific bases, the duration and the period of time it was executed.

This part needs attention, as the default xml timestamp is in UTC timezone, so to put the real time that the server has, we add the time difference that the server has with the UTC timezone (DATEADD(HOUR,DATEDIFF(hour, SYSUTCDATETIME(),SYSDATETIME() )).

declare

@xel as varchar(max),
@xem as varchar(max) 

set @xel=(select 
--n.name as XeventName,
SUBSTRING(cast(f.value as varchar(max)),1,len(cast(f.value as varchar(max)))-4)+'*.xel' as xel
--,SUBSTRING(cast(f.value as varchar(max)),1,len(cast(f.value as varchar(max)))-4)+'*.xem' as xem
from sys.server_event_session_fields f
inner join sys.server_event_sessions n on f.event_session_id = n.event_session_id
WHERE f.NAME = 'filename' 
and n.name like '%BlockedProcessReport%') --Set xevent Name


set @xem=(select 
--n.name as XeventName,
--SUBSTRING(cast(f.value as varchar(max)),1,len(cast(f.value as varchar(max)))-4)+'*.xel' as xel
SUBSTRING(cast(f.value as varchar(max)),1,len(cast(f.value as varchar(max)))-4)+'*.xem' as xem
from sys.server_event_session_fields f
inner join sys.server_event_sessions n on f.event_session_id = n.event_session_id
WHERE f.NAME = 'filename' 
and n.name like '%BlockedProcessReport%')  --Set xevent Name


;WITH XEvents AS
(
select object_name, CAST(event_data AS XML) AS A FROM sys.fn_xe_file_target_read_file(
@xel
,@xem
, NULL, NULL)
)
SELECT 
d.name as DB_Name,
A.value ('(/event/action[@name=''database_name'']/value)[1]', 'VARCHAR(MAX)') AS DB_Name,
DATEADD(HOUR,DATEDIFF(hour,  SYSUTCDATETIME(),SYSDATETIME() ),A.value ('(/event/@timestamp)[1]', 'DATETIME')) AS [Time],
A.value ('(event/data[@name="duration"]/value)[1]','bigint') / 1000000  AS [Duration_Seconds],
A.value ('(event/data[@name="object_id"]/value)[1]','bigint')   AS Object_ID,
A.value ('(/event/data[@name="lock_mode"]/text)[1]',  'VARCHAR(MAX)') AS lock_mode,
A.value ('(/event/data[@name="blocked_process"]/value/blocked-process-report/blocked-process/process/inputbuf)[1]',  'VARCHAR(MAX)') AS BlockedQuery,
--A.value ('(/event/data[@name="blocked_process"]/value/blocked-process-report/blocked-process/process/@hostname)[1]',  'VARCHAR(MAX)') AS BlockedHostName,
A.value ('(/event/data[@name="blocked_process"]/value/blocked-process-report/blocked-process/process/@loginname)[1]',  'VARCHAR(MAX)') AS BlockedLoginName,
A.value ('(/event/data[@name="blocked_process"]/value/blocked-process-report/blocking-process/process/inputbuf)[1]',  'VARCHAR(MAX)')  AS BlockingQuery,
A.value ('(/event/data[@name="blocked_process"]/value/blocked-process-report/blocking-process/process/inputbuf)[1]',  'VARCHAR(MAX)')  AS BlockingQuery,
A.value ('(/event/data[@name="blocked_process"]/value/blocked-process-report/blocking-process/process/@loginname)[1]',  'VARCHAR(MAX)')  AS BlockingLoginName,
A.value ('(/event/data[@name="blocked_process"]/value/blocked-process-report/blocking-process/process/@hostname)[1]',  'VARCHAR(MAX)')  AS BlockingLoginName,
A.value ('(/event/data[@name="blocked_process"]/value/blocked-process-report/blocking-process/process/executionStack/frame/@sqlhandle)[1]',  'VARCHAR(MAX)') AS sql_handle1,
sf1.text as full_text1,
qp1.query_plan as query_plan1,
A   AS xml_report
--,A.value('(event/data[@name="cpu_time"]/value)[1]','bigint') /1000000 AS cpu_seconds
--,A.value('(event/data[@name="physical_reads"]/value)[1]','bigint') AS physical_reads
--,A.value('(event/data[@name="logical_reads"]/value)[1]','bigint') AS logical_reads
--,A.value('(event/data[@name="row_count"]/value)[1]','bigint') AS row_count
From XEvents x
inner join sys.databases d on x.A.value ('(/event/data[@name="database_id"]/value)[1]',  'VARCHAR(MAX)') =d.database_id
outer apply sys.dm_exec_sql_text (CONVERT(VARBINARY(MAX), x.A.value ('(/event/data[@name="blocked_process"]/value/blocked-process-report/blocking-process/process/executionStack/frame/@sqlhandle)[1]',  'varchar(max)'), 1)) as sf1
outer apply sys.dm_exec_query_plan((select top 1 plan_handle from sys.dm_exec_query_stats where sql_handle = CONVERT(VARBINARY(MAX), x.A.value ('(/event/data[@name="blocked_process"]/value/blocked-process-report/blocking-process/process/executionStack/frame/@sqlhandle)[1]',  'varchar(max)'), 1)order by last_execution_time desc))as qp1

where  1=1
and DATEADD(HOUR,DATEDIFF(hour,  SYSUTCDATETIME(),SYSDATETIME() ),A.value ('(/event/@timestamp)[1]', 'DATETIME'))  between '2020-05-01 10:45:00.000' and '2020-05-30 12:45:00.000'
and A.value ('(/event/action[@name=''database_name'']/value)[1]', 'VARCHAR(MAX)') ='DB_1'

The result

The result of the query brought us for this period of time, on the basis we requested, the queries that were made block, from which query they were blocked, in which object and finally with which locking mode.

How we collect blocking queries via Extended Event and how we read its data

Sources:

Share it

Leave a reply