对不同的ID更新操作竟然也引发死锁?
文章目录
- 对不同的ID更新操作竟然也引发死锁?
- 背景
- 分析
- 初步分析 - 怀疑程序并发问题
- 进一步分析 - 怀疑主键缺失行级锁失效
- 再进一步分析 - 是否存在死锁条件
- 解决方案
- 复盘
- 附录
- 示例的死锁日志
- 常用故障排查 SQL
- 参考链接
背景
我们有一个数据集成平台,主要为上下游系统提供数据传输网关服务,把上游系统的文件传送到下游系统。前段时间,团队同事发现了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) 循环等待条件:若干进程之间形成一种头尾相接的循环等待资源关系。
这四个条件是死锁的必要条件,只要系统发生死锁,这些条件必然成立,而只要上述条件之一不满足,就不会发生死锁。
如下图所示,满足死锁需要两个Session互相持有对方的资源,是否程序中有类似的操作?
经过排查,程序中存在类似如下不同会话的更新操作,这里手动模拟程序的更新操作,因为这里添加了延迟时间,以下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
以下是问题排查过程中用到的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