MySQL慢查詢日誌相關設定

問題：開啟慢查詢日誌後，超過long_query_time的操作哪些不會記錄到慢日誌檔案中？

mysql> show global variables like '%slow%';

+---------------------------+-----------------------------+

| Variable_name             | Value                       |

+---------------------------+-----------------------------+

| log_slow_admin_statements | OFF                         |

| log_slow_extra            | OFF                         |

| log_slow_slave_statements | OFF                         |

| slow_launch_time          | 2                           |

| slow_query_log            | ON                          |

| slow_query_log_file       | /app/mysql/log/slow3306.log |

+---------------------------+-----------------------------+

6 rows in set (0.01 sec)

mysql> show global variables like 'long_query_time'; 

+-----------------+----------+

| Variable_name   | Value    |

+-----------------+----------+

| long_query_time | 1.000000 |

+-----------------+----------+

1 row in set (0.01 sec)

首先來看幾種最普通的操作

（1）sleep

（2）正常的表查詢

（3）查詢過程中會話中斷

（4）包含排序、分組等操作

mysql> select sleep(1) ;

+----------+

| sleep(1) |

+----------+

|        0 |

+----------+

1 row in set (1.00 sec)

mysql> select count(1) from test.account t1,test.account t2;

+----------------+

| count(1)       |

+----------------+

| 35116409328100 |

+----------------+

1 row in set (1.08 sec)

mysql> select count(1) from test.account t1,test.account t2,test.account t3,information_schema.tables;

^C^C -- query aborted

ERROR 1317 (70100): Query execution was interrupted

mysql> select * from account t1 order by name limit 100000,1;

+---------+-------------+---------+---------------------+---------------------+-------------------+

| id      | name        | partkey | created_at          | updated_at2         | conform_pay_state |

+---------+-------------+---------+---------------------+---------------------+-------------------+

| 1134998 | name1134998 | e1      | 2021-10-15 13:36:08 | 2021-10-15 13:36:08 | 3                 |

+---------+-------------+---------+---------------------+---------------------+-------------------+

1 row in set (23.63 sec)

mysql> select substr(name,4,3),count(1) from account t1 group by substr(name,4,3)  limit 2;

+------------------+----------+

| substr(name,4,3) | count(1) |

+------------------+----------+

| e34              |    74076 |

| e35              |    74076 |

+------------------+----------+

2 rows in set (6.81 sec)

日誌內容：

# Time: 2021-11-25T20:50:24.421438+08:00

# User@Host: root[root] @  [127.0.0.1]  Id: 64077

# Query_time: 1.000365  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 1

SET timestamp=1637844623;

select sleep(1);

# Time: 2021-11-25T20:51:12.203789+08:00

# User@Host: root[root] @  [127.0.0.1]  Id: 64077

# Query_time: 1.078180  Lock_time: 0.000291 Rows_sent: 1  Rows_examined: 0

SET timestamp=1637844671;

select count(1) from test.account t1,test.account t2;

# Time: 2021-11-25T20:51:43.745724+08:00

# User@Host: root[root] @  [127.0.0.1]  Id: 64077

# Query_time: 8.127499  Lock_time: 0.001228 Rows_sent: 0  Rows_examined: 27259

SET timestamp=1637844695;

select count(1) from test.account t1,test.account t2,test.account t3,information_schema.tables;

# Time: 2021-11-25T21:53:56.716651+08:00

# User@Host: root[root] @  [127.0.0.1]  Id: 64141

# Query_time: 23.629454  Lock_time: 0.000146 Rows_sent: 1  Rows_examined: 6025911

SET timestamp=1637848413;

select * from account t1 order by name limit 100000,1;

# Time: 2021-11-25T21:55:09.622017+08:00

# User@Host: root[root] @  [127.0.0.1]  Id: 64141

# Query_time: 6.810800  Lock_time: 0.000199 Rows_sent: 2  Rows_examined: 5925910

SET timestamp=1637848502;

select substr(name,4,3),count(1) from account t1 group by substr(name,4,3)  limit 2;

這些都被正常記錄到慢日誌檔案中。

再看幾種較為複雜的場景：

（5）操作被阻塞

@會話1：

mysql> begin;

Query OK, 0 rows affected (0.00 sec)

mysql>  select * from account where id=1134998 for update;

+---------+------------+---------+---------------------+---------------------+-------------------+

| id      | name       | partkey | created_at          | updated_at2         | conform_pay_state |

+---------+------------+---------+---------------------+---------------------+-------------------+

| 1134998 | namea12345 | e1      | 2021-11-25 21:59:54 | 2021-11-25 21:59:54 | 3                 |

