I have encountered a situation where a user has run something in one of our applications which runs a stored procedure. The stored procedure does a few bits of logging (INSERTing to a log table) and then performs a simple delete in the format
DELETE FROM MyTable WHERE Id = 1
The DELETE is deleting tens of thousands of records from a table with millions of rows (the stored procedure does this for a number of tables) and produces a parellel execution plan. The column Id, is the second column in a composite primary key but the table does not have any indexes leading with that column.
The DELETE plan is available here
The anonymised DDL for the table is below
CREATE TABLE [dbo].MyTable
(
[Column15] [varchar](50) NULL,
[Column16] [int] NULL,
[Column2] [datetime] NULL,
[Column3] [datetime] NULL,
[Column4] [varchar](50) NOT NULL,
[Column5] [datetime] NULL,
[Column17] [varchar](8) NULL,
[Column18] [varchar](50) NULL,
[Column6] [int] NULL,
[Column7] [int] NULL,
[Column9] [int] NULL,
[Column8] [int] NULL,
[Column19] [varchar](50) NULL,
[Column20] [varchar](50) NULL,
[Column21] [varchar](50) NULL,
[Column22] [varchar](50) NULL,
[Column23] [varchar](50) NULL,
[Column24] [varchar](50) NULL,
[Column25] [varchar](50) NULL,
[Column26] [varchar](50) NULL,
[Column10] [datetime] NULL,
[Column27] [varchar](50) NULL,
[Column28] [varchar](50) NULL,
[Column29] [varchar](50) NULL,
[Column30] [varchar](50) NULL,
[Column31] [varchar](50) NULL,
[Column32] [datetime] NULL,
[Column33] [datetime] NULL,
[Column34] [int] NULL,
[Column35] [varchar](50) NULL,
[Column11] [char](1) NULL,
[Column36] [char](1) NULL,
[Column12] [char](1) NULL,
[Column37] [char](1) NULL,
[Column38] [char](1) NULL,
[Column39] [char](1) NULL,
[Column40] [char](1) NULL,
[Column41] [char](1) NULL,
[Column42] [datetime] NULL,
[Column13] [varchar](50) NULL,
[Column43] [varchar](50) NULL,
[Column44] [varchar](50) NULL,
[Column45] [varchar](50) NULL,
[Column46] [varchar](50) NULL,
[Column47] [varchar](50) NULL,
[Column48] [varchar](50) NULL,
[Column49] [varchar](50) NULL,
[Column50] [varchar](255) NULL,
[Column51] [varchar](50) NULL,
[Column52] [varchar](50) NULL,
[Column53] [varchar](50) NULL,
[Column54] [varchar](50) NULL,
[Column55] [varchar](50) NULL,
[Column56] [varchar](50) NULL,
[Column57] [varchar](50) NULL,
[Column58] [varchar](50) NULL,
[Column59] [varchar](50) NULL,
[Column60] [varchar](50) NULL,
[Column61] [varchar](50) NULL,
[Column62] [varchar](50) NULL,
[Column63] [varchar](50) NULL,
[Column64] [int] NOT NULL,
[Column65] [varchar](50) NULL,
[Column66] [varchar](255) NULL,
[Column67] [varchar](50) NULL,
[Column68] [varchar](50) NULL,
[Column14] [varchar](50) NOT NULL,
[Column69] [varchar](50) NULL,
[Column70] [varchar](255) NULL,
[Column71] [varchar](50) NULL,
[Column72] [int] NULL,
[Column73] [varchar](50) NULL,
[Column74] [varchar](255) NULL,
[Column75] [varchar](50) NULL,
[Column76] [varchar](255) NULL,
[Column77] [varchar](50) NULL,
[Column78] [varchar](50) NULL,
[Column79] [varchar](255) NULL,
[Column80] [varchar](50) NULL,
[Column81] [varchar](50) NULL,
[Column82] [char](1) NULL,
[Column83] [char](1) NULL,
[Column84] [date] NULL,
[Column85] [date] NULL,
[Column86] [date] NULL,
[Column87] [date] NULL,
[Column88] [date] NULL,
CONSTRAINT [MyConstraintName] PRIMARY KEY CLUSTERED
(
[Columnn4] ASC,
[Column1] ASC,
[Column14] ASC
)
WITH
(
PAD_INDEX = OFF,
STATISTICS_NORECOMPUTE = OFF,
IGNORE_DUP_KEY = OFF,
ALLOW_ROW_LOCKS = ON,
ALLOW_PAGE_LOCKS = ON
)
)
GO
ALTER TABLE [dbo].[MyTable] ADD DEFAULT ('MyDefault') FOR [COLUMN_14]
GO
CREATE NONCLUSTERED INDEX [IDX_MyTable] ON [dbo].[MyTable]
(
[Column11] ASC,
[Column12] ASC,
[Column10] ASC,
[Column9] ASC,
[Column8] ASC,
[Column5] ASC,
[Column2] ASC,
[Column3] ASC,
[Column13] ASC,
[Column6] ASC,
[Column7] ASC
)
WITH
(
PAD_INDEX = OFF,
STATISTICS_NORECOMPUTE = OFF,
SORT_IN_TEMPDB = OFF,
DROP_EXISTING = OFF,
ONLINE = OFF,
ALLOW_ROW_LOCKS = ON,
ALLOW_PAGE_LOCKS = ON
)
The user reported that the application wasn't doing anything and when I looked in SQL Server using sp_whoisactive, I can see what appears to be deadlock:
We can see sessions 98 & 99 and 69 are blocked by 107 but 107 is blocked by 69 so there is a deadlock between 69 and 107 - they are both waiting on the other releasing locks?
I grabbed the sp_whoisactive @get_locks = 1 output for each 69 and 107 and can see they both appear to have been granted page locks on an index (though we can't see which page) and are waiting for a lock on a different page within the index:
<Database name="MyDB">
<Locks>
<Lock request_mode="S" request_status="GRANT" request_count="1" />
</Locks>
<Objects>
<Object name="Mytable" schema_name="dbo">
<Locks>
<Lock resource_type="OBJECT" request_mode="IX" request_status="GRANT" request_count="9" />
<Lock resource_type="PAGE" page_type="*" index_name="IDX_Mytable" request_mode="U" request_status="GRANT" request_count="337" />
<Lock resource_type="PAGE" page_type="*" index_name="IDX_MyTable" request_mode="U" request_status="WAIT" request_count="8" />
</Locks>
</Object>
</Objects>
</Database>
<Database name="MyDB">
<Locks>
<Lock request_mode="S" request_status="GRANT" request_count="1" />
</Locks>
<Objects>
<Object name="MyTable" schema_name="dbo">
<Locks>
<Lock resource_type="OBJECT" request_mode="IX" request_status="GRANT" request_count="9" />
<Lock resource_type="PAGE" page_type="" index_name="IDX_MyTable" request_mode="U" request_status="GRANT" request_count="685415" />
<Lock resource_type="PAGE" page_type="" index_name="IDX_MyTable" request_mode="U" request_status="WAIT" request_count="4" />
</Locks>
</Object>
</Objects>
</Database>
<Database name="tempdb">
<Objects>
<Object name="(null)">
<Locks>
<Lock resource_type="DATABASE.ENCRYPTION_SCAN" request_mode="S" request_status="GRANT" request_count="2" />
</Locks>
</Object>
</Objects>
</Database>
sure enough, I KILLed session 69 and the remaining three sessions completed.
The following are block process reports between session 69 and 107 (and interestingly, a block report for session 69 blocking itself!?):
69 Blocking 107
<event name="blocked_process_report" package="sqlserver" timestamp="2022-06-01T09:36:33.217Z">
<data name="duration">
<value>5291794000</value>
</data>
<data name="database_id">
<value>7</value>
</data>
<data name="object_id">
<value>0</value>
</data>
<data name="index_id">
<value>0</value>
</data>
<data name="lock_mode">
<value>4</value>
<text>U</text>
</data>
<data name="transaction_id">
<value>4524669110</value>
</data>
<data name="resource_owner_type">
<value>0x00000001</value>
<text>LOCK</text>
</data>
<data name="blocked_process">
<value>
<blocked-process-report monitorLoop="386256">
<blocked-process>
<process id="processf491f8a4e8" taskpriority="0" logused="0" waitresource="PAGE: 7:8:40517682 " waittime="5291794" ownerId="4524669110" transactionname="DELETE" lasttranstarted="2022-06-01T09:08:12.210" XDES="0xfc5d2fdc40" lockMode="U" schedulerid="11" kpid="78972" status="suspended" spid="107" sbid="0" ecid="2" priority="0" trancount="0" lastbatchstarted="2022-06-01T09:06:18.560" lastbatchcompleted="2022-06-01T09:06:18.550" lastattention="1900-01-01T00:00:00.550" clientapp=".Net SqlClient Data Provider" hostname="MyServer" hostpid="52940" isolationlevel="read committed (2)" xactid="4524669110" currentdb="7" currentdbname="MyDB" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
<executionStack>
<frame line="1" stmtstart="6116" stmtend="6236" sqlhandle="0x020000003320a71f1f003704cf13be99833b422d70e704c70000000000000000000000000000000000000000" />
<frame line="1" stmtstart="6116" stmtend="6236" sqlhandle="0x020000009d132a27f589a9771a2be6d262e2dcecf057db6d0000000000000000000000000000000000000000" />
<frame line="61" stmtstart="5794" stmtend="5814" sqlhandle="0x030007007d01b22be394d50083ae000001000000000000000000000000000000000000000000000000000000" />
<frame line="1" stmtend="90" sqlhandle="0x01000700990d272800ffb8abec00000000000000000000000000000000000000000000000000000000000000" />
</executionStack>
<inputbuf>
EXEC dbo.MyProc 'MyParam', 542 </inputbuf>
</process>
</blocked-process>
<blocking-process>
<process status="suspended" waitresource="PAGE: 7:4:40156264 " waittime="5291779" spid="69" sbid="0" ecid="4" priority="0" trancount="0" lastbatchstarted="2022-06-01T09:06:10.557" lastbatchcompleted="2022-06-01T09:06:10.550" lastattention="1900-01-01T00:00:00.550" clientapp=".Net SqlClient Data Provider" hostname="MyServer" hostpid="52940" isolationlevel="read committed (2)" xactid="4524737805" currentdb="7" currentdbname="MyDB" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
<executionStack>
<frame line="1" stmtstart="6116" stmtend="6236" sqlhandle="0x020000003320a71f1f003704cf13be99833b422d70e704c70000000000000000000000000000000000000000" />
<frame line="1" stmtstart="6116" stmtend="6236" sqlhandle="0x02000000c6cda92c3611dbd63ae5aab8d90f06e394ee900c0000000000000000000000000000000000000000" />
<frame line="61" stmtstart="5794" stmtend="5814" sqlhandle="0x030007007d01b22be394d50083ae000001000000000000000000000000000000000000000000000000000000" />
<frame line="1" stmtend="90" sqlhandle="0x010007003ebee03a606e2cc9df00000000000000000000000000000000000000000000000000000000000000" />
</executionStack>
<inputbuf>
EXEC dbo.MyProc 'MyParam', 541 </inputbuf>
</process>
</blocking-process>
</blocked-process-report>
</value>
</data>
<data name="database_name">
<value>MyDb</value>
</data>
</event>
107 Blocking 69
<event name="blocked_process_report" package="sqlserver" timestamp="2022-06-01T09:36:33.216Z">
<data name="duration">
<value>5291778000</value>
</data>
<data name="database_id">
<value>7</value>
</data>
<data name="object_id">
<value>0</value>
</data>
<data name="index_id">
<value>0</value>
</data>
<data name="lock_mode">
<value>4</value>
<text>U</text>
</data>
<data name="transaction_id">
<value>4524737805</value>
</data>
<data name="resource_owner_type">
<value>0x00000001</value>
<text>LOCK</text>
</data>
<data name="blocked_process">
<value>
<blocked-process-report monitorLoop="386256">
<blocked-process>
<process id="process923873f468" taskpriority="0" logused="0" waitresource="PAGE: 7:4:40156264 " waittime="5291778" ownerId="4524737805" transactionname="DELETE" lasttranstarted="2022-06-01T09:08:20.940" XDES="0x8b14c02960" lockMode="U" schedulerid="11" kpid="118356" status="suspended" spid="69" sbid="0" ecid="4" priority="0" trancount="0" lastbatchstarted="2022-06-01T09:06:10.557" lastbatchcompleted="2022-06-01T09:06:10.550" lastattention="1900-01-01T00:00:00.550" clientapp=".Net SqlClient Data Provider" hostname="MyServer" hostpid="52940" isolationlevel="read committed (2)" xactid="4524737805" currentdb="7" currentdbname="MyDB" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
<executionStack>
<frame line="1" stmtstart="6116" stmtend="6236" sqlhandle="0x020000003320a71f1f003704cf13be99833b422d70e704c70000000000000000000000000000000000000000" />
<frame line="1" stmtstart="6116" stmtend="6236" sqlhandle="0x02000000c6cda92c3611dbd63ae5aab8d90f06e394ee900c0000000000000000000000000000000000000000" />
<frame line="61" stmtstart="5794" stmtend="5814" sqlhandle="0x030007007d01b22be394d50083ae000001000000000000000000000000000000000000000000000000000000" />
<frame line="1" stmtend="90" sqlhandle="0x010007003ebee03a606e2cc9df00000000000000000000000000000000000000000000000000000000000000" />
</executionStack>
<inputbuf>
EXEC dbo.MyProc 'MyParam', 541 </inputbuf>
</process>
</blocked-process>
<blocking-process>
<process status="suspended" waittime="5283425" spid="107" sbid="0" ecid="6" priority="0" trancount="0" lastbatchstarted="2022-06-01T09:06:18.560" lastbatchcompleted="2022-06-01T09:06:18.550" lastattention="1900-01-01T00:00:00.550" clientapp=".Net SqlClient Data Provider" hostname="MyServer" hostpid="52940" isolationlevel="read committed (2)" xactid="4524669110" currentdb="7" currentdbname="MyDB" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
<executionStack>
<frame line="1" stmtstart="6116" stmtend="6236" sqlhandle="0x020000003320a71f1f003704cf13be99833b422d70e704c70000000000000000000000000000000000000000" />
<frame line="1" stmtstart="6116" stmtend="6236" sqlhandle="0x020000009d132a27f589a9771a2be6d262e2dcecf057db6d0000000000000000000000000000000000000000" />
<frame line="61" stmtstart="5794" stmtend="5814" sqlhandle="0x030007007d01b22be394d50083ae000001000000000000000000000000000000000000000000000000000000" />
<frame line="1" stmtend="90" sqlhandle="0x01000700990d272800ffb8abec00000000000000000000000000000000000000000000000000000000000000" />
</executionStack>
<inputbuf>
EXEC dbo.MyProc 'MyParam', 542 </inputbuf>
</process>
</blocking-process>
</blocked-process-report>
</value>
</data>
<data name="database_name">
<value>MyDB</value>
</data>
</event>
69 Blocking 69
<event name="blocked_process_report" package="sqlserver" timestamp="2022-06-01T09:36:33.216Z">
<data name="duration">
<value>5291785000</value>
</data>
<data name="database_id">
<value>7</value>
</data>
<data name="object_id">
<value>0</value>
</data>
<data name="index_id">
<value>0</value>
</data>
<data name="lock_mode">
<value>4</value>
<text>U</text>
</data>
<data name="transaction_id">
<value>4524737805</value>
</data>
<data name="resource_owner_type">
<value>0x00000001</value>
<text>LOCK</text>
</data>
<data name="blocked_process">
<value>
<blocked-process-report monitorLoop="386256">
<blocked-process>
<process id="processbd825f2108" taskpriority="0" logused="0" waitresource="PAGE: 7:9:42316852 " waittime="5291785" ownerId="4524737805" transactionname="DELETE" lasttranstarted="2022-06-01T09:08:20.940" XDES="0x89f1981100" lockMode="U" schedulerid="12" kpid="124532" status="suspended" spid="69" sbid="0" ecid="2" priority="0" trancount="0" lastbatchstarted="2022-06-01T09:06:10.557" lastbatchcompleted="2022-06-01T09:06:10.550" lastattention="1900-01-01T00:00:00.550" clientapp=".Net SqlClient Data Provider" hostname="MyServer" hostpid="52940" isolationlevel="read committed (2)" xactid="4524737805" currentdb="7" currentdbname="MyDB" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
<executionStack>
<frame line="1" stmtstart="6116" stmtend="6236" sqlhandle="0x020000003320a71f1f003704cf13be99833b422d70e704c70000000000000000000000000000000000000000" />
<frame line="1" stmtstart="6116" stmtend="6236" sqlhandle="0x02000000c6cda92c3611dbd63ae5aab8d90f06e394ee900c0000000000000000000000000000000000000000" />
<frame line="61" stmtstart="5794" stmtend="5814" sqlhandle="0x030007007d01b22be394d50083ae000001000000000000000000000000000000000000000000000000000000" />
<frame line="1" stmtend="90" sqlhandle="0x010007003ebee03a606e2cc9df00000000000000000000000000000000000000000000000000000000000000" />
</executionStack>
<inputbuf>
EXEC dbo.MyProc 'My Param', 541 </inputbuf>
</process>
</blocked-process>
<blocking-process>
<process status="suspended" waitresource="PAGE: 7:9:42316852 " waittime="5291791" spid="69" sbid="0" ecid="5" priority="0" trancount="0" lastbatchstarted="2022-06-01T09:06:10.557" lastbatchcompleted="2022-06-01T09:06:10.550" lastattention="1900-01-01T00:00:00.550" clientapp=".Net SqlClient Data Provider" hostname="MyServer" hostpid="52940" isolationlevel="read committed (2)" xactid="4524737805" currentdb="7" currentdbname="MyDB" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
<executionStack>
<frame line="1" stmtstart="6116" stmtend="6236" sqlhandle="0x020000003320a71f1f003704cf13be99833b422d70e704c70000000000000000000000000000000000000000" />
<frame line="1" stmtstart="6116" stmtend="6236" sqlhandle="0x02000000c6cda92c3611dbd63ae5aab8d90f06e394ee900c0000000000000000000000000000000000000000" />
<frame line="61" stmtstart="5794" stmtend="5814" sqlhandle="0x030007007d01b22be394d50083ae000001000000000000000000000000000000000000000000000000000000" />
<frame line="1" stmtend="90" sqlhandle="0x010007003ebee03a606e2cc9df00000000000000000000000000000000000000000000000000000000000000" />
</executionStack>
<inputbuf>
EXEC dbo.MyProc 'My Param', 541 </inputbuf>
</process>
</blocking-process>
</blocked-process-report>
</value>
</data>
<data name="database_name">
<value>MyDB</value>
</data>
</event>
I can also see using dm_tran_locks that one session appears to have blocked itself on the same resources. (note this output is from a subsequent run and the session IDs involved have changed to 83 and 58)
/* which session has the lock on the resources that session 83 is waiting */
SELECT resource_description,
request_status,
request_session_id
FROM sys.dm_tran_locks
WHERE resource_description IN (
SELECT resource_description
FROM sys.dm_tran_locks
WHERE request_session_id IN (83) AND
request_status = 'WAIT'
) AND
request_status = 'GRANT'
/* which session has the lock on the resources that session 58 is waiting */
SELECT resource_description,
request_status,
request_session_id
FROM sys.dm_tran_locks
WHERE resource_description IN (
SELECT resource_description
FROM sys.dm_tran_locks
WHERE request_session_id IN (58) AND
request_status = 'WAIT'
) AND
request_status = 'GRANT'
What has happened here? was it a deadlock? If so, why did SQL Server not interevene?
Version details:
Microsoft SQL Server 2016 (SP2-CU17) (KB5001092) - 13.0.5888.11 (X64)
Mar 19 2021 19:41:38
Copyright (c) Microsoft Corporation
Enterprise Edition: Core-based Licensing (64-bit) on Windows Server 2012 R2 Datacenter 6.3 <X64> (Build 9600: ) (Hypervisor)
