mysql deadline_MySQL事务RUNNING状态引发的Transactiontimedout:deadline问题_MySQL

最新推荐文章于 2023-02-03 16:18:19 发布

六号轨迹

最新推荐文章于 2023-02-03 16:18:19 发布

阅读量1.5k

点赞数

文章标签： mysql deadline

本文链接：https://blog.csdn.net/weixin_28737399/article/details/113908456

版权

前言：朋友说简单的查询导致Transaction timed out: deadline问题，怀疑是数据库表锁了，

1，应用故障描述Deadline问题：--- The error occurred in META-INF/ibatis/ITEM_sqlmap.xml.

--- The error occurred while executing query.

--- Check the SELECT I.ID, I.SHOP_ID, I.ITEM_GROUP_ID, I.ITEM_GROUP_NAME, I.ITEM_NAME, I.LIST_PRICE, I.PL_PRICE, I.PROTECTION_PRICE, I.MALL, I.STAT, I.LOGISTICS, I.TYPE, I.ITEM_CATEGORY_ID, I.BRAND_ID, I.BRAND, I.FAVOUR_NUM, I.IS_SUBSCRIBE, I.VOLUME, I.WEIGHT, I.INVENTORY, I.RELEASE_DATE, I.OFF_REASON, I.IS_DEL, I.CREATED_DATE, I.UPDATED_DATE, I.SIMPLE_DESCRIPTION, I.VIRTUAL_BEGIN_DATE, I.VIRTUAL_END_DATE, I.SEQ_NUM, IPC.PICTURE_PATH FROM ITEM AS I INNER JOIN ITEM_PICTURE AS IPC ON I.ITEM_GROUP_ID = IPC.ITEM_GROUP_ID where I.ID = ? AND IPC.TYPE='1' AND IPC.IS_DEL='0' .

--- Check the SQL Statement (preparation failed).

--- Cause: org.springframework.transaction.TransactionTimedOutException: Transaction timed out: deadline was Tue Nov 25 13:33:07 CST 2014

at com.ibatis.sqlmap.engine.mapping.statement.MappedStatement.executeQueryWithCallback(MappedStatement.java:204)

at com.ibatis.sqlmap.engine.mapping.statement.MappedStatement.executeQueryForObject(MappedStatement.java:120)

at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForObject(SqlMapExecutorDelegate.java:518)

at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForObject(SqlMapExecutorDelegate.java:493)

at com.ibatis.sqlmap.engine.impl.SqlMapSessionImpl.queryForObject(SqlMapSessionImpl.java:106)

at org.springframework.orm.ibatis.SqlMapClientTemplate$1.doInSqlMapClient(SqlMapClientTemplate.java:273)

at org.springframework.orm.ibatis.SqlMapClientTemplate.execute(SqlMapClientTemplate.java:203)

... 41 more

Caused by: org.springframework.transaction.TransactionTimedOutException: Transaction timed out: deadline was Tue Nov 25 13:33:07 CST 2014

at org.springframework.transaction.support.ResourceHolderSupport.checkTransactionTimeout(ResourceHolderSupport.java:141)

at org.springframework.transaction.support.ResourceHolderSupport.getTimeToLiveInMillis(ResourceHolderSupport.java:130)

at org.springframework.transaction.support.ResourceHolderSupport.getTimeToLiveInSeconds(ResourceHolderSupport.java:114)

at org.springframework.jdbc.datasource.DataSourceUtils.applyTimeout(DataSourceUtils.java:275)

at org.springframework.jdbc.datasource.DataSourceUtils.applyTransactionTimeout(DataSourceUtils.java:257)

at org.springframework.jdbc.datasource.TransactionAwareDataSourceProxy$TransactionAwareInvocationHandler.invoke(TransactionAwareDataSourceProxy.java:244)

at com.sun.proxy.$Proxy324.prepareStatement(Unknown Source)

at com.ibatis.sqlmap.engine.execution.SqlExecutor.prepareStatement(SqlExecutor.java:497)

at com.ibatis.sqlmap.engine.execution.SqlExecutor.executeQuery(SqlExecutor.java:175)

