MySQL 事务RUNNING状态引发的Transaction timed out: deadline问题

标签： mysql running 状态 | 发表时间：2014-11-26 08:15 | 作者：mchdba
出处：http://blog.csdn.net

前言：
    朋友说简单的查询导致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`;
+----------+-----------+---------------------+-----------------------+------------------+------------+---------------------+-----------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
| trx_id   | trx_state | trx_started         | trx_requested_lock_id | trx_wait_started | trx_weight | trx_mysql_thread_id | trx_query | trx_operation_state | trx_tables_in_use | trx_tables_locked | trx_lock_structs | trx_lock_memory_bytes | trx_rows_locked | trx_rows_modified | trx_concurrency_tickets | trx_isolation_level | trx_unique_checks | trx_foreign_key_checks | trx_last_foreign_key_error | trx_adaptive_hash_latched | trx_adaptive_hash_timeout | trx_is_read_only | trx_autocommit_non_locking |
+----------+-----------+---------------------+-----------------------+------------------+------------+---------------------+-----------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
| 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`;
+----------+-----------+---------------------+-----------------------+------------------+------------+---------------------+-----------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
| trx_id   | trx_state | trx_started         | trx_requested_lock_id | trx_wait_started | trx_weight | trx_mysql_thread_id | trx_query | trx_operation_state | trx_tables_in_use | trx_tables_locked | trx_lock_structs | trx_lock_memory_bytes | trx_rows_locked | trx_rows_modified | trx_concurrency_tickets | trx_isolation_level | trx_unique_checks | trx_foreign_key_checks | trx_last_foreign_key_error | trx_adaptive_hash_latched | trx_adaptive_hash_timeout | trx_is_read_only | trx_autocommit_non_locking |
+----------+-----------+---------------------+-----------------------+------------------+------------+---------------------+-----------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
| 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='[email protected]'
###   @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)
----------------------------------------------------------------------------------------------------------------

作者：mchdba 发表于2014-11-26 0:15:26 原文链接
阅读：250 评论：0 查看评论

相关 [mysql running 状态] 推荐：

MySQL 事务RUNNING状态引发的Transaction timed out: deadline问题

- - CSDN博客推荐文章
    朋友说简单的查询导致Transaction timed out: deadline问题，怀疑是数据库表锁了，. 1，应用故障描述Deadline问题： . 2，检查Innodb存储引擎状态以及表锁状态.         SHOW ENINGE INNODB STATUS；没有死锁信息以及其它异常信息；去查询系统表INNODB_LOCKS、INNODB_LOCK_WAITS表都为NULL，只有INNODB_TRX表有记录，并且处于长时间RUNNING状态，判断是因为事务没有提交或者回滚的缘故.

[MySQL] 生产环境MySQL数据库事务一直在RUNNING

- - CSDN博客数据库推荐文章
运营人员反映，有一单子提交卡住了，页面一直没有返回. 1，刚开始怀疑是应用服务器或者db压力过高hang住了，马上去check应用服务器以及db的负载，看起来都OK，蛮低的，应该不是DB性能问题. 2，最后去看下是否是表锁住了，查看到有2个事务一直RUNNING，没有结束. 3，通过trx_mysql_thread_id: 1662332的去查询information_schema.processlist找到执行事务的客户端请求的SQL线程.

MySQL执行状态分析

- - CSDN博客推荐文章
当感觉mysql性能出现问题时，通常会先看下当前mysql的执行状态，使用 show processlist 来查看，例如：. 其中state状态列信息非常重要，先看下各列含义，然后看下state常用状态. 一个标识，你要kill一个语句的时候使用，例如 mysql> kill 207;. 显示当前用户，如果不是root，这个命令就只显示你权限范围内的sql语句.

MySQL锁定状态查看命令

- - CSDN博客数据库推荐文章
SHOW PROCESSLIST显示哪些线程正在运行. 您也可以使用mysqladmin processlist语句得到此信息. 如果您有SUPER权限，您可以看到所有线程. 否则，您只能看到您自己的线程（也就是，与您正在使用的MySQL账户相关的线程）. 如果有线程在update或者insert 某个表，此时进程的status为updating 或者 sending data.

Mysql查看连接数、状态

- - CSDN博客数据库推荐文章
如果是root帐号，你能看到所有用户的当前连接,如果是其它普通帐号，只能看到自己占用的连接. show processlist只能列出前100条;如果想全列出请使用show full processlist. show status like ‘%变量%’. Aborted_clients 由于客户没有正确关闭连接已经死掉，已经放弃的连接数量.

Mysql 查看连接数,状态

- - 数据库 - ITeye博客
命令： show processlist;. 如果是root帐号，你能看到所有用户的当前连接. 如果是其它普通帐号，只能看到自己占用的连接. show processlist;只列出前100条，如果想全列出请使用show full processlist;. 命令： show status;. 命令：show status like '%下面变量%';.

Mysql 查看连接数,状态

- - 互联网 - ITeye博客
来源  http://blog.csdn.net/starnight_cbj/article/details/4492555. 命令： show processlist;. 如果是root帐号，你能看到所有用户的当前连接. 如果是其它普通帐号，只能看到自己占用的连接. show processlist;只列出前100条，如果想全列出请使用show full processlist;.

Mysql 大数据操作状态查询

- - SegmentFault 最新的文章
这种时候我们就应该祭出一些方法了，在这里我总结一下我查到的资料. 在mysql中执行这个语句后，就能显示出mysql正在执行和处理哪些语句，以及相应的其他信息. Id: 40 User: root Host: localhost db: dbname Command: Query Time: 2061 State: Sending data Info: insert into table t1(*) select * from t2.

使用HAProxy对MySQL进行负载均衡和状态监控

- Kevin - Michael`s blog
转载请保留原文内容，并声明转载地址：http://www.toplee.com/blog/1284.html. 乐搜（lesoo.com)使用HAProxy已经很久了，但主要用在前端web请求的负载均衡和状态监控上，对于后端的Memcached以及MySQL却一直没有应用，最近对系统架构进行了小规模的整理，把MySQL也收编到了HAProxy下，经过一段时间的使用，体验还是不错的.

配置 CACTI 监控 MySQL 数据库状态

- - CSDN博客数据库推荐文章
   MySQL 自身在性能监测方面很不给力、这是令许多 MySQL DBA 夜夜辗转难眠、.    幸运的是、通过 Cacti 监测（注意是监测而非监控）MySQL 数据库状态.    借助 cacti+rrdtool 强大的绘图功能、加上专用的 mysql 模板、能够灵活快速的创建对多个 MySQL 实例的监测.