info@techdevops.com | 437-991-3573 | Data Engineering Services
TechDevOps.com
Resources Tools
Experts in Microsoft SQL Server on Windows, Linux, Containers | Clusters, Always On, FCI | Migrations, Cloud, Performance



Extract Blocking Chains from your SQL Servers
by BF (Principal Consultant; Architecture; Engineering)
2018-02-13








Step 1: Log Active Requests in your SQL Server


Create Logging Table for Active Requests
- Convert int to bigint if any errors

SET ANSI_NULLS ON
GO

SET QUOTED_IDENTIFIER ON
GO

CREATE TABLE [dbo].[LOG_ACTIVE_SPID_EXECUTING_DURATION](
[LogID] [int] IDENTITY(1,1) NOT NULL,
[session_id] [int] NOT NULL,
[status] [varchar](150) NULL,
[Blk_by] [int] NULL,
[wait_type] [varchar](150) NULL,
[wait_resource] [varchar](250) NULL,
[wait_sec] [decimal](18, 6) NULL,
[cpu_time] [int] NULL,
[logical_reads] [int] NULL,
[reads] [int] NULL,
[writes] [int] NULL,
[elaps_sec] [decimal](18, 6) NULL,
[dbname] [varchar](30) NULL,
[statement_text] [varchar](max) NULL,
[command_text] [varchar](max) NULL,
[command] [varchar](100) NULL,
[login_name] [varchar](100) NULL,
[host_name] [varchar](100) NULL,
[program_name] [varchar](250) NULL,
[last_request_end_time] [datetime] NULL,
[login_time] [datetime] NULL,
[open_transaction_count] [int] NULL,
[inserteddate] [datetime] NULL,
CONSTRAINT [PK_LOG_ACTIVE_SPID_EXECUTING_DURATION] PRIMARY KEY CLUSTERED
(
[LogID] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
) ON [PRIMARY] TEXTIMAGE_ON [PRIMARY]

GO

ALTER TABLE [dbo].[LOG_ACTIVE_SPID_EXECUTING_DURATION] ADD CONSTRAINT [DF_LOG_ACTIVE_SPID_EXECUTING_DURATION_inserteddate] DEFAULT (getdate()) FOR [inserteddate]
GO


Create Stored Procedure for Active Requests

SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO

Create Procedure [dbo].[sp_Microsoft_Active_v2]
as

SELECT s.session_id,
r.status,
r.blocking_session_id 'Blk by',
r.wait_type,
wait_resource,
r.wait_time / (1000.0) 'Wait Sec',
r.cpu_time,
r.logical_reads,
r.reads,
r.writes,
r.total_elapsed_time / (1000.0) 'Elaps Sec',
db_name(r.database_id) as DBName,
'"'+Substring(st.TEXT,(r.statement_start_offset / 2) + 1,
((CASE
WHEN r.statement_end_offset = -1
THEN Datalength(st.TEXT)
WHEN (r.statement_end_offset - r.statement_start_offset) < 0
Then Datalength(st.TEXT)
ELSE r.statement_end_offset
END - r.statement_start_offset) / 2) + 1)+'"' AS statement_text,
'"'+Coalesce(Quotename(Db_name(st.dbid)) + N'.' + Quotename(Object_schema_name(st.objectid,st.dbid)) + N'.' + Quotename(Object_name(st.objectid,st.dbid)),
'')+'"' AS command_text,
r.command,
s.login_name,
s.host_name,
s.program_name,
s.last_request_end_time,
s.login_time,
r.open_transaction_count
FROM sys.dm_exec_sessions AS s
JOIN sys.dm_exec_requests AS r
ON r.session_id = s.session_id
CROSS APPLY sys.Dm_exec_sql_text(r.sql_handle) AS st
WHERE r.session_id != @@SPID
ORDER BY r.cpu_time desc, r.status,
r.blocking_session_id,
s.session_id
GO


SQL Job: (schedule to every 15 minutes or even lower if ok for your specific logging)

Insert into OPS.dbo.LOG_ACTIVE_SPID_EXECUTING_DURATION
(session_id,[status],Blk_by,wait_type,wait_resource,wait_sec,cpu_time,logical_reads,reads,writes,elaps_sec,dbname,statement_text,command_text,command,
login_name,[host_name],[program_name],last_request_end_time,login_time,open_transaction_count)

Exec [dbo].[sp_Microsoft_Active_v2]




Step 2: Extract any Blocking Chains from the Logged Request Data


Create Procedure [dbo].[GetBlockingChainsv2]
@LogTime datetime
as

--Exec GetBlockingChainsv2 '2018-02-06 14:13:58.180'
--Exec GetBlockingChainsv2 '2018-02-06 14:48:12.293'
--Exec GetBlockingChainsv2 '2018-02-06 22:18:24.580'

SET NOCOUNT ON
Create Table #SESSIONS (session_id int, blk_by int, batch varchar(max), command varchar(50), dbname varchar(100), elaps_sec int)
Insert INTO #SESSIONS (session_id, blk_by, batch, [command], dbname, elaps_sec)
SELECT session_id, Blk_by, statement_text as 'Batch', [command], dbname, elaps_sec
FROM [dbo].[LOG_ACTIVE_SPID_EXECUTING_DURATION] R where inserteddate = @LogTime
;WITH BLOCKERS (session_id, Blk_by, LEVEL, BATCH, COMMAND, DBNAME, elaps_sec)
AS
(
SELECT session_id,
Blk_by,
CAST (REPLICATE ('0', 4-LEN (CAST (session_id AS VARCHAR))) + CAST (session_id AS VARCHAR) AS VARCHAR (1000)) AS LEVEL,
BATCH, COMMAND, DBNAME, elaps_sec FROM #SESSIONS R
WHERE (Blk_by = 0 OR Blk_by = session_id)
AND EXISTS (SELECT * FROM #SESSIONS R2 WHERE R2.Blk_by = R.session_id AND R2.Blk_by <> R2.session_id)
UNION ALL
SELECT R.session_id,
R.Blk_by,
CAST (BLOCKERS.LEVEL + RIGHT (CAST ((1000 + R.session_id) AS VARCHAR (100)), 4) AS VARCHAR (1000)) AS LEVEL,
R.BATCH, R.COMMAND, R.DBNAME, R.elaps_sec FROM #SESSIONS AS R
INNER JOIN BLOCKERS ON R.Blk_by = BLOCKERS.session_id WHERE R.Blk_by > 0 AND R.Blk_by <> R.session_id
)
SELECT N' ' + REPLICATE (N'| ', LEN (LEVEL)/4 - 1) +
CASE WHEN (LEN(LEVEL)/4 - 1) = 0
THEN 'HEAD - '
ELSE '|---------- ' END
+ CAST (session_id AS NVARCHAR (10)) + ' | ' + CAST (UPPER(dbname) as NVARCHAR(50)) + ' | ' + CAST (command as NVARCHAR(50)) + ' | ' + CAST (elaps_sec as NVARCHAR(50)) + 's | ' + N' ' + BATCH AS BLOCKING_TREE
FROM BLOCKERS ORDER BY LEVEL ASC
DROP TABLE #SESSIONS
GO


Create Procedure dbo.ExtractBlockingChainsv2
as

/*
Execute in new QW:
Select inserteddate, command, * from [dbo].[LOG_ACTIVE_SPID_EXECUTING_DURATION] where inserteddate = '2018-02-06 14:58:14.487' order by LogID ASC
*/

IF OBJECT_ID('tempdb..#ITERATIONS') IS NOT NULL DROP TABLE #ITERATIONS

Declare @totallogged decimal(18,0)
Set @totallogged = (Select count(*) from [dbo].[LOG_ACTIVE_SPID_EXECUTING_DURATION])
Select @totallogged as 'Total Logged Active Requests'

Declare @total decimal(18,1)
Set @total = (Select count(*) from [dbo].[LOG_ACTIVE_SPID_EXECUTING_DURATION] where Blk_by <> 0)
Select UPPER(dbname) as 'Database', count(*) 'Total SPIDs Blocked', convert(decimal(18,1),count(*)/@total * 100) as '% of Total Blocked' from [dbo].[LOG_ACTIVE_SPID_EXECUTING_DURATION] where Blk_by <> 0 group by dbname

Declare @Iterations int
Set @Iterations = (select count(distinct(inserteddate)) from [dbo].[LOG_ACTIVE_SPID_EXECUTING_DURATION])

Set nocount on
Declare @Cnt int = 1
Declare @IterationTimeMin datetime

Create Table #ITERATIONS (ID int Identity(1,1), IterationTime datetime)
Insert into #ITERATIONS (IterationTime)
Select distinct(inserteddate) from [dbo].[LOG_ACTIVE_SPID_EXECUTING_DURATION] order by inserteddate asc
--Select * from #TMP

While Exists (Select 1 from #ITERATIONS)
Begin
Set @IterationTimeMin = (Select top 1 min(IterationTime) from #ITERATIONS)
Select convert(varchar(10),@cnt) + ' / ' + convert(varchar(10),@Iterations) 'Iteration', convert(varchar(50), @IterationTimeMin, 121) as 'Session time'
Exec dbo.GetBlockingChainsv2 @IterationTimeMin
Set @cnt = @cnt + 1
Delete from #ITERATIONS where IterationTime = @IterationTimeMin
End