+---------+------------+---------+---------------------+---------------------+-------------------+

1 row in set (0.00 sec)

@會話2：

mysql> update account set name='namea111111' where id=1134998;

由於會話2需要等待會話1釋放鎖，一直處於阻塞狀態，直到會話1 commit

Query OK, 1 row affected (41.99 sec)

Rows matched: 1  Changed: 1  Warnings: 0

雖然耗時41.99秒，但由於不是執行耗時，因此慢日誌未記錄

（6）DDL操作

mysql> alter table account drop column testcol;

Query OK, 0 rows affected (24.63 sec)

Records: 0  Duplicates: 0  Warnings: 0

也不會被記錄到慢日誌中。

##########################################################

根據官方文件，5.7版本中，記錄慢日誌需要順序滿足以下邏輯：

1.語句不能是管理語句（ALTER TABLE, ANALYZE TABLE, CHECK TABLE, CREATE INDEX, DROP INDEX, OPTIMIZE TABLE,REPAIR TABLE），除非開啟了log_slow_admin_statements

2.語句耗時超過long_query_time，或者開啟了log_queries_not_using_indexes引數的情況下查詢未使用索引（小於long_query_time也會被記錄）

3.語句需要至少掃描了min_examined_row_limit行

4.設定了log_throttle_queries_not_using_indexes引數時，語句沒有被壓縮顯示

不會記錄查詢快取處理的語句(僅5.7版本涉及，8.0版本已經沒有快取)

從庫預設不會記錄replicated到的語句；如果開啟log_slow_slave_statements，並且binlog_format是statement 或者binlog_format=MIXED且語句是按statement同步的，則可以被放入慢日誌檔案。

因此 5.7\8.0版本mysql中需要設定如下引數（個人總結），可以記錄阻塞情況以外的大部分可疑慢查詢語句。

slow_query_log=1

long_query_time=5  [根據實際情況調整]

log_slow_admin_statements=1

log_queries_not_using_indexes=1

global min_examined_row_limit=10000

log_throttle_queries_not_using_indexes=10

log_slow_extra=1

釋義：開啟慢查詢日誌，記錄超過5秒的語句，包含管理類語句，包含未使用索引的語句且每分鐘最多記錄10條這樣的語句，超過10條的部分將被壓縮記錄。記錄慢查詢的額外資訊（起止時間、thread_id、是否被kill等）

相關例項1：下面是設定log_throttle_queries_not_using_indexes=2後，一分鐘內6次執行未使用索引的語句，後面四次被壓縮記錄了。

# Time: 2021-11-25T22:38:48.769946+08:00

# User@Host: root[root] @  [127.0.0.1]  Id: 64141

# Query_time: 0.001497  Lock_time: 0.000147 Rows_sent: 1  Rows_examined: 1000

SET timestamp=1637851128;

select * from test1 where name='name34';

# Time: 2021-11-25T22:38:48.777614+08:00

# User@Host: root[root] @  [127.0.0.1]  Id: 64142

# Query_time: 0.001219  Lock_time: 0.000095 Rows_sent: 1  Rows_examined: 1000

SET timestamp=1637851128;

select * from test1 where name='name35';

# Time: 2021-11-25T22:40:02.848238+08:00

# User@Host: [] @  []  Id: 64195

# Query_time: 0.004725  Lock_time: 0.000398 Rows_sent: 1  Rows_examined: 1

SET timestamp=1637851202;

throttle:          4 'index not used' warning(s) suppressed.;   《《《《《有額外的四條語句未使用索引

相關例項2：開啟log_slow_extra前後，同一sql的日誌差異:

# Time: 2021-11-25T22:56:07.740623+08:00

# User@Host: root[root] @  [127.0.0.1]  Id: 64141

# Query_time: 7.300167  Lock_time: 0.000403 Rows_sent: 0  Rows_examined: 29583

SET timestamp=1637852160;

select count(1) from test.account t1,test.account t2,test.account t3,information_schema.tables;

# Time: 2021-11-25T22:58:36.141562+08:00

# User@Host: root[root] @  [127.0.0.1]  Id: 64141

# Query_time: 11.336944  Lock_time: 0.000852 Rows_sent: 0  Rows_examined: 37156 Thread_id: 64141 Errno: 1160 Killed: 1053 Bytes_received: 0 Bytes_sent: 0 Read_first: 3 Read_last: 0 Read_key: 5132 Read_next: 20528 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 4654 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2021-11-25T22:58:24.804618+08:00 End: 2021-11-25T22:58:36.141562+08:00

SET timestamp=1637852304;

select count(1) from test.account t1,test.account t2,test.account t3,information_schema.tables;