at com.ibatis.sqlmap.engine.mapping.statement.MappedStatement.sqlExecuteQuery(MappedStatement.java:221)

at com.ibatis.sqlmap.engine.mapping.statement.MappedStatement.executeQueryWithCallback(MappedStatement.java:189)

... 47 more

2，检查Innodb存储引擎状态以及表锁状态

SHOW ENINGE INNODB STATUS；没有死锁信息以及其它异常信息；去查询系统表INNODB_LOCKS、INNODB_LOCK_WAITS表都为NULL，只有INNODB_TRX表有记录，并且处于长时间RUNNING状态，判断是因为事务没有提交或者回滚的缘故。mysql> SELECT * FROM `INNODB_TRX`;

+----------+-----------+---------------------+-----------------------+------------------+------------+---------------------+-----------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+

| 19183390 | RUNNING | 2014-11-25 15:39:30 | NULL | NULL | 9 | 940341 | NULL | NULL | 0 | 0 | 5 | 1248 | 3 | 4 | 0 | READ COMMITTED | 1 | 1 | NULL | 0 | 9762 | 0 | 0 |

| 19183153 | RUNNING | 2014-11-25 15:36:41 | NULL | NULL | 0 | 940206 | NULL | NULL | 0 | 0 | 0 | 376 | 0 | 0 | 0 | READ COMMITTED | 1 | 1 | NULL | 0 | 9411 | 0 | 0 |

| 19183139 | RUNNING | 2014-11-25 15:36:28 | NULL | NULL | 0 | 940238 | NULL | NULL | 0 | 0 | 0 | 376 | 0 | 0 | 0 | READ COMMITTED | 1 | 1 | NULL | 0 | 9937 | 0 | 0 |

3 rows in set (0.00 sec)

mysql> SELECT * FROM `INNODB_LOCKS`;

Empty set (0.00 sec)

mysql> SELECT * FROM `INNODB_LOCK_WAITS`;

Empty set (0.00 sec)

mysql>

仔细check从中可以看出，没有表锁，没有行锁，没有锁等待，只有事务RUNNING没有提交或者回滚。临时解决办法，kill掉这些事务所在的线程。

3，问题重现，查看事务表记录mysql> SELECT * FROM `INNODB_TRX`;

| 19196180 | RUNNING | 2014-11-25 17:41:10 | NULL | NULL | 12 | 942663 | NULL | NULL | 0 | 0 | 4 | 1248 | 2 | 8 | 0 | READ COMMITTED | 1 | 1 | NULL | 0 | 9810 | 0 | 0 |

1 rows in set (0.00 sec)

mysql>

4，去Slow log和binlog里面分析去slow log里面看942663线程ID的slow记录，没有找到，去看binlog里面942663线程ID的DML记录，有如下2条记录：#141125 17:41:10 server id 230 end_log_pos 118147 CRC32 0x6f2402a1 Query thread_id=942663 exec_time=0 error_code=0

SET TIMESTAMP=1416908470/*!*/;

BEGIN

/*!*/;

# at 118147

#141125 17:41:10 server id 230 end_log_pos 118231 CRC32 0x0219bed2 Table_map: `business_db`.`SHOP_CASH_COUPON_USER_REF` mapped to number 178

# at 118231

#141125 17:41:10 server id 230 end_log_pos 118298 CRC32 0xc6665994 Write_rows: table id 178 flags: STMT_END_F

### INSERT INTO `business_db`.`SHOP_CASH_COUPON_USER_REF`

### SET

### @1=4859

### @2=284

### @3=2425

### @4='0'

### @5='2014-11-25 17:41:10'

### @6=NULL

# at 118298

#141125 17:41:10 server id 230 end_log_pos 118411 CRC32 0x93f6d105 Table_map: `business_db`.`CASH_TICKET` mapped to number 727

# at 118411

#141125 17:41:10 server id 230 end_log_pos 118703 CRC32 0xe4b314ad Update_rows: table id 727 flags: STMT_END_F

### UPDATE `business_db`.`CASH_TICKET`

### WHERE

### @1=19956

### @2=1416886592

