MSSqlServer Select与Insert高并发下的死锁---曲水流觞

目录

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_countLog 线索整理

大量的数据库事务回滚

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 排序是因为测试过程中发现抽奖过快会出现相同时间戳记录的出现，当然这种概率极低。考虑性能输出，对于相同时间戳的记录排序混乱可以忍受。 ---来自腾讯云社区的---曲水流觞