前言：
朋友说简单的查询导致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='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)
----------------------------------------------------------------------------------------------------------------