通过查询日志定位持有锁的SQL语句

Mysql 版本：
mysql> select version();
+------------+
| version()  |
+------------+
| 5.6.27-log |
+------------+
1 row in set (0.00 sec)



1. 启用查询日志
mysql> SET GLOBAL general_log=1;
Query OK, 0 rows affected (0.02 sec)


mysql> show variables like 'general_log%';
+------------------+--------------------------------------------------+
| Variable_name    | Value                                            |
+------------------+--------------------------------------------------+
| general_log      | ON                                               |
| general_log_file | /app/oracle/oradata2/mysql-5.5.37/data/oradb.log |
+------------------+--------------------------------------------------+
2 rows in set (0.00 sec)


2. 查看MYSQL 线程信息
--MYSQL 线程1
mysql> show full processlist;
+----+------+-----------+------+---------+------+-------+-----------------------+
| Id | User | Host      | db   | Command | Time | State | Info                  |
+----+------+-----------+------+---------+------+-------+-----------------------+
|  1 | root | localhost | NULL | Query   |    0 | init  | show full processlist |
+----+------+-----------+------+---------+------+-------+-----------------------+
1 row in set (0.00 sec)


--MYSQL 线程2
mysql> show full processlist;
+----+------+-----------+------+---------+------+-------+-----------------------+
| Id | User | Host      | db   | Command | Time | State | Info                  |
+----+------+-----------+------+---------+------+-------+-----------------------+
|  1 | root | localhost | NULL | Sleep   |  145 |       | NULL                  |
|  2 | root | localhost | NULL | Query   |    0 | init  | show full processlist |
+----+------+-----------+------+---------+------+-------+-----------------------+
2 rows in set (0.00 sec)


--MYSQL 线程3

mysql> show full processlist;
+----+------+-----------+------+---------+------+-------+-----------------------+
| Id | User | Host      | db   | Command | Time | State | Info                  |
+----+------+-----------+------+---------+------+-------+-----------------------+
|  1 | root | localhost | NULL | Sleep   |  189 |       | NULL                  |
|  2 | root | localhost | NULL | Sleep   |   44 |       | NULL                  |
|  3 | root | localhost | NULL | Query   |    0 | init  | show full processlist |
+----+------+-----------+------+---------+------+-------+-----------------------+
3 rows in set (0.00 sec)


--MSYQL 线程4
mysql> show full processlist;
+----+------+-----------+------+---------+------+-------+-----------------------+
| Id | User | Host      | db   | Command | Time | State | Info                  |
+----+------+-----------+------+---------+------+-------+-----------------------+
|  1 | root | localhost | NULL | Sleep   |  238 |       | NULL                  |
|  2 | root | localhost | NULL | Sleep   |   93 |       | NULL                  |
|  3 | root | localhost | NULL | Sleep   |   49 |       | NULL                  |
|  4 | root | localhost | NULL | Query   |    0 | init  | show full processlist |
+----+------+-----------+------+---------+------+-------+-----------------------+
4 rows in set (0.00 sec)


--MYSQL 查询日志
[root@oradb data]# tail -f oradb.log
/app/oracle/oradata2/mysql-5.6.27/bin/mysqld, Version: 5.6.27-log (MySQL CommUnity Server (GPL)). started with:
tcp port: 3306  Unix Socket: /tmp/mysql.sock
Time                 Id Command    Argument
161116 10:48:57     1 Query     show variables like 'general_log%'
161116 10:50:07     1 Query     show full processlist
161116 10:52:24     2 Connect   root@localhost on
                    2 Query     select @@version_comment limit 1
161116 10:52:32     2 Query     show full processlist
161116 10:53:09     3 Connect   root@localhost on
                    3 Query     select @@version_comment limit 1
161116 10:53:16     3 Query     show full processlist
161116 10:53:57     4 Connect   root@localhost on
                    4 Query     select @@version_comment limit 1
161116 10:54:05     4 Query     show full processlist


ID：表示MYSQL 线程ID


3. 使用查询日志找出持有锁造成阻塞的SQL
--MYSQL 线程1 执行更新，并且不提交事务持续持有锁
use test;
START TRANSACTION;
UPDATE t1 SET NAME='test11' WHERE id<11;

--MYSQL 线程2，被阻塞
use test;
START TRANSACTION;
UPDATE t1 SET NAME='test11' WHERE id<10;

--MYSQL 线程3，被阻塞
use test;
START TRANSACTION;
UPDATE t1 SET NAME='test11' WHERE id<9;



--查看锁阻塞信息
SELECT CONCAT('thread ',b.trx_mysql_thread_id,' from ',p.host) AS who_blocks,
       IF(p.command="Sleep",p.time,0) AS idle_in_trx,
       MAX(TIMESTAMPDIFF(SECOND,r.trx_wait_started,NOW())) AS max_wait_time,
       COUNT(*) AS num_waiters
FROM infORMation_schema.`INNODB_LOCK_WAITS` AS w
INNER JOIN information_schema.`INNODB_TRX` AS b ON b.trx_id=w.`blocking_trx_id`
INNER JOIN information_schema.`INNODB_TRX` AS r ON r.`trx_id`= w.`requesting_trx_id`
LEFT JOIN   information_schema.`PROCESSLIST` AS p ON p.id= b.`trx_mysql_thread_id`
GROUP BY who_blocks ORDER BY num_waiters DESC\G

