MSSqlServer Select与Insert高并发下的死锁
小编:啊南 264阅读 2020.11.30
目录
1 事件回放 2 DB Trace 线索整理 3 Log 线索整理 4 当时的数据库配置说明 5 原因分析 6 解决方案
事件回放
客服和市场部反应积分游戏-大转盘出现无法查询“投注记录”,点击抽奖后一直超时导致球进入问号区域无法获知抽奖结果。
随后接到系统室的通知,数据库层面有大量死锁,CPU 利用率已达到瓶颈值,随后跟市场部联系将游戏入口切换到升级页面,停掉应用,迅速协查原因。
BI 报表和 Zabbix 监控
接口响应时间阻塞严重
请求路径
请求笔数
响应时间平均
响应时间 90
响应时间最大
getBetRecords.json
21,318
37,399
53,257
133,631
drawLottery.json
58,458
28,811
50,172
132,225
DB Trace 线索整理
请参见文件:Database-Dump.zip
关注一下几处关键点
引起死锁的源头:
-- headblockersummary --
select top 6 lelog0*.log_id as log1_3*,
lelog0*.log_activity_code as log2_3*,
lelog0*.log_bet_actor_code as log3_3*,
lelog0*.log_bet_actor_count as log4_3*,
lelog0*.log_bet_actor_name as log5_3*,
lelog0*.log_bet_actor_type as log6_3*,
lelog0\_.log_cmb_accou
io 成本比较高:
plan_total_logical_readsplan_total_exec_count
Log 线索整理
大量的数据库事务回滚
org.hibernate.TransactionException: JDBC rollback failed
at org.springframework.orm.hibernate3.HibernateTransactionManager.doRollback(HibernateTransactionManager.java:679)
Caused by: org.hibernate.TransactionException: JDBC rollback failed
at org.hibernate.transaction.JDBCTransaction.rollback(JDBCTransaction.java:170)
at org.springframework.orm.hibernate3.HibernateTransactionManager.doRollback(HibernateTransactionManager.java:676)
... 89 more
Caused by: java.sql.SQLException: Connection has already been closed.
at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:117)
at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
大量的数据库连接关闭
2015-05-06 08:24:15,073 [catalina-exec-30][org.hibernate.jdbc.abstractbatcher] [WARN][280] - exception clearing maxRows/queryTimeout
com.microsoft.sqlserver.jdbc.SQLServerException: The connection is closed.
at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:190)
at com.microsoft.sqlserver.jdbc.SQLServerConnection.checkClosed(SQLServerConnection.java:388)
at com.microsoft.sqlserver.jdbc.SQLServerStatement.checkClosed(SQLServerStatement.java:978)
at com.microsoft.sqlserver.jdbc.SQLServerStatement.getMaxRows(SQLServerStatement.java:1011)
大量的 Socket 连接关闭
org.springframework.dao.DataAccessResourceFailureException: could not insert: [com.cmbchina.ccd.pluto.lotteryengine.models.LeLog]; nested exception is org.hibernate.exception.JDBCC
onnectionException: could not insert: [com.cmbchina.ccd.pluto.lotteryengine.models.LeLog]
at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:625)
at org.springframework.orm.hibernate3.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:412)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:411)
Caused by: org.hibernate.exception.JDBCConnectionException: could not insert: [com.cmbchina.ccd.pluto.lotteryengine.models.LeLog]
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:74)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
at org.hibernate.id.insert.AbstractReturningDelegate.performInsert(AbstractReturningDelegate.java:40)
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2163)
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2643)
at org.hibernate.action.EntityIdentityInsertAction.execute(EntityIdentityInsertAction.java:51)
at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279)
Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: Socket closed
at com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:1667)
at com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:1654)
at com.microsoft.sqlserver.jdbc.TDSChannel.read(IOBuffer.java:1789)
当时的数据库配置说明
DB Version :Microsoft SqlServer 2008
Le_Log 日志表创建的索引为:
聚集 IDX_ACTIVITY_ACCOUNTID = activityCode + accountId + logUpdateAt
非聚集 IDX_ACTIVITY_USREID = activityCode + userId + logUpdateAt
日志查询语句及执行计划
SELECT top 6 \* FROM LE_LOG WHERE activityCode=? AND userId=? AND updateAt BETWEEN ? AND ?
INDEX Seek 非聚集索引 IDX_ACTIVITY_USREID 找到对应的 rowId
INDEX Seek 聚集索引 IDX_ACTIVITY_ACCOUNTID 根据 rowId 找到对应行其他列的数据
日志插入
INSERT INTO LE_LOG VALUES();
先拿到聚集索引的排它锁,将要插入的行进行物理排序,然后对非聚集索引进行维护
-- 注意,MYSQL的INSERT在RR隔离级别下还有GAP锁的存在。
原因分析(查询事务隔离级别应该为 READ UNCOMMITTED)
在本文的场景中,问题可能就出在非聚集索引与聚集索引的死锁问题上
步骤
Select 过程
Insert 过程
1
Select 获取到对应用户抽奖记录的行共享 S 锁拿到 rowId
2
Insert 获取聚集索引的排它 X 锁
3
根据 rowId 试图获取聚集索引的共享 S 锁查询其他列的数据,阻塞!
4
Insert 需要同步更新非聚集索引,试图获取排它锁 X,被 S 锁阻塞!
所以死锁发生了。。。
大量的事务回滚应该是为了防止死锁造成数据库宕机设置的锁超时机制造成的,一旦无法插入或者查询日志记录就出现了大量的回滚或者连接强制断开,也就是我们在异常日志中看到的。而事务回滚占用的资源量很大,结果就是系统 CPU 利用率不断升高。
解决方案
SQL 语句添加 WITH (NOLOCK) 允许脏读 HQL 语句 Service 的方法前添加 @Transactional(isolation=ISOLATION.READ_UNCOMMITTED)
将 userId 原本的非聚集索引修改为聚集索引, accountId 原本的聚集索引改为非聚集索引。这样投注记录的 select 查询将只走聚集索引 seek。
将 select * from 修改为 select 明确的列 from, 减少 io 数据量
清理数据库:目前抽奖记录因为市场部的强烈要求必须保留 3 个月,所以数据量无法缩减。下期新游戏上线的时候会将投注记录 UI 的提示字样改为一个月,然后同步修改数据库清理脚本为只保留一个月数据。
在查询投注记录明细的时候排序采用的字段是 log_id desc,不是聚集索引中的 log_update_at,导致执行计划中有很大一部分的排序性能消耗,修改为按照更新时间倒序。当初采用 log_id 排序是因为测试过程中发现抽奖过快会出现相同时间戳记录的出现,当然这种概率极低。考虑性能输出,对于相同时间戳的记录排序混乱可以忍受。
1 事件回放 2 DB Trace 线索整理 3 Log 线索整理 4 当时的数据库配置说明 5 原因分析 6 解决方案
事件回放
客服和市场部反应积分游戏-大转盘出现无法查询“投注记录”,点击抽奖后一直超时导致球进入问号区域无法获知抽奖结果。
随后接到系统室的通知,数据库层面有大量死锁,CPU 利用率已达到瓶颈值,随后跟市场部联系将游戏入口切换到升级页面,停掉应用,迅速协查原因。
BI 报表和 Zabbix 监控
接口响应时间阻塞严重
请求路径
请求笔数
响应时间平均
响应时间 90
响应时间最大
getBetRecords.json
21,318
37,399
53,257
133,631
drawLottery.json
58,458
28,811
50,172
132,225
DB Trace 线索整理
请参见文件:Database-Dump.zip
关注一下几处关键点
引起死锁的源头:
-- headblockersummary --
select top 6 lelog0*.log_id as log1_3*,
lelog0*.log_activity_code as log2_3*,
lelog0*.log_bet_actor_code as log3_3*,
lelog0*.log_bet_actor_count as log4_3*,
lelog0*.log_bet_actor_name as log5_3*,
lelog0*.log_bet_actor_type as log6_3*,
lelog0\_.log_cmb_accou
io 成本比较高:
plan_total_logical_readsplan_total_exec_count
Log 线索整理
大量的数据库事务回滚
org.hibernate.TransactionException: JDBC rollback failed
at org.springframework.orm.hibernate3.HibernateTransactionManager.doRollback(HibernateTransactionManager.java:679)
Caused by: org.hibernate.TransactionException: JDBC rollback failed
at org.hibernate.transaction.JDBCTransaction.rollback(JDBCTransaction.java:170)
at org.springframework.orm.hibernate3.HibernateTransactionManager.doRollback(HibernateTransactionManager.java:676)
... 89 more
Caused by: java.sql.SQLException: Connection has already been closed.
at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:117)
at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
大量的数据库连接关闭
2015-05-06 08:24:15,073 [catalina-exec-30][org.hibernate.jdbc.abstractbatcher] [WARN][280] - exception clearing maxRows/queryTimeout
com.microsoft.sqlserver.jdbc.SQLServerException: The connection is closed.
at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:190)
at com.microsoft.sqlserver.jdbc.SQLServerConnection.checkClosed(SQLServerConnection.java:388)
at com.microsoft.sqlserver.jdbc.SQLServerStatement.checkClosed(SQLServerStatement.java:978)
at com.microsoft.sqlserver.jdbc.SQLServerStatement.getMaxRows(SQLServerStatement.java:1011)
大量的 Socket 连接关闭
org.springframework.dao.DataAccessResourceFailureException: could not insert: [com.cmbchina.ccd.pluto.lotteryengine.models.LeLog]; nested exception is org.hibernate.exception.JDBCC
onnectionException: could not insert: [com.cmbchina.ccd.pluto.lotteryengine.models.LeLog]
at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:625)
at org.springframework.orm.hibernate3.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:412)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:411)
Caused by: org.hibernate.exception.JDBCConnectionException: could not insert: [com.cmbchina.ccd.pluto.lotteryengine.models.LeLog]
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:74)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
at org.hibernate.id.insert.AbstractReturningDelegate.performInsert(AbstractReturningDelegate.java:40)
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2163)
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2643)
at org.hibernate.action.EntityIdentityInsertAction.execute(EntityIdentityInsertAction.java:51)
at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279)
Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: Socket closed
at com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:1667)
at com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:1654)
at com.microsoft.sqlserver.jdbc.TDSChannel.read(IOBuffer.java:1789)
当时的数据库配置说明
DB Version :Microsoft SqlServer 2008
Le_Log 日志表创建的索引为:
聚集 IDX_ACTIVITY_ACCOUNTID = activityCode + accountId + logUpdateAt
非聚集 IDX_ACTIVITY_USREID = activityCode + userId + logUpdateAt
日志查询语句及执行计划
SELECT top 6 \* FROM LE_LOG WHERE activityCode=? AND userId=? AND updateAt BETWEEN ? AND ?
INDEX Seek 非聚集索引 IDX_ACTIVITY_USREID 找到对应的 rowId
INDEX Seek 聚集索引 IDX_ACTIVITY_ACCOUNTID 根据 rowId 找到对应行其他列的数据
日志插入
INSERT INTO LE_LOG VALUES();
先拿到聚集索引的排它锁,将要插入的行进行物理排序,然后对非聚集索引进行维护
-- 注意,MYSQL的INSERT在RR隔离级别下还有GAP锁的存在。
原因分析(查询事务隔离级别应该为 READ UNCOMMITTED)
在本文的场景中,问题可能就出在非聚集索引与聚集索引的死锁问题上
步骤
Select 过程
Insert 过程
1
Select 获取到对应用户抽奖记录的行共享 S 锁拿到 rowId
2
Insert 获取聚集索引的排它 X 锁
3
根据 rowId 试图获取聚集索引的共享 S 锁查询其他列的数据,阻塞!
4
Insert 需要同步更新非聚集索引,试图获取排它锁 X,被 S 锁阻塞!
所以死锁发生了。。。
大量的事务回滚应该是为了防止死锁造成数据库宕机设置的锁超时机制造成的,一旦无法插入或者查询日志记录就出现了大量的回滚或者连接强制断开,也就是我们在异常日志中看到的。而事务回滚占用的资源量很大,结果就是系统 CPU 利用率不断升高。
解决方案
SQL 语句添加 WITH (NOLOCK) 允许脏读 HQL 语句 Service 的方法前添加 @Transactional(isolation=ISOLATION.READ_UNCOMMITTED)
将 userId 原本的非聚集索引修改为聚集索引, accountId 原本的聚集索引改为非聚集索引。这样投注记录的 select 查询将只走聚集索引 seek。
将 select * from 修改为 select 明确的列 from, 减少 io 数据量
清理数据库:目前抽奖记录因为市场部的强烈要求必须保留 3 个月,所以数据量无法缩减。下期新游戏上线的时候会将投注记录 UI 的提示字样改为一个月,然后同步修改数据库清理脚本为只保留一个月数据。
在查询投注记录明细的时候排序采用的字段是 log_id desc,不是聚集索引中的 log_update_at,导致执行计划中有很大一部分的排序性能消耗,修改为按照更新时间倒序。当初采用 log_id 排序是因为测试过程中发现抽奖过快会出现相同时间戳记录的出现,当然这种概率极低。考虑性能输出,对于相同时间戳的记录排序混乱可以忍受。
相关推荐
- SQL Server 常用函数 1.获取当前时间--GetDate()2.DatePart() 函数3.字符串截取--substring三个参数,第一个参数需要截取的,第二个参数,截取字符串的起始位置(起始位置是1),第三个参数需要截取字符串的长度。4.日期增减函数-DateAdd三个参数,第一参数合法的日期表达式,第二个参…
- 3DMAX提示和技巧 本主题标识使用 Civil View 的一些重要提示和技巧。常规使用屏幕分辨率至少为 1280x1024 的 Civil View。低于此分辨率时,一些面板将占用过多屏幕空间。 将视口设置为线框显示以达到最佳性能。 要尽可能简化用户界面,请在单个视口中工作并关闭 3ds Max 命令面…