事故复盘 | 对不同的ID更新操作竟然也引发死锁？

最新推荐文章于 2024-02-27 22:04:26 发布

风筝风筝等等我

最新推荐文章于 2024-02-27 22:04:26 发布

阅读量594

点赞数

分类专栏： mysql 文章标签：数据库 sql

原文链接：https://blog.csdn.net/Evan_Leung/article/details/128555119

版权

mysql 专栏收录该内容

10 篇文章 5 订阅

订阅专栏

文章目录

背景

我们有一个数据集成平台，主要为上下游系统提供数据传输网关服务，把上游系统的文件传送到下游系统。前段时间，团队同事发现了Production的文件经常传输超时，经简单排查发现数据库表中的文件传输状态经常更新失败(例如状态没办法更新为Finished)导致文件被误认为传输超时或者文件处理中断而频繁触发了重试机制。查看应用日志，发现了如下报错：

com.microsoft.sqlserver.jdbc.SQLServerException: Transaction (Process ID) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.

这些报错信息都是发生在有update语句操作附近，并且当我们并行处理的文件越多的时候，报错越频繁。

因为公司的笔记没办法外传到外网，以下是模拟当时发生问题的现场

数据库版本是: 2014 SQL Server

数据库事务隔离级别是如下:
在这里插入图片描述

当时发生问题的数据库表示例:

文件都处于PROCESSING状态等待更新

在这里插入图片描述

分析

因为我们自己没有生成数据库admin权限，没办法获取到数据库日志。

初步分析 - 怀疑程序并发问题

因此一开始是认为可能是程序并发问题引起，所以往这个方向排查，后面发现基本这些异常都是发生某个表的update操作之后，虽然不同的线程同时操作数据库表，但是查看执行的sql 都是基于主键去操作，并且在日志中并没有发现有同时持有相同ID的update操作，都是类似如下sql操作:

Session 1

 update test set STATUS='FINISHED' ,UPDATE_TIME=getdate() where id=1

Session 2

 update test set STATUS='FINISHED' ,UPDATE_TIME=getdate() where id=2

根据上面的两个sql可以看到，这两个Session分别操作的是不同的的id，两个独立的事务不应该存在资源竞争关系。

进一步分析 - 怀疑主键缺失行级锁失效

因为从上面的sql语句可以看到，本身不相关的两个主键的更新操作，却发生了冲突，很可能是主键确缺失或者唯一索引缺失导致了无办法进行行级锁。查看了下表结构，果然这个表是缺少了主键约束也没有唯一约束，模拟当时数据库表结构大概如下所示：
在这里插入图片描述
手动模拟程序的更新操作，开两个不同的数据库Session，分别去对不同的id进行更新操作

Session 1:

begin transaction trans1
        update test set STATUS='POSTED' ,UPDATE_TIME=getdate() where id=2

Session 2:

begin transaction trans1
        update test set STATUS='POSTED' ,UPDATE_TIME=getdate() where id=1

分别执行上面语句，你会发现这两个事务会被其中一个阻塞，这跟原来的猜想一致，因为主键缺失，这两个操作并不是行锁，所以互相会阻塞，直到对方提交事务或者回滚。虽然这个主键缺失引起两个更新操作阻塞，如果程序中有大量线程并行操作会因为阻塞导致变慢，但是并不会引发死锁。难道还有更深层的原因引发如下死锁问题从而导致频繁更新失败？

com.microsoft.sqlserver.jdbc.SQLServerException: Transaction (Process ID) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.

再进一步分析 - 是否存在死锁条件

产生死锁的四个必要条件：
（1）互斥条件：一个资源每次只能被一个进程使用。
（2）请求与保持条件：一个进程因请求资源而阻塞时，对已获得的资源保持不放。
（3）不剥夺条件:进程已获得的资源，在末使用完之前，不能强行剥夺。
（4）循环等待条件:若干进程之间形成一种头尾相接的循环等待资源关系。
这四个条件是死锁的必要条件，只要系统发生死锁，这些条件必然成立，而只要上述条件之一不满足，就不会发生死锁。

在这里插入图片描述
经过排查，程序中存在类似如下不同会话的更新操作，这里手动模拟程序的更新操作，因为这里添加了延迟时间，以下Sql的执行顺序分别是按操作1，2，3进行。

Session 1

begin
	
    begin transaction trans1
        -- 执行操作1
        -- 开始对id为2的数据进行更新操作
        update test set STATUS='POSTED' ,UPDATE_TIME=getdate() where id=2
        waitfor delay '00:00:10'
        -- 执行操作3
        -- 开始对id为3的数据进行更新操作
        update test set STATUS='FINISHED' ,UPDATE_TIME=getdate() where id=3
        EXEC sp_lock @@spid
        print convert(nvarchar(30),convert(datetime,getdate(),121),121)
    commit transaction
