Monday, October 29, 2012

Monitor Blocking with Extented Events in SQL 2012

1. Set the "blocked process threshold (s)"
sp_configure 'show advanced options', 1 ;
GO
RECONFIGURE ;
GO
sp_configure 'blocked process threshold', 10 ;
GO
RECONFIGURE ;
GO

here we set the threshold to 10 seconds, which generating a blocked process report for each task that is blocked.

2. Create Extented Events Session
CREATE EVENT SESSION [blockingMonitor] ON SERVER
ADD EVENT sqlserver.blocked_process_report(
    ACTION(sqlos.task_time,sqlserver.database_id,sqlserver.database_name,sqlserver.request_id,sqlserver.sql_text))
ADD TARGET package0.event_file(SET filename=N'C:\temp\blockingMonitor.xel')
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

here we save the log to c:\temp\BlockingMonitor.xel file.

3. Start Extented Events Session
ALTER EVENT SESSION [blockingMonitor] ON SERVER STATE=START

4. Create blocking scenario as testing:
    a) create first session, and run
create table test(a int)
go
insert into test values(1)
go
insert into test values(1)
go
insert into test values(1)
go
select @@spid
go
begin tran
update test set a=2
    b) create second session, and run
delete from test

5. Check the blocking log file, and get the blocking info
====================================================================
select 'SPID ' + b.[blocked_process spid]+ ' (from server '+ b.[blocked_process hostname] +' with login account '+ b.[blocked_process loginname]+') wants to acquire '
  + b.[blocked_process lockMode] + ' lock on resource ' + b.[blocked_process waitresource]+', which is owned by SPID '
  + b.[blocking_process spid]+ ' (from server '+ b.[blocking_process hostname] +' with login account '+ b.[blocking_process loginname]+')' as Summary
 ,*
from
(

 select dateadd(HH,DATEDIFF( hh, GETUTCDATE(), GETDATE()),cast(trace.data.value('(/event/@timestamp)[1]', 'DATETIME') as datetime)) as [Time]
   ,trace.data.value ('(/event/data[@name=''database_id'']/value)[1]', 'BIGINT') AS [Databaseid]
   ,trace.data.value ('(/event/data[@name=''lock_mode'']/text)[1]', 'VARCHAR(5)') AS [lock_mode]
   ,trace.data.value ('(/event/data[@name=''transaction_id'']/value)[1]', 'VARCHAR(20)') AS [transaction_id]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@id)[1]', 'VARCHAR(20)') AS [blocked_process id]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@taskpriority)[1]', 'VARCHAR(20)') AS [blocked_process taskpriority]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@logused)[1]', 'VARCHAR(20)') AS [blocked_process logused]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@waitresource)[1]', 'VARCHAR(20)') AS [blocked_process waitresource]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@waittime)[1]', 'VARCHAR(20)') AS [blocked_process waittime]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@ownerId)[1]', 'VARCHAR(20)') AS [blocked_process ownerId]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@transactionname)[1]', 'VARCHAR(20)') AS [blocked_process transactionname]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@lasttranstarted)[1]', 'VARCHAR(20)') AS [blocked_process lasttranstarted]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@XDES)[1]', 'VARCHAR(20)') AS [blocked_process XDES]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@lockMode)[1]', 'VARCHAR(20)') AS [blocked_process lockMode]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@schedulerid)[1]', 'VARCHAR(20)') AS [blocked_process schedulerid]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@kpid)[1]', 'VARCHAR(20)') AS [blocked_process kpid]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@status)[1]', 'VARCHAR(20)') AS [blocked_process status]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@spid)[1]', 'VARCHAR(20)') AS [blocked_process spid]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@sbid)[1]', 'VARCHAR(20)') AS [blocked_process sbid]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@ecid)[1]', 'VARCHAR(20)') AS [blocked_process ecid]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@priority)[1]', 'VARCHAR(20)') AS [blocked_process priority]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@trancount)[1]', 'VARCHAR(20)') AS [blocked_process trancount]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@lastbatchstarted)[1]', 'VARCHAR(20)') AS [blocked_process lastbatchstarted]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@lastbatchcompleted)[1]', 'VARCHAR(20)') AS [blocked_process lastbatchcompleted]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@lastattention)[1]', 'VARCHAR(20)') AS [blocked_process lastattention]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@clientapp)[1]', 'VARCHAR(20)') AS [blocked_process clientapp]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@hostname)[1]', 'VARCHAR(20)') AS [blocked_process hostname]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@hostpid)[1]', 'VARCHAR(20)') AS [blocked_process hostpid]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@loginname)[1]', 'VARCHAR(20)') AS [blocked_process loginname]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@isolationlevel)[1]', 'VARCHAR(20)') AS [blocked_process isolationlevel]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@xactid)[1]', 'VARCHAR(20)') AS [blocked_process xactid]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@currentdb)[1]', 'VARCHAR(20)') AS [blocked_process currentdb]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@lockTimeout)[1]', 'VARCHAR(20)') AS [blocked_process lockTimeout]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@clientoption1)[1]', 'VARCHAR(20)') AS [blocked_process clientoption1]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@clientoption2)[1]', 'VARCHAR(20)') AS [blocked_process clientoption2]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/executionStack/frame/@sqlhandle)[1]', 'VARCHAR(20)') AS [blocked_process sqlhandle]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/inputbuf)[1]', 'VARCHAR(20)') AS [blocked_process sql]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@status)[1]', 'VARCHAR(20)') AS [blocking_process status]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@spid)[1]', 'VARCHAR(20)') AS [blocking_process spid]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@sbid)[1]', 'VARCHAR(20)') AS [blocking_process sbid]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@ecid)[1]', 'VARCHAR(20)') AS [blocking_process ecid]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@priority)[1]', 'VARCHAR(20)') AS [blocking_process priority]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@trancount)[1]', 'VARCHAR(20)') AS [blocking_process trancount]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@lastbatchstarted)[1]', 'VARCHAR(20)') AS [blocking_process lastbatchstarted]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@lastbatchcompleted)[1]', 'VARCHAR(20)') AS [blocking_process lastbatchcompleted]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@lastattention)[1]', 'VARCHAR(20)') AS [blocking_process lastattention]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@clientapp)[1]', 'VARCHAR(20)') AS [blocking_process clientapp]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@hostname)[1]', 'VARCHAR(20)') AS [blocking_process hostname]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@hostpid)[1]', 'VARCHAR(20)') AS [blocking_process hostpid]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@loginname)[1]', 'VARCHAR(20)') AS [blocking_process loginname]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@isolationlevel)[1]', 'VARCHAR(20)') AS [blocking_process isolationlevel]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@xactid)[1]', 'VARCHAR(20)') AS [blocking_process xactid]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@currentdb)[1]', 'VARCHAR(20)') AS [blocking_process currentdb]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@lockTimeout)[1]', 'VARCHAR(20)') AS [blocking_process lockTimeout]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@clientoption1)[1]', 'VARCHAR(20)') AS [blocking_process clientoption1]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/@clientoption2)[1]', 'VARCHAR(20)') AS [blocking_process clientoption2]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/executionStack/frame/@sqlhandle)[1]', 'VARCHAR(20)') AS [blocking_process sqlhandle]
   ,trace.data.value ('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/inputbuf)[1]', 'VARCHAR(20)') AS [blocking_process sql]
 from(
  select *,CAST(event_data as xml) data
  from sys.fn_xe_file_target_read_file('C:\temp\*.xel', null, null, null)
 ) as trace
) as b