MySQL如何定位未提交事務執行的SQL語句?

1、問題描述

咱們常常會碰到這樣的狀況，某個事務執行完了未提交，後續再來一個DDL和DML操做，致使後面的session要麼處於waiting for metadata lock，要麼是鎖等待超時。這時咱們每每只能找到這個未提交的事務的事務id和session id，可是通常都處於sleep狀態，很差分析事務內容究竟是什麼，因此一般都是粗魯地kill這個session後解決問題，可是應用層的研發人員每每找不到究竟是哪一個事務引發的，後面再出現問題時還要重複kill。那這個狀況下，怎麼辦呢？

下面我先模擬兩種狀況

 

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21

mysql> create table test_lock(id int,name varchar(10)); Query OK, 0 rows affected (0.01 sec)   mysql> insert into test_lock values(1,'jack'); Query OK, 1 rowaffected (0.00 sec)   mysql> insert into test_lock values(2,'Jerry'); Query OK, 1 rowaffected (0.00 sec)   mysql> insert into test_lock values(3,'mark'); Query OK, 1 rowaffected (0.00 sec)   mysql> begin; Query OK, 0 rowsaffected (0.00 sec)   mysql> update test_lock set id=123 where id=1; Query OK, 1 rowaffected (0.00 sec) Rows matched:1  Changed: 1  Warnings: 0   mysql> insert into test_lock values(4,'andy'); Query OK, 1 row affected (0.00 sec)

這裏我特地在開啓事務後執行一條update，又執行了一條insert語句。

 

1 2 3 4 5 6 7 8 9 10 11 12

mysql> show variables like '%innodb_lock_w%'; +--------------------------+-------+ |Variable_name            | Value | +--------------------------+-------+ |innodb_lock_wait_timeout  | 5     | +--------------------------+-------+ 1 row in set(0.00 sec)   mysql> update test_lock set id=1234 where id=1; ERROR 1205(HY000): Lock wait timeout exceeded; try restarting transaction   mysql> alter table test_lock add column name2 varchar(50);

這時session2一直卡住，咱們再開一個窗口session3。

 

1 2 3 4 5 6 7 8 9 10

mysql> show processlist; +------+-------------+-----------+--------+---------+-------+----------------------------------+----------------------------------------------------+ | Id   | User        | Host      | db     | Command | Time  | State                            | Info                                               | +------+-------------+-----------+--------+---------+-------+----------------------------------+----------------------------------------------------+ |    1 | system user |           | NULL   | Connect | 67678 | Waiting for master to send event | NULL                                               | | 2063 | root        | localhost | sbtest | Sleep   |    98 |                                  | NULL                                               | | 1935 | root        | localhost | sbtest | Query   |     8 | Waiting for table metadata lock  | alter table test_lock add column name2 varchar(50) | | 1938 | root        | localhost | sbtest | Query   |     0 | starting                         | show processlist                                   | +------+-------------+-----------+--------+---------+-------+----------------------------------+----------------------------------------------------+ 4 rows in set (0.00 sec)

可看到ddl操做也被卡住了，以前的事務1也處於sleep狀態，沒法得知它到底執行了什麼。

這時咱們查詢innodb_trx表可看到事務1也看不到sql信息。

 

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27

mysql> select * from information_schema.innodb_trx\G *************************** 1. row ***************************                     trx_id: 1854303                  trx_state: RUNNING                trx_started: 2017-03-29 13:28:06      trx_requested_lock_id: NULL           trx_wait_started: NULL                 trx_weight: 3        trx_mysql_thread_id: 1928                  trx_query: NULL        trx_operation_state: NULL          trx_tables_in_use: 0          trx_tables_locked: 1           trx_lock_structs: 2      trx_lock_memory_bytes: 1136            trx_rows_locked: 1          trx_rows_modified: 1    trx_concurrency_tickets: 0        trx_isolation_level: READ COMMITTED          trx_unique_checks: 1     trx_foreign_key_checks: 1 trx_last_foreign_key_error: NULL trx_adaptive_hash_latched: 0 trx_adaptive_hash_timeout: 0           trx_is_read_only: 0 trx_autocommit_non_locking: 0 1 row in set (0.00 sec)