end

Session 2

-- 开始对id为1的数据进行更新操作
begin
     
    begin transaction trans2
        print convert(nvarchar(30),convert(datetime,getdate(),121),121)
        -- 执行操作2
        update test set STATUS='FINISHED' ,UPDATE_TIME=getdate() where id=1
        waitfor delay '00:00:5'
        EXEC sp_lock @@spid
        print convert(nvarchar(30),convert(datetime,getdate(),121),121)
    commit transaction

end
go

对以上Session 1和 Session 2的SQL分别在两个会话执行，就会看到如下死锁信息出现，SQL Server并不会让这两个进程无限等待下去，而是选择一个更加容易Rollback的事务作为牺牲品，而另一个事务得以正常执行。
在这里插入图片描述

我们选取以上Update语句查看执行计划，可以看到虽然过滤条件是 Where id=2，但是由于id 字段缺少主键索引，所以实际检索数据是采用的是Table Scan

在这里插入图片描述

对于以上死锁过程大概如下：

因为表中 ID缺少主键约束，对于两个会话，都需要进行全表扫描。 Session 1的操作一更新扫描所有记录，扫描过程会对扫描的每一条记录下U锁，如果满足更新条件，则转化为X锁更新；操作一完成后，第一个更新的记录保持X锁（因为事务没有完成），Session 1等待操作2更新操作

对于Session 2的更新操作，与Session 1的更新过程相同，如果更新的记录在Session 1的操作一更新的记录之前，那么Session 2所在的更新记录也会持有X锁，但在扫描记录进行到Session 1的一个更新的记录的时候，需要等待Session 1完成（已经有X锁的记录无法下U锁），这个时候Session 2被Session 1阻塞

对于Session 1，操作三的更新进行时，它也扫描所有记录，进行到操作三的更新所在的记录的时候，它无法取得U锁（因为已经被Session 2下了X锁），这个时候Session 1等待Session 2完成。在这种情况下，Session 1和Session 2就是互相等待了，符合死锁条件

在这里插入图片描述
如果Session 2更新的记录在Session 1第一个更新操作的记录之后，那么Session 2的U扫描行到Session 1第一次更新记录的时候，就会因为锁冲突导致无法进行下去，必须等待查询一完成，这个时候Session 2没有会导致Session 2第一个更新无法进行的锁，也就不会导致死锁了

将操作1和操作2更新条件替换下，以下不会发生死锁

Session 1

begin
	
    begin transaction trans1
        -- 执行操作1
        -- 开始对id为2的数据进行更新操作
        update test set STATUS='POSTED' ,UPDATE_TIME=getdate() where id=1
        waitfor delay '00:00:10'
        -- 执行操作3
        -- 开始对id为3的数据进行更新操作
        update test set STATUS='FINISHED' ,UPDATE_TIME=getdate() where id=3
        EXEC sp_lock @@spid
        print convert(nvarchar(30),convert(datetime,getdate(),121),121)
    commit transaction
end

Session 2

-- 开始对id为1的数据进行更新操作
begin
     
    begin transaction trans2
        print convert(nvarchar(30),convert(datetime,getdate(),121),121)
        -- 执行操作2
        update test set STATUS='FINISHED' ,UPDATE_TIME=getdate() where id=2
        waitfor delay '00:00:5'
        EXEC sp_lock @@spid
        print convert(nvarchar(30),convert(datetime,getdate(),121),121)
    commit transaction

end
go

锁的兼容关系:

在这里插入图片描述

解决方案

经过上面的分析就知道，这个问题主要是表缺失主键索引产生的，因为我们一直都认为表ID字段都添加了主键约束，不同ID之间的操作不应该会出现资源竞争问题，至于为什么会导致ID主键约束缺失，后面会提到。

以上问题，只需要添加主键约束就可以解决

在这里插入图片描述

再查看执行计划可以发现，这时候Update语句走的是Index Seek，这时候加锁范围只会针对对应ID的行，不同ID之间的更新操作可以相互独立，也就不存在以上不同ID操作也会被其他事务加锁的问题。

在这里插入图片描述
之前的两个会话操作就会变成互不干扰了

复盘

1.为什么表会缺少主键约束，明明我们自己创建表的规范都是有指定主键的？

答：经事后排查，我们的表原本的创建语句都有指定ID为Primary Key，但是之前有同事做一些新改动发布过程中发现有些问题，做过数据库表回滚，他大概的操作如下：

通过主表来创建一个备份表 -> 执行SQL -> 发布过程中发现问题 -> 直接把备份表rename成原表

这个回滚过程有个很大的问题就是最后一步，直接把备份表改名为原表名字，我们可以通过以下示例对比看看:

