Introduction
If you have
inherited an application that generates dynamic SQL and the last upgrade is
causing blocking it can be a difficult problem to solve. However with these two
SQL stored procedures, a capture job, some common sense, and SQL Query analyzer
you can find that elusive “rogue” SQL statement.
Setting up the Capture JobThe kill
root blocker SQL procedure follows the root blocker capture procedure. Users
issuing the blocking query will be affected however other will not.
The output
of the stored procedure “sp_find_root_blocker2” should be directed to a text
file for later review.
Setting up a Capture Alert
In addition
to a Capture Job you can also set up a capture alert
Reading the captured data
This is an example of the
captured root blocker data. In this case a single statement appeared four time
in the course of an hour.
'Check_For_Root_Blocker' : Step 1, 'Check for Blocker' : Began Executing 2003-08-19 15:05:00
No processes are currently blocked [SQLSTATE 01000]
Job 'Check_For_Root_Blocker' : Step 1, 'Check for Blocker' : Began Executing 2003-08-19 15:10:00
spid status loginame hostname blk db cmd waittype
73 runnable ANGEL5SESSIONS B2R05 0 ANGELDB2 DELETE 0000
EventTypeParameters EventInfo
Event0 DELETE FROM LSN_LOGS WHERE ENTRY_ID IN (SELECT ENTRY_ID FROM LSN_ENTRIES WHERE LSN_ENTRIES.COURSE_ID = '200304FABR RCMPSC101 001' AND LSN_ENTRIES.PARENT_ID = 'DELETED')
Job 'Check_For_Root_Blocker' : Step 1, 'Check for Blocker' : Began Executing 2003-08-19 15:15:00
No processes are currently blocked [SQLSTATE 01000]
Job 'Check_For_Root_Blocker' : Step 1, 'Check for Blocker' : Began Executing 2003-08-19 15:20:00
No processes are currently blocked [SQLSTATE 01000]
Job 'Check_For_Root_Blocker' : Step 1, 'Check for Blocker' : Began Executing
2003-08-19 15:25:01
spid status loginame hostname blk db cmd waittype
66 sleeping ANGEL5SESSIONS B2R05 0 ANGELDB2 DELETE 0208
66 runnable ANGEL5SESSIONS B2R05 0 ANGELDB2 DELETE 0000
EventTypeParameters EventInfo
Event0 DELETE FROM LSN_LOGS WHERE ENTRY_ID = '07863204DB4O1128'
Job 'Check_For_Root_Blocker' : Step 1, 'Check for Blocker' : Began Executing 2003-08-19 15:30:00
No processes are currently blocked [SQLSTATE 01000]
Analyzing the
Captured Query
The kill
root blocker SQL procedure follows the root blocker capture procedure. Users
issuing the blocking query will be affected however other will not.
The output
of the stored procedure “sp_find_root_blocker2” should be directed to a text
file for later review.
Setting up a Capture Alert
In addition
to a Capture Job you can also set up a capture alert
Reading the captured data
This is an example of the
captured root blocker data. In this case a single statement appeared four time
in the course of an hour.
'Check_For_Root_Blocker' : Step 1, 'Check for Blocker' : Began Executing 2003-08-19 15:05:00 No processes are currently blocked [SQLSTATE 01000] Job 'Check_For_Root_Blocker' : Step 1, 'Check for Blocker' : Began Executing 2003-08-19 15:10:00 spid status loginame hostname blk db cmd waittype 73 runnable ANGEL5SESSIONS B2R05 0 ANGELDB2 DELETE 0000
EventTypeParameters EventInfo Event0 DELETE FROM LSN_LOGS WHERE ENTRY_ID IN (SELECT ENTRY_ID FROM LSN_ENTRIES WHERE LSN_ENTRIES.COURSE_ID = '200304FABR RCMPSC101 001' AND LSN_ENTRIES.PARENT_ID = 'DELETED')
Job 'Check_For_Root_Blocker' : Step 1, 'Check for Blocker' : Began Executing 2003-08-19 15:15:00 No processes are currently blocked [SQLSTATE 01000] Job 'Check_For_Root_Blocker' : Step 1, 'Check for Blocker' : Began Executing 2003-08-19 15:20:00 No processes are currently blocked [SQLSTATE 01000]
Job 'Check_For_Root_Blocker' : Step 1, 'Check for Blocker' : Began Executing 2003-08-19 15:25:01 spid status loginame hostname blk db cmd waittype 66 sleeping ANGEL5SESSIONS B2R05 0 ANGELDB2 DELETE 0208 66 runnable ANGEL5SESSIONS B2R05 0 ANGELDB2 DELETE 0000
EventTypeParameters EventInfo Event0 DELETE FROM LSN_LOGS WHERE ENTRY_ID = '07863204DB4O1128'
Job 'Check_For_Root_Blocker' : Step 1, 'Check for Blocker' : Began Executing 2003-08-19 15:30:00 No processes are currently blocked [SQLSTATE 01000]
Analyzing the
Captured Query
When you
have captured a root blocking statement copy and paste the query in SQL Query
Analyzer referencing the effected database. You should either press CNTL+L or
navigate to “Query” then “Display Estimated Execution Plan” and click.
The SQL
statement “DELETE FROM LSN_LOGS WHERE ENTRY_ID IN (SELECT ENTRY_ID FROM
LSN_ENTRIES WHERE LSN_ENTRIES.COURSE_ID = '200304FABR RCMPSC101 001' AND
LSN_ENTRIES.PARENT_ID = 'DELETED')” appeared four times in the course on an
hour additionally other statements referencing the “ENTRY_ID” column on the
LSN_LOGS table appeared. The big clue is multiple SQL statements referencing
the same type of statement usually a delete or an update, which results in a
cluster index or table scan using exclusive locks.
This DELETE
statement with a sub query caused a nested loop join of a 10 million row table
to a eight hundred thousand table, clearly there was room for improvement. A I
mentioned previously, a delete statement uses exclusive locks preventing all
users not using uncommitted reads (dirty reads) from accessing the table.
Implementing a
Solution
In this
case the standard technique of applying indexes to both side of a join worked
well. One index was added to the “LSN_LOGS” side of the join and the join type
changed from Nested Join, Cluster Index Scan to Hash Join, Index Seek with
almost an order of magnitude improvement in speed. This was verified by running
the “Display Estimated Execution Plan” again after the change.
Sp_find_root_blocker2
This stored
procedure will capture the details related to the head of the blocking chain.
It should be placed in the MASTER database.
if exists (select * from dbo.sysobjects where id = object_id(N'[dbo].[sp_find_root_blocker2]') and OBJECTPROPERTY(id, N'IsProcedure') = 1) drop procedure [dbo].[sp_find_root_blocker2] GO SET QUOTED_IDENTIFIER ON GO SET ANSI_NULLS ON GO CREATE PROCEDURE sp_find_root_blocker2 /* Object: sp_find_root_blocker Description: Finds the root offender(s) in the chain(s) of blocked processes Usage: sp_find_root_blocker Returns: spid of the root blocking process (returns the last one if there are multiple) Example: sp_find_root_blocker */AS IF EXISTS (SELECT * FROM master..sysprocesses p1 JOIN master..sysprocesses p2 ON (p1.spid=p2.blocked)) BEGIN DECLARE @spid int SELECT @spid=p1.spid -- Get the _last_ prime offender FROM master..sysprocesses p1 JOIN master..sysprocesses p2 ON (p1.spid=p2.blocked) WHERE p1.blocked=0 SELECT p1.spid, p1.status, loginame=LEFT(p1.loginame,20), hostname=substring(p1.hostname,1,20), blk=CONVERT(char(3),p1.blocked), db=LEFT(db_name(p1.dbid),10), p1.cmd, p1.waittype FROM master..sysprocesses p1 JOIN master..sysprocesses p2 ON (p1.spid=p2.blocked) WHERE p1.blocked=0 DBCC INPUTBUFFER(@spid) RETURN(@spid) -- Return the last root block END ELSE BEGIN PRINT 'No processes are currently blocked' RETURN(0) END RETURN 0 GO SET QUOTED_IDENTIFIER OFF GO SET ANSI_NULLS ON GOSp_Kill_Root_Blocker
This stored procedure will kill the head of the blocking chain. It should be placed in the MASTER database.if exists (select * from dbo.sysobjects where id = object_id(N'[dbo].[sp_kill_root_blocker]') and OBJECTPROPERTY(id, N'IsProcedure') = 1) drop procedure [dbo].[sp_kill_root_blocker] GO SET QUOTED_IDENTIFIER OFF GO SET ANSI_NULLS ON GO CREATE PROCEDURE sp_kill_root_blocker /* Object: sp_kill_root_blocker Description: Finds the root offender(s) in the chain(s) of blocked processes and kills them Usage: exec sp_kill_root_blocker */AS WHILE EXISTS (SELECT * FROM master..sysprocesses p1 JOIN master..sysprocesses p2 ON (p1.spid=p2.blocked)) BEGIN DECLARE @spid int DECLARE @KILLSTATE varchar(32) SELECT @spid=p1.spid FROM master..sysprocesses p1 JOIN master..sysprocesses p2 ON (p1.spid=p2.blocked) WHERE p1.blocked=0 select @KILLSTATE = 'KILL ' + CONVERT(char, @spid) print @KILLSTATE exec(@KILLSTATE ) END GO SET QUOTED_IDENTIFIER OFF GO SET ANSI_NULLS ON GO