目录
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 |
请参见文件: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
大量的数据库事务回滚
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锁的存在。
在本文的场景中,问题可能就出在非聚集索引与聚集索引的死锁问题上
步骤 | Select 过程 | Insert 过程 |
---|---|---|
1 | Select 获取到对应用户抽奖记录的行共享 S 锁拿到 rowId | |
2 | Insert 获取聚集索引的排它 X 锁 | |
3 | 根据 rowId 试图获取聚集索引的共享 S 锁查询其他列的数据,阻塞! | |
4 | Insert 需要同步更新非聚集索引,试图获取排它锁 X,被 S 锁阻塞! |
所以死锁发生了。。。
大量的事务回滚应该是为了防止死锁造成数据库宕机设置的锁超时机制造成的,一旦无法插入或者查询日志记录就出现了大量的回滚或者连接强制断开,也就是我们在异常日志中看到的。而事务回滚占用的资源量很大,结果就是系统 CPU 利用率不断升高。
本文分享自 曲水流觞TechRill 微信公众号,前往查看
如有侵权,请联系 cloudcommunity@tencent.com 删除。
本文参与 腾讯云自媒体同步曝光计划 ,欢迎热爱写作的你一起参与!