### @3=NULL

### @4=NULL

### @5=1

### @6='2014-12-31 00:00:00'

### @7='2014-11-25 00:00:00'

### @8=NULL

### @9=NULL

### @10=NULL

### @11=NULL

### @12=NULL

### @13=NULL

### @14=NULL

### @15=NULL

### @16='5c2483b3033b30c6b948d6a971c87f1d'

### @17='CASH-TICKET-1'

### @18='0'

### @19=000000050.000000000

### @20=NULL

### @21=284

### @22='0'

### SET

### @1=19956

### @2=1416908470

### @3='PL.1qaz2wsx'

### @4=NULL

### @5=1

### @6='2014-12-31 00:00:00'

### @7='2014-11-25 00:00:00'

### @8=NULL

### @9=2425

### @10='PL.1qaz2wsx'

### @11='1qaz2wsx@163.com'

### @12='4859'

### @13=NULL

### @14=NULL

### @15=NULL

### @16='5c2483b3033b30c6b948d6a971c87f1d'

### @17='CASH-TICKET-1'

### @18='0'

### @19=000000050.000000000

### @20=1416908470

### @21=284

### @22='0'

# at 118703

#141125 17:41:10 server id 230 end_log_pos 118734 CRC32 0x6949012e Xid = 16199116

COMMIT/*!*/;

看到这个执行成功的DML操作和一直RUNNING的事务时间上比较吻合，所以通过这binlog的INSERT语句和UPDATE语句，找到应用的一个业务模块的方法，发现其异常处理模块没有及时COMMIT和ROLLBACK的。

添加上ROLLBACK处理后，再测试N次，没有出现过报错信息，而执行SELECT * FROM `INNODB_TRX`;也没有记录，这表示事务都及时COMMIT或者ROLLBACK了。

5，期间遇到的额外问题Cause: java.sql.SQLException: Cannot execute statement: impossible to write to binary log since BINLOG_FORMAT = STATEMENT and at least one table uses a storage engine limited to row-based logging. InnoDB is limited to row-logging when transaction isolation level is READ COMMITTED or READ UNCOMMITTED.; nested exception is com.ibatis.common.jdbc.exception.NestedSQLException:

--- The error occurred while applying a parameter map.

--- Check the ITEM.updateByInventory-InlineParameterMap.

--- Check the statement (update failed).

--- Cause: java.sql.SQLException: Cannot execute statement: impossible to write to binary log since BINLOG_FORMAT = STATEMENT and at least one table uses a storage engine limited to row-based logging. InnoDB is limited to row-logging when transaction isolation level is READ COMMITTED or READ UNCOMMITTED.

处理方法：将BINLOG_FORMAT设置成MIXED即可，SET GLOBAL BINLOG_FORMAT = MIXED;

6，总结这个问题看似解决了，但是可能还有更多的细节没有梳理，为什么事务开启后没有ROLLBACK或者COMMIT，后续执行SELECT就会报错呢？自己想来是DML形成排它锁X，而查询是有共享锁S，X和S是互斥的(关于Innodb锁请参考：http://blog.itpub.net/26230597/viewspace-1315111/)，所以就出问题了，至于源码层的底层分析，有待以后继续深究，如果有遇到此类问题的朋友，欢迎share下你的处理思路以及分析过程，谢谢。

----------------------------------------------------------------------------------------------------------------

原博客地址： http://blog.itpub.net/26230597/viewspace-1346680/

原作者：黄杉 (mchdba)

----------------------------------------------------------------------------------------------------------------

本文原创发布php中文网，转载请注明出处，感谢您的尊重！

六号轨迹

关注

0
点赞
踩
0

收藏

觉得还不错? 一键收藏
0
评论
mysql deadline_MySQL事务RUNNING状态引发的Transactiontimedout:deadline问题_MySQL

前言：朋友说简单的查询导致Transaction timed out: deadline问题，怀疑是数据库表锁了，1，应用故障描述Deadline问题：--- The error occurred in META-INF/ibatis/ITEM_sqlmap.xml.--- The error occurred while executing query.--- Check the SE...
复制链接

扫一扫