2、解決方案

方案一

我想到的第一種方法是利用performance_schema中的相關信息查詢

 

1 2 3 4 5 6 7

mysql> show variables like 'performance_schema'; +--------------------+-------+ |Variable_name      | Value | +--------------------+-------+ |performance_schema  | ON    | +--------------------+-------+ 1 row in set(0.00 sec)

經過查看events_statements_current表可看到每個session正在執行的sql，哪怕它依舊執行完成了，只是沒有提交。這裏可看到事務1最後執行的正是updatetest_lock set id=123 where id=1;

 

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15

mysql> select * from performance_schema.events_statements_current\G *************************** 1. row ***************************               THREAD_ID: 1953                EVENT_ID: 47            END_EVENT_ID: 47              EVENT_NAME: statement/sql/insert                  SOURCE: socket_connection.cc:95             TIMER_START: 69507697694362000               TIMER_END: 69507697987390000              TIMER_WAIT: 293028000               LOCK_TIME: 102000000                SQL_TEXT: insert into test_lock values(4,'andy')                  DIGEST: b8eea4576e85ce7af54a5a643278b6cb             DIGEST_TEXT: INSERT INTO `test_lock` VALUES (...)          CURRENT_SCHEMA: sbtest

不過方案1有個缺陷，一個事務可能有一組sql組成，這個方法只能看到這個事務最後執行的是什麼SQL，沒法看到所有。也就是說，關於information_schema.processlist和events_statements_current如何一一對應起來，能夠經過performance_schema.threads表來關聯，語句以下：

 

1	mysql> select * from performance_schema.events_statements_current where THREAD_ID in (select THREAD_ID from performance_schema.threads where PROCESSLIST_ID=2063)\G

若是你是MySQL 5.7版本，能夠經過查看sys.session視圖和sys.processlist視圖獲得最後一次執行的SQL語句。

方案二

而後我想到了是否是能夠用general_log的方式，通常狀況下general_log不大可能打開，因此咱們先打開general_log等着問題復現的方式來定位，經測試，即便事務沒有提交，同樣會寫到general_log。

 

1 2 3 4 5 6 7 8 9 10 11

mysql> show variables like '%general%'; +------------------+-------------------------------------------+ | Variable_name    | Value                                     | +------------------+-------------------------------------------+ | general_log      | OFF                                       | | general_log_file | /data/mysql/3306/data/qs-ops-db-01.log | +------------------+-------------------------------------------+ 2 rows in set (0.00 sec)   mysql> set global general_log=1; Query OK, 0 rowsaffected (0.00 sec)

開啓general日誌後，只要知道了未提交事務的進程號就能夠完美找到對應的SQL語句了。

 

1 2 3 4 5 6 7

$ cat /data/mysql/3306/data/qs-ops-db-01.log | grep 2063 mysqld, Version: 5.7.17-log (MySQL Community Server (GPL)). started with: Tcp port: 3306  Unix socket: /data/mysql/3306/mysql.sock Time                 Id Command    Argument 2017-03-29T07:22:00.949233Z 2063 Query begin 2017-03-29T07:22:11.090712Z 2063 Query update test_lock set id=123 where id=1 2017-03-29T07:22:18.347311Z 2063 Query insert into test_lock values(4,'andy')

這樣只要後續可否復現的話，就能找到全部的SQL了，就是若是此會話是長鏈接，那麼必然執行的SQL語句較多，這時候就須要慢慢排查了。

方案三

假如後面應用層最終commit了，那麼會在binlog裏記錄，能夠根據當時的session id去binlog裏面查看完整事務。

想不到還有什麼更好的辦法了，目前只能這樣了。