10

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:

enter image description here

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'

enter image description here

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)
6
  • 1
    This question is gradually improving, but I still cannot understand the preference for vague textual description ("The column Id, is the second column in a composite primary key but the table does not have any indexes leading with that column.") rather than just showing DDL for table indexes and the delete plan shape. Separately, do you monitor deadlocks? Are you seeing lots of them? Resolving deadlocks isn't instant.
    – Paul White
    Jun 29, 2022 at 8:29
  • Hi @PaulWhite , I appreciate what you are saying - the vague textual description is because I am struggling to 100% replicate the problem within the app layer, let alone be able to work out which is relevant DDL (which tables, which indexes) to be able to form a reproducible case . I am continuing to investigate an add info as I go. I will endeavour to upload the (Anonymised) delete plan today. We do monitor deadlocks using the system_health XE session, though I don't believe I have seen any which include these tables (this delete process is ad hoc rather than frequent)
    – SE1986
    Jun 29, 2022 at 9:23
  • @PaulWhite I've added a link to the delete plan now. I will also try to add the Table DDL and the Clustered Index DDL once I have anonymised them
    – SE1986
    Jun 29, 2022 at 10:42
  • SQL Server queries have a MAXDOP query hint option: OPTION (MAXDOP 1) at the end of the query. This will disable parallelization for only the hinted query and should stop deadlocks. MAXDOP Query Hint
    – JBJ
    Aug 12, 2022 at 15:36
  • @JBJ how do we know paralellism is the cause?
    – SE1986
    Aug 13, 2022 at 17:08

0