MySQL 事務RUNNING狀態引發的Transaction timed out: deadline問題
前言:
朋友說簡單的查詢導致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)
----------------------------------------------------------------------------------------------------------------
來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/26230597/viewspace-1346680/,如需轉載,請註明出處,否則將追究法律責任。
相關文章
- mysql併發事務的常見問題MySql
- 髒讀!幻讀!不可重複讀!mysql併發事務引發的問題MySql
- Android-問題-obtainBuffer timed out (is the CPU pegged?)AndroidAI
- Spring事務(Transaction)管理高階篇一棧式解決開發中遇到的事務問題Spring
- indexedDB transaction 事務Index
- MySQL事務的隔離級別與併發問題MySql
- 事務狀態持久化持久化
- Check the transaction running in oracleOracle
- 關於 MySQL 的巢狀事務MySql巢狀
- MySQL關於事務常見的問題MySql
- 【問題處理】Oracle process running out of OS kernel I/O resourcesOracle
- DAPPER 事務 TRANSACTIONAPP
- mysql隱式提交事務transaction一點筆記MySql筆記
- 隨筆:MySQL 查詢事務狀態欄位說明MySql
- Feign,HTTP連線超時問題SocketTimeoutException: Read timed outHTTPException
- PostgreSQL的idle in transaction連線狀態SQL
- 3分鐘搞懂MySQL事務隔離級別及SET TRANSACTION影響事務MySql
- WARNING: inbound connection timed out (ORA-3136)連線超時問題
- GoldenGate Pump Porcess: TCP/IP error 110 (Connection timed out)的問題解決GoTCPError
- 開啟mysql審計後引發的問題MySql
- JDBC中事務的問題JDBC
- web service 的事務問題Web
- oracle set transaction read only與dbms_transaction實現事務transaction控制Oracle
- pxc 事務pre-commit狀態阻塞MIT
- mysql 主從同步 Error 'Out of range value for column的問題MySql主從同步Error
- 線上併發事務死鎖問題排查
- Oracle ITL (Interested Transaction List) - 事務槽OracleREST
- 關於事務的英文說明 Transaction OverviewView
- MySQL handler相關狀態引數解釋MySql
- 面試官問:Java 執行緒沒有 Running 狀態,為什麼?面試Java執行緒
- MySQL事務與併發MySql
- 一個延時任務問題引發的思考
- squid!Your cache is running out of fileUI
- 分散式事務 TCC-Transaction 原始碼分析 —— 事務恢復分散式原始碼
- 資料庫事務併發產生的問題以及事務的隔離級別資料庫
- [Clickhouse] Clickhouse 報SQLException : Read timed outSQLException
- sqlnet.log error - Operation timed outSQLError
- 資料庫事務併發問題----各種事務隔離下的情況資料庫