为什么不记录慢查询？

㈠ 背景介绍：
  
  2014/8/18 13点37分收到前端说反馈有玩家掉线情况，检查CPU、慢查询、DB请求量，并未发现异常，DB表现一如往常。

㈡ 定位原因：

INSERT INTO t (col1, col2, col3, col4, col5, col6, col7) VALUES ('3532082239485507011_130_99', '130_99', 130, 99, 3532082239485507011, 2172353000317425008, 29078) 

这个长事务执行 1个多小时没有退出，Kill 掉对应的进程，程序前端恢复正常


㈢ 处理思路：

  ⑴ 查询视图

select trx_id,trx_state,trx_started,trx_requested_lock_id,trx_weight,trx_mysql_thread_id from information_schema.innodb_trx where trx_state='RUNNING';

  ⑵ show engine innodb status\G; 关注Transactions部分提取SQL及事务信息
  

㈣ 我的疑问：


为什么这条执行了1个多小时的SQL没有被记录到慢查询日志中呢？？


㈤ 原来如此：


Query_time - Lock_time > long_query_time  <===记录
Query_time - Lock_time < long_query_time  <===不记录


㈥ 模拟场景：


⑴ Query_time - Lock_time > long_query_time

Session_A：

mysql> begin;
Query OK, 0 rows affected (0.00 sec)

mysql> select emp_no,hire_date from employees where emp_no=10170 for update;
+--------+------------+
| emp_no | hire_date  |
+--------+------------+
|  10170 | 1986-01-02 |
+--------+------------+
1 row in set (0.00 sec)

Session_B:

mysql> select emp_no,hire_date,sleep(3) from employees where emp_no=10170 for update;

过段时间在A做commit，B会执行、并被记录到slow log中：

# Time: 140818 22:37:31
# User@Host: root[root] @ localhost []  Id:     1
# Query_time: 3.049016  Lock_time: 0.018891 Rows_sent: 1  Rows_examined: 1
use employees;
SET timestamp=1408372651;
select emp_no,hire_date,sleep(3) from employees where emp_no=10170 for update;

⑵ Query_time - Lock_time < long_query_time

Session_A：

mysql> begin;
Query OK, 0 rows affected (0.00 sec)

mysql> select emp_no,hire_date from employees where emp_no=10170 for update;
+--------+------------+
| emp_no | hire_date  |
+--------+------------+
|  10170 | 1986-01-02 |
+--------+------------+
1 row in set (0.00 sec)

Session_B:

mysql> select emp_no,hire_date from employees where emp_no=10170 for update;

过段时间在A做commit，B会执行、但不会被记录到slow log中

㈦ 我的收获：

我们日常做性能剖析实际上应该包括2个方面：

1）基于执行时间的分析

2）基于等待时间的分析

By water

Good Luck！