一傻粘、問(wèn)題描述
我們經(jīng)常會(huì)碰到這樣的情況每窖，某個(gè)事務(wù)執(zhí)行完了未提交，后續(xù)再來(lái)一個(gè)DDL和DML操作弦悉，導(dǎo)致后面的session要么處于waiting for metadata lock窒典，要么是鎖等待超時(shí)。這時(shí)我們往往只能找到這個(gè)未提交的事務(wù)的事務(wù)id和session id稽莉，但是一般都處于sleep狀態(tài)瀑志，不好分析事務(wù)內(nèi)容到底是什么，所以通常都是粗魯?shù)豮ill這個(gè)session后解決問(wèn)題污秆，但是應(yīng)用層的研發(fā)人員往往找不到到底是哪個(gè)事務(wù)引起的劈猪，后面再出現(xiàn)問(wèn)題時(shí)還要重復(fù)kill。那這個(gè)情況下良拼，怎么辦呢战得？
下面我先模擬兩種情況
這里我特意在開啟session后執(zhí)行一條update，又執(zhí)行了一條insert語(yǔ)句庸推。
這時(shí)session2一直卡住
我們?cè)匍_一個(gè)窗口session3常侦。
mysql> show processlist;
+----+------+-----------+------+---------+------+---------------------------------+----------------------------------------------------+
| Id | User | Host? ? ? | db? | Command | Time | State? ? ? ? ? ? ? ? ? ? ? ? ? | Info? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? |
+----+------+-----------+------+---------+------+---------------------------------+----------------------------------------------------+
|? 4 | root | localhost | test | Sleep? |? 841 |? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? | NULL? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? |
|? 5 | root | localhost | test | Query? |? 709 | Waiting for table metadata lock | alter table test_lock add column name2 varchar(50) |
|? 6 | root | localhost | NULL | Query? |? ? 0 | starting? ? ? ? ? ? ? ? ? ? ? ? | show processlist? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? |
+----+------+-----------+------+---------+------+---------------------------------+----------------------------------------------------+
可看到ddl操作也被卡住了，之前的事務(wù)1也處于sleep狀態(tài)贬媒，無(wú)法得知它到底執(zhí)行了什么聋亡。
這時(shí)我們查詢innodb_trx表可看到事務(wù)1也看不到sql信息。
二际乘、解決方案
方案一
我想到的第一種方法是利用performance_schema中的相關(guān)信息查詢
mysql> show variables like 'performance_schema';
+--------------------+-------+
|Variable_name??????| Value |
+--------------------+-------+
|performance_schema??| ON????|
+--------------------+-------+
1 row in set(0.00 sec)
通過(guò)查看events_statements_current表可看到每一個(gè)session正在執(zhí)行的sql坡倔，哪怕它依舊執(zhí)行完成了，只是沒(méi)有提交。這里可看到事務(wù)1最后執(zhí)行的正是insert into test_lock values(4,'andy');
mysql> select * from performance_schema.events_statements_current\G
不過(guò)方案1有個(gè)缺陷罪塔，一個(gè)事務(wù)可能有一組sql組成投蝉，這個(gè)方法只能看到這個(gè)事務(wù)最后執(zhí)行的是什么SQL，無(wú)法看到全部征堪。也就是說(shuō)墓拜，關(guān)于information_schema.processlist和events_statements_current如何一一對(duì)應(yīng)起來(lái)，可以通過(guò)performance_schema.threads表來(lái)關(guān)聯(lián)请契，語(yǔ)句如下：
mysql> select * from performance_schema.events_statements_current where THREAD_ID in (select THREAD_ID from performance_schema.threads where PROCESSLIST_ID=4)\G
如果你是MySQL 5.7版本，可以通過(guò)查看sys.session視圖和sys.processlist視圖得到最后一次執(zhí)行的SQL語(yǔ)句夏醉。
方案二
然后我想到了是不是可以用general_log的方式爽锥，一般情況下general_log不大可能打開，所以我們先打開general_log等著問(wèn)題復(fù)現(xiàn)的方式來(lái)定位畔柔，經(jīng)測(cè)試氯夷，即使事務(wù)沒(méi)有提交，一樣會(huì)寫到general_log靶擦。
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日志后腮考，只要知道了未提交事務(wù)的進(jìn)程號(hào)就可以完美找到對(duì)應(yīng)的SQL語(yǔ)句了。
$ cat /data/mysql/3306/data/qs-ops-db-01.log | grep 4
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 4 Query begin
2017-03-29T07:22:11.090712Z 4 Query update test_lock set id=123 where id=1
2017-03-29T07:22:18.347311Z 4 Query insert into test_lock values(4,'andy')
這樣只要后續(xù)能否復(fù)現(xiàn)的話玄捕，就能找到所有的SQL了踩蔚，就是如果此會(huì)話是長(zhǎng)連接，那么必然執(zhí)行的SQL語(yǔ)句較多枚粘，這時(shí)候就需要慢慢排查了馅闽。
方案三
假如后面應(yīng)用層最終commit了，那么會(huì)在binlog里記錄馍迄，可以根據(jù)當(dāng)時(shí)的session id去binlog里面查看完整事務(wù)福也。