创建备份表test_bk

Select * into test_bk  from  test

对比 test_bk 和原表 test

在这里插入图片描述

从上图可以看出，新的备份表会直接把原表的表结构丢失掉，例如主键约束、索引、默认值等通通都丢失了，如果这时候直接rename成原表会有很大问题

因此对于这些回滚操作，最好就是从备份表往原表同步更新来还原数据，而不是直接rename备份表

2.这次主键约束缺失，主要影响什么？

影响了文件传输性能，因为主键约束缺失直接导致了我们的文件传输表慢，因为在更新状态的时候不同ID操作会阻塞，造成文件传输经常延迟。
当并行处理的文件比较多的时候，频繁出现死锁，导致大量状态没办法正常从中间状态更新到完成状态。

附录

示例的死锁日志

"Node:1
"
RID: 5:1:344:1                 CleanCnt:2 Mode:X Flags: 0x3
 Grant List 2:
   Owner:0x00000010693353C0 Mode: X        Flg:0x40 Ref:0 Life:02000000 SPID:52 ECID:0 XactLockInfo: 0x0000001064B0C458
   SPID: 52 ECID: 0 Statement Type: UPDATE Line #: 7
"   Input Buf: Language Event: begin
    begin transaction trans1

        update test set STATUS='POSTED' ,UPDATE_TIME=getdate() where id=2

        waitfor delay '00:00:10'
        update test set STATUS='FINISHED' ,UPDATE_TIME=getdate() where id=3
        EXEC sp_lock @@spid
       "
Requested by: 
  ResType:LockOwner Stype:'OR'Xdes:0x000000106FDD4420 Mode: U SPID:55 BatchID:0 ECID:0 TaskProxy:(0x000000105E9F29C8) Value:0x69337e80 Cost:(0/204)

"Node:2
"
RID: 5:1:344:0                 CleanCnt:2 Mode:X Flags: 0x3
 Grant List 3:
   Owner:0x0000001069337EC0 Mode: X        Flg:0x40 Ref:0 Life:02000000 SPID:55 ECID:0 XactLockInfo: 0x000000106FDD4458
   SPID: 55 ECID: 0 Statement Type: UPDATE Line #: 5
"   Input Buf: Language Event: begin

    begin transaction trans1
        print convert(nvarchar(30),convert(datetime,getdate(),121),121)
        update test set STATUS='FINISHED' ,UPDATE_TIME=getdate() where id=1
        waitfor delay '00:00:5'
        EXEC sp_lock @@spid
        pri"
Requested by: 
  ResType:LockOwner Stype:'OR'Xdes:0x0000001064B0C420 Mode: U SPID:52 BatchID:0 ECID:0 TaskProxy:(0x000000105D0549C8) Value:0x635cf7c0 Cost:(0/260)
deadlock-list
 deadlock victim=process1064166108

  process-list
Victim Resource Owner:
   process id=process1064166108 taskpriority=0 logused=204 waitresource=RID: 5:1:344:1 waittime=10244 ownerId=275988 transactionname=trans1 lasttranstarted=2023-01-07T08:52:05.943 XDES=0x106fdd4420 lockMode=U schedulerid=8 kpid=636 status=suspended spid=55 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2023-01-07T08:52:05.950 lastbatchcompleted=2023-01-07T08:52:05.903 lastattention=1900-01-01T00:00:00.903 clientapp=DataGrip hostname=evans-MBP hostpid=0 loginname=sa isolationlevel=read committed (2) xactid=275988 currentdb=5 currentdbname=eshare lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
 ResType:LockOwner Stype:'OR'Xdes:0x000000106FDD4420 Mode: U SPID:55 BatchID:0 ECID:0 TaskProxy:(0x000000105E9F29C8) Value:0x69337e80 Cost:(0/204)
    executionStack
     frame procname=adhoc line=5 stmtstart=58 stmtend=200 sqlhandle=0x020000006227ac2f5e0a64227f6467e5fa57c604e53826490000000000000000000000000000000000000000
unknown     
     frame procname=adhoc line=5 stmtstart=232 stmtend=364 sqlhandle=0x02000000b5f1463824ed88c284aae5d42e896d3b69f9774b0000000000000000000000000000000000000000
unknown     
    inputbuf
"begin

    begin transaction trans1
        print convert(nvarchar(30),convert(datetime,getdate(),121),121)
        update test set STATUS='FINISHED' ,UPDATE_TIME=getdate() where id=1
        waitfor delay '00:00:5'
        EXEC sp_lock @@spid
        print convert(nvarchar(30),convert(datetime,getdate(),121),121)
    commit transaction