*************************** 1. row ***************************
   who_blocks: thread 1 from localhost
  idle_in_trx: 7
max_wait_time: 4
  num_waiters: 2
*************************** 2. row ***************************
   who_blocks: thread 2 from localhost
  idle_in_trx: 0
max_wait_time: 2
  num_waiters: 1
2 rows in set (0.11 sec)

我们看到 MSYQL 线程1 阻塞了 2 个 线程。


SELECT r.trx_id AS waiting_trx_id,r.`trx_mysql_thread_id` AS waiting_thread,
       TIMESTAMPDIFF(SECOND,r.trx_wait_started,CURRENT_TIMESTAMP) AS wait_time,
       r.`trx_query` AS waiting_query,l.`lock_table` AS waiting_table_lock,
       b.trx_id AS blocking_trx_id,b.`trx_mysql_thread_id` AS blocking_thread,
       SUBSTRING(p.host,1,INSTR(p.host,':')-1) AS blocking_host,
       SUBSTRING(p.host,INSTR(p.host,':')+1) AS blocking_port,
       IF(p.command="Sleep",p.time,0) AS idle_in_trx,
       b.`trx_query` AS blocking_query
FROM information_schema.`INNODB_LOCK_WAITS` AS w
INNER JOIN information_schema.`INNODB_TRX` AS b  ON b.trx_id=w.blocking_trx_id
INNER JOIN information_schema.`INNODB_TRX` AS r ON  r.trx_id = w.requesting_trx_id
INNER JOIN information_schema.`INNODB_LOCKS` AS l ON w.requested_lock_id=l.lock_id
LEFT JOIN information_schema.`PROCESSLIST` AS p ON p.id=b.trx_mysql_thread_id
ORDER BY wait_time DESC


*************************** 1. row ***************************
    waiting_trx_id: 17159
    waiting_thread: 2
         wait_time: 3
     waiting_query: UPDATE t1 SET NAME='test11' WHERE id<10
waiting_table_lock: `test`.`t1`
   blocking_trx_id: 17158
   blocking_thread: 1
     blocking_host:
     blocking_port: localhost
       idle_in_trx: 456
    blocking_query: NULL
*************************** 2. row ***************************
    waiting_trx_id: 17160
    waiting_thread: 3
         wait_time: 2
     waiting_query: UPDATE t1 SET NAME='test11' WHERE id<9
waiting_table_lock: `test`.`t1`
   blocking_trx_id: 17158
   blocking_thread: 1
     blocking_host:
     blocking_port: localhost
       idle_in_trx: 456
    blocking_query: NULL
*************************** 3. row ***************************
    waiting_trx_id: 17160
    waiting_thread: 3
         wait_time: 2
     waiting_query: UPDATE t1 SET NAME='test11' WHERE id<9
waiting_table_lock: `test`.`t1`
   blocking_trx_id: 17159
   blocking_thread: 2
     blocking_host:
     blocking_port: localhost
       idle_in_trx: 0
    blocking_query: UPDATE t1 SET NAME='test11' WHERE id<10
3 rows in set (0.01 sec)

等待 T1 表上的锁

--查询日志
161116 11:00:30     1 Query     SELECT DATABASE()
                    1 Init DB   test
                    1 Query     show databases
                    1 Query     show tables
                    1 Field List        t1
                    1 Query     START TRANSACTION
161116 11:00:45     2 Query     SELECT DATABASE()
                    2 Init DB   test
                    2 Query     show databases
                    2 Query     show tables
                    2 Field List        t1
                    2 Query     START TRANSACTION
161116 11:00:51     3 Query     SELECT DATABASE()
                    3 Init DB   test
                    3 Query     show databases
                    3 Query     show tables
                    3 Field List        t1
                    3 Query     START TRANSACTION
161116 11:00:54     4 Query     SELECT DATABASE()
                    4 Init DB   test
                    4 Query     show databases
                    4 Query     show tables
                    4 Field List        t1
                    4 Query     START TRANSACTION
161116 11:01:53     1 Query     UPDATE t1 SET NAME='test11' WHERE id<11
161116 11:01:56     2 Query     UPDATE t1 SET NAME='test11' WHERE id<10
161116 11:01:58     3 Query     UPDATE t1 SET NAME='test11' WHERE id<9
161116 11:02:00     4 Query     SELECT CONCAT('thread ',b.trx_mysql_thread_id,' from ',p.host) AS who_blocks,
       IF(p.command="Sleep",p.time,0) AS idle_in_trx,
       MAX(TIMESTAMPDIFF(SECOND,r.trx_wait_started,NOW())) AS max_wait_time,
       COUNT(*) AS num_waiters
FROM information_schema.`INNODB_LOCK_WAITS` AS w
INNER JOIN information_schema.`INNODB_TRX` AS b ON b.trx_id=w.`blocking_trx_id`
INNER JOIN information_schema.`INNODB_TRX` AS r ON r.`trx_id`= w.`requesting_trx_id`
LEFT JOIN   information_schema.`PROCESSLIST` AS p ON p.id= b.`trx_mysql_thread_id`
GROUP BY who_blocks ORDER BY num_waiters DESC


通过查询日志结合上面查到的锁阻塞信息可以判断是 MSYQL 线程1 执行的UPDATE t1 SET NAME='test11' WHERE id<11
语句持有锁没提交事务，阻塞了线程2、3。
从查询日志的时间上可以看出来，线程1的SQL比线程2和3的SQL先执行。