end    "
   process id=process1066d868c8 taskpriority=0 logused=260 waitresource=RID: 5:1:344:0 waittime=3467 ownerId=275976 transactionname=trans1 lasttranstarted=2023-01-07T08:52:02.720 XDES=0x1064b0c420 lockMode=U schedulerid=6 kpid=992 status=suspended spid=52 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2023-01-07T08:52:02.720 lastbatchcompleted=2023-01-07T08:52:02.697 lastattention=1900-01-01T00:00:00.697 clientapp=DataGrip hostname=evans-MBP hostpid=0 loginname=sa isolationlevel=read committed (2) xactid=275976 currentdb=5 currentdbname=eshare lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
    executionStack
     frame procname=adhoc line=7 stmtstart=58 stmtend=200 sqlhandle=0x020000006227ac2f5e0a64227f6467e5fa57c604e53826490000000000000000000000000000000000000000
unknown     
     frame procname=adhoc line=7 stmtstart=304 stmtend=436 sqlhandle=0x02000000703972165ec8ceaa22c8deabb6c86e1d2e7ae2070000000000000000000000000000000000000000
unknown     
    inputbuf
"begin
    begin transaction trans1

        update test set STATUS='POSTED' ,UPDATE_TIME=getdate() where id=2

        waitfor delay '00:00:10'
        update test set STATUS='FINISHED' ,UPDATE_TIME=getdate() where id=3
        EXEC sp_lock @@spid
        print convert(nvarchar(30),convert(datetime,getdate(),121),121)
    commit transaction
end    "
  resource-list
   ridlock fileid=1 pageid=344 dbid=5 objectname=eshare.dbo.test id=lock1066ddf380 mode=X associatedObjectId=72057594042974208
    owner-list
     owner id=process1066d868c8 mode=X
    waiter-list
     waiter id=process1064166108 mode=U requestType=wait
   ridlock fileid=1 pageid=344 dbid=5 objectname=eshare.dbo.test id=lock1066dda280 mode=X associatedObjectId=72057594042974208
    owner-list
     owner id=process1064166108 mode=X
    waiter-list
"     waiter id=process1066d868c8 mode=U requestType=wait
"

常用故障排查 SQL

-- 插入样本数据
INSERT INTO test ( FILE_NAME, STATUS, CREATE_TIME, UPDATE_TIME) VALUES('1.CSV','PROCESSING',getdate(),getdate())
go
INSERT INTO test ( FILE_NAME, STATUS, CREATE_TIME, UPDATE_TIME) VALUES('2.CSV','PROCESSING',getdate(),getdate())
go

INSERT INTO test (FILE_NAME, STATUS, CREATE_TIME, UPDATE_TIME) VALUES('3.CSV','PROCESSING',getdate(),getdate())
go


-- 清除表数据
truncate table test
go

-- 查看锁表语句
select request_session_id spid,OBJECT_NAME(resource_associated_entity_id) tableName
from sys.dm_tran_locks where resource_type='OBJECT'


-- 开启锁日志追踪
--a. 开启跟踪死锁
DBCC TRACEON(3605,1204,1222,-1)

--b. 关闭信号跟踪
DBCC TRACEOFF(1222,-1)
DBCC TRACEOFF(1204,-1)

--c. 查看信号跟踪是否开启。
DBCC TRACESTATUS(1204,-1)
DBCC TRACESTATUS(1222,-1)

-- 查看死锁日志
EXEC xp_ReadErrorLog 0, 1
go

-- 查询阻塞语句
select dbid,* from sys.sysprocesses
where 1=1
  and spid >50
  and blocked <> 0

-- 查询阻塞数据
Select name,dbid from master.sys.sysdatabases where dbid=5

-- 查询死锁或阻塞语句
DBCC INPUTBUFFER(51)
go

-- 查看锁
EXEC sp_lock 55
-- 查看数据库链接
SELECT * FROM SYS.DM_TRAN_LOCKS WHERE RESOURCE_TYPE='OBJECT'

参考链接

https://www.cnblogs.com/wanglg/p/3751895.html

风筝风筝等等我

关注

0
点赞
踩
1

收藏

觉得还不错? 一键收藏
0
评论
事故复盘 | 对不同的ID更新操作竟然也引发死锁？

对于Session 2的更新操作，与Session 1的更新过程相同，如果更新的记录在Session 1的操作一更新的记录之前，那么Session 2所在的更新记录也会持有X锁，但在扫描记录进行到Session 1的一个更新的记录的时候，需要等待Session 1完成（已经有X锁的记录无法下U锁），这个时候Session 2被Session 1阻塞。经过排查，程序中存在类似如下不同会话的更新操作，这里手动模拟程序的更新操作，因为这里添加了延迟时间，以下Sql的执行顺序分别是按操作1，2，3进行。
复制链接

扫一扫

专栏目录