慢查詢日志概述
所謂慢查詢日志，就是用于記錄MySQL中回應時間超過設定閾值的SQL陳述句，通過打開慢查詢開關，MySQL會將大于閾值的SQL記錄在日志中，以便于分析性能，
慢查詢日志選項默認是關閉的，如果要開啟，則需要手動設定，
慢查詢日志選項不建議一直開啟，因為記錄日志意味著IO操作，本身對性能有一定的影響，因此，建議在生產環境關閉該選項；而在開發環境調優階段可以適當打開該選項，
檢查是否開啟了慢查詢日志：
mysql> show variables like '%slow_query_log%';
+---------------------+-----------------------------------------+
| Variable_name | Value |
+---------------------+-----------------------------------------+
| slow_query_log | OFF |
| slow_query_log_file | /var/lib/mysql/DESKTOP-Q5J25HR-slow.log |
+---------------------+-----------------------------------------+
2 rows in set (0.03 sec)
slow_query_log選項即開啟慢查詢的開關，OFF為關閉，ON為開啟，
slow_query_log_file即慢查詢日志的名稱，
如果要開啟慢查詢日志，則執行如下陳述句：
set global slow_query_log = ON;
/* 或者 */
set global slow_query_log = 1;
以上兩句話是一個意思，執行任意一條都可以，執行完畢，再次查詢，已經打開，
mysql> set global slow_query_log = ON;
Query OK, 0 rows affected (0.05 sec)
mysql> show variables like '%slow_query_log%';
+---------------------+-----------------------------------------+
| Variable_name | Value |
+---------------------+-----------------------------------------+
| slow_query_log | ON |
| slow_query_log_file | /var/lib/mysql/DESKTOP-Q5J25HR-slow.log |
+---------------------+-----------------------------------------+
2 rows in set (0.00 sec)
同樣的，慢查詢日志的檔案名也可以重新指定，只需要設定set global slow_query_log_file = 檔案名即可，
前面說過，慢查詢日志只有當SQL陳述句回應時間超過一定閾值才會記錄在日志中，那么這個閾值是多少，該如何設定呢？
可通過以下命令查看慢查詢日志的閾值：
mysql> show variables like '%long_query_time%';
+-----------------+-----------+
| Variable_name | Value |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)
可以看到，默認的閾值是10秒，該值同樣可以通過設定來修改，如設定為0.1秒：
set global long_query_time = 0.1;
long_query_time設定完成后，需要退出MySQL客戶端，重新登錄后才生效，于是可以看到該值已經變成了0.1：
mysql> show variables like '%long_query_time%';
+-----------------+----------+
| Variable_name | Value |
+-----------------+----------+
| long_query_time | 0.100000 |
+-----------------+----------+
1 row in set (0.01 sec)
慢查詢日志具體案例
接下來通過案例的方式來演示慢查詢日志：
我在當前資料庫里有一張test01表，表結構如下所示：
mysql> desc test01;
+--------+-------------+------+-----+---------+-------+
| Field | Type | Null | Key | Default | Extra |
+--------+-------------+------+-----+---------+-------+
| id | int(4) | YES | MUL | NULL | |
| name | varchar(20) | YES | | NULL | |
| passwd | char(20) | YES | | NULL | |
| inf | char(50) | YES | | NULL | |
+--------+-------------+------+-----+---------+-------+
4 rows in set (0.04 sec)
分別做如下查詢：
select * from test01;
select sleep(1);
select id, sleep(2) from test01;
執行結果如下所示：
mysql> select * from test01;
+------+------+--------+--------+
| id | name | passwd | inf |
+------+------+--------+--------+
| 1 | zz | 123456 | asdfgh |
+------+------+--------+--------+
1 row in set (0.00 sec)
mysql> select sleep(1);
+----------+
| sleep(1) |
+----------+
| 0 |
+----------+
1 row in set (1.00 sec)
mysql> select id, sleep(2) from test01;
+------+----------+
| id | sleep(2) |
+------+----------+
| 1 | 0 |
+------+----------+
1 row in set (2.00 sec)
此時并需要去不關心SQL本身，而是看這三條SQL執行的時間，從上面可以看到，第一條SQL執行幾乎不耗時間，顯示0.00 sec，第二條SQL顯示時間為 1.00 sec，第三條SQL為 2.00 sec，
因為我們設定了閾值為0.1秒，因此后兩條SQL應該都要記錄在慢查詢日志中，接下來驗證是否如此：
通過如下命令，可查看慢查詢SQL的條數：
mysql> show global status like '%slow_queries%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Slow_queries | 2 |
+---------------+-------+
1 row in set (0.02 sec)
顯示記錄為2條，與實際情況一致，
通過show variables like '%slow_query_log%'命令，可以查看到日志的具體路徑，
mysql> show variables like '%slow_query_log%';
+---------------------+-----------------------------------------+
| Variable_name | Value |
+---------------------+-----------------------------------------+
| slow_query_log | ON |
| slow_query_log_file | /var/lib/mysql/DESKTOP-Q5J25HR-slow.log |
+---------------------+-----------------------------------------+
2 rows in set (0.00 sec)
打開/var/lib/mysql/DESKTOP-Q5J25HR-slow.log，可以看到日志當中記錄了時間超過閾值的那兩條SQL陳述句：
/usr/sbin/mysqld, Version: 5.7.29-0ubuntu0.18.04.1 ((Ubuntu)). started with:
Tcp port: 3306 Unix socket: /var/run/mysqld/mysqld.sock
Time Id Command Argument
/usr/sbin/mysqld, Version: 5.7.29-0ubuntu0.18.04.1 ((Ubuntu)). started with:
Tcp port: 3306 Unix socket: /var/run/mysqld/mysqld.sock
Time Id Command Argument
# Time: 2020-03-31T13:41:25.726554Z
# User@Host: root[root] @ localhost [] Id: 6
# Query_time: 1.000644 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
use testDB;
SET timestamp=1585662085;
select sleep(1);
# Time: 2020-03-31T13:41:34.246770Z
# User@Host: root[root] @ localhost [] Id: 6
# Query_time: 2.000536 Lock_time: 0.000057 Rows_sent: 1 Rows_examined: 1
SET timestamp=1585662094;
select id, sleep(2) from test01;
mysqldumpslow工具
以上介紹的方法雖然可以查看出所有慢SQL陳述句，但顯然都記錄在一個日志檔案里，會顯得很亂，而且一旦SQL比較多，定位起來還是比較麻煩的，
好在MySQL本身提供了一個專門用來查看慢查詢日志的工具，即mysqldumpslow，
可通過MySQLdumpslow -help查看具體使用方法：
chenyc@DESKTOP-Q5J25HR:~$ mysqldumpslow -help
Usage: mysqldumpslow [ OPTS... ] [ LOGS... ]
Parse and summarize the MySQL slow query log. Options are
--verbose verbose
--debug debug
--help write this text to standard output
-v verbose
-d debug
-s ORDER what to sort by (al, at, ar, c, l, r, t), 'at' is default
al: average lock time
ar: average rows sent
at: average query time
c: count
l: lock time
r: rows sent
t: query time
-r reverse the sort order (largest last instead of first)
-t NUM just show the top n queries
-a don't abstract all numbers to N and strings to 'S'
-n NUM abstract numbers with at least n digits within names
-g PATTERN grep: only consider stmts that include this string
-h HOSTNAME hostname of db server for *-slow.log filename (can be wildcard),
default is '*', i.e. match all
-i NAME name of server instance (if using mysql.server startup script)
-l don't subtract lock time from total time
從以上檔案中，可以知道，該工具用法如下：
mysqldumpslow [選項] [日志名]
常用選項說明：
- -s 即order排序,后面可以有以下選項：
- al 平均鎖定時間
- ar 平均回傳記錄時間
- at 平均查詢時間
- c 計數
- l 鎖定時間
- r 逆序排序
- t 查詢時間
- -t，相當于top n，即回傳前面n條陳述句
- -g， 匹配正則運算式，大小寫不敏感
如：
sudo mysqldumpslow -s r -t 3 -g 'select' /var/lib/mysql/DESKTOP-Q5J25HR-slow.log
以上命令表示：回傳按逆序排序的其中三條陳述句，且陳述句中包含select的SQL陳述句，
結果如下所示：
chenyc@DESKTOP-Q5J25HR:~$ sudo mysqldumpslow -s r -t 3 -g 'select' /var/lib/mysql/DESKTOP-Q5J25HR-slow.log
Reading mysql slow query log from /var/lib/mysql/DESKTOP-Q5J25HR-slow.log
Count: 1 Time=2.00s (2s) Lock=0.00s (0s) Rows=1.0 (1), root[root]@localhost
select id, sleep(N) from test01
Count: 1 Time=1.00s (1s) Lock=0.00s (0s) Rows=1.0 (1), root[root]@localhost
select sleep(N)
Died at /usr/bin/mysqldumpslow line 167, <> chunk 2.
Profiles工具
profiles最大的作用是用來分析海量資料，該命令會記錄所有執行過的SQL陳述句，
這個選項默認也是關閉的，需要手動打開，
查詢profiles選項命令：
mysql> show variables like '%profiling%';
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| have_profiling | YES |
| profiling | OFF |
| profiling_history_size | 15 |
+------------------------+-------+
3 rows in set (0.01 sec)
打開命令：
mysql> set profiling = ON;
Query OK, 0 rows affected, 1 warning (0.00 sec)
再次查看，可以換一種方式查看：
mysql> select @@profiling;
+-------------+
| @@profiling |
+-------------+
| 1 |
+-------------+
1 row in set, 1 warning (0.00 sec)
以上選項，1代表打開，0代表關閉，
為了更為直觀的查看profile，我們再執行兩條SQL：
mysql> select sleep(3);
+----------+
| sleep(3) |
+----------+
| 0 |
+----------+
1 row in set (3.00 sec)
mysql> select * from test01;
+------+------+--------+--------+
| id | name | passwd | inf |
+------+------+--------+--------+
| 1 | zz | 123456 | asdfgh |
+------+------+--------+--------+
1 row in set (0.00 sec)
好了，準備作業就到這里，現在來查看profile：
mysql> show profiles;
+----------+------------+-----------------------------------+
| Query_ID | Duration | Query |
+----------+------------+-----------------------------------+
| 1 | 0.00214400 | show variables like '%profiling%' |
| 2 | 0.00017400 | select @@profiling |
| 3 | 3.00062925 | select sleep(3) |
| 4 | 0.00023450 | select * from test01 |
+----------+------------+-----------------------------------+
4 rows in set, 1 warning (0.00 sec)
如上所示，它會記錄所有的陳述句，其中第二列Duration代表的是執行時間，
以上雖然可以看到每條SQL的執行時間，但我們無法精確知道有多少時間花費在IO上，多少時間花費在CPU上，因此，還可使用以下陳述句查看更為精確的內容：
show profile all for query $(Query_ID);
上面的Query_ID即show profiles結果中第一列的id編號，如：
mysql> show profile all for query 4;
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file
| Source_line |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
| starting | 0.000045 | 0.000000 | 0.000000 | 0 | 0 | 0 |
0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL
| NULL |
| checking permissions | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | 0 |
0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_authorization.cc | 809 |
| Opening tables | 0.000020 | 0.000000 | 0.000000 | 0 | 0 | 0 |
0 | 0 | 0 | 0 | 0 | 0 | open_tables | sql_base.cc
| 5781 |
| init | 0.000017 | 0.000000 | 0.000000 | 0 | 0 | 0 |
0 | 0 | 0 | 0 | 0 | 0 | handle_query | sql_select.cc
| 128 |
| System lock | 0.000016 | 0.000000 | 0.000000 | 0 | 0 | 0 |
0 | 0 | 0 | 0 | 2 | 0 | mysql_lock_tables | lock.cc
| 330 |
| optimizing | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 |
0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc
| 158 |
| statistics | 0.000014 | 0.000000 | 0.000000 | 0 | 0 | 0 |
0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc
| 374 |
| preparing | 0.000010 | 0.000000 | 0.000000 | 0 | 0 | 0 |
0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc
| 482 |
| executing | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 |
0 | 0 | 0 | 0 | 0 | 0 | exec | sql_executor.cc
| 126 |
| Sending data | 0.000051 | 0.000000 | 0.000000 | 0 | 0 | 0 |
0 | 0 | 0 | 0 | 8 | 0 | exec | sql_executor.cc
| 202 |
| end | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 |
0 | 0 | 0 | 0 | 0 | 0 | handle_query | sql_select.cc
| 206 |
| query end | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 |
0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc
| 4956 |
| closing tables | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 |
0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc
| 5009 |
| freeing items | 0.000013 | 0.000000 | 0.000000 | 0 | 0 | 0 |
0 | 0 | 0 | 0 | 0 | 0 | mysql_parse | sql_parse.cc
| 5622 |
| cleaning up | 0.000013 | 0.000000 | 0.000000 | 0 | 0 | 0 |
0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc
| 1931 |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+-------------
--+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------
----+-------------+
15 rows in set, 1 warning (0.00 sec)
上面的結果由于選項太多，看起來還是有些亂，其實很多東西我們并不關注，而主要只關注CPU和IO情況，因此，可以進一步簡化如下：
mysql> show profile cpu, block io for query 4;
+----------------------+----------+----------+------------+--------------+---------------+
| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting | 0.000045 | 0.000000 | 0.000000 | 0 | 0 |
| checking permissions | 0.000008 | 0.000000 | 0.000000 | 0 | 0 |
| Opening tables | 0.000020 | 0.000000 | 0.000000 | 0 | 0 |
| init | 0.000017 | 0.000000 | 0.000000 | 0 | 0 |
| System lock | 0.000016 | 0.000000 | 0.000000 | 0 | 0 |
| optimizing | 0.000005 | 0.000000 | 0.000000 | 0 | 0 |
| statistics | 0.000014 | 0.000000 | 0.000000 | 0 | 0 |
| preparing | 0.000010 | 0.000000 | 0.000000 | 0 | 0 |
| executing | 0.000004 | 0.000000 | 0.000000 | 0 | 0 |
| Sending data | 0.000051 | 0.000000 | 0.000000 | 0 | 0 |
| end | 0.000005 | 0.000000 | 0.000000 | 0 | 0 |
| query end | 0.000007 | 0.000000 | 0.000000 | 0 | 0 |
| closing tables | 0.000007 | 0.000000 | 0.000000 | 0 | 0 |
| freeing items | 0.000013 | 0.000000 | 0.000000 | 0 | 0 |
| cleaning up | 0.000013 | 0.000000 | 0.000000 | 0 | 0 |
+----------------------+----------+----------+------------+--------------+---------------+
15 rows in set, 1 warning (0.00 sec)
全域查詢日志
同profiles一樣，打開全域查詢日志選項以后，它會記錄下所有SQL陳述句，但是由于該操作比較耗費性能，因此，只建議在開發環境臨時打開該選項，
查看全域查詢日志命令：
mysql> show variables like '%general_log%';
+------------------+------------------------------------+
| Variable_name | Value |
+------------------+------------------------------------+
| general_log | OFF |
| general_log_file | /var/lib/mysql/DESKTOP-Q5J25HR.log |
+------------------+------------------------------------+
2 rows in set (0.01 sec)
打開全域查詢日志選項：
set global general_log = on;
再次查詢：
mysql> show variables like '%general_log%';
+------------------+------------------------------------+
| Variable_name | Value |
+------------------+------------------------------------+
| general_log | ON |
| general_log_file | /var/lib/mysql/DESKTOP-Q5J25HR.log |
+------------------+------------------------------------+
2 rows in set (0.00 sec)
設定完以上之后，還需要做如下設定：
set global log_output = 'table';
同樣的，準備以下SQL：
select * from test01;
select id, name from test01 where id = 1;
全域查詢日志記錄在mysql.general_log表中，
mysql> select * from mysql.general_log;
+----------------------------+---------------------------+-----------+-----------+--------------+------------------------------------------+
| event_time | user_host | thread_id | server_id | command_type | argument
|
+----------------------------+---------------------------+-----------+-----------+--------------+------------------------------------------+
| 2020-03-31 22:31:24.750895 | root[root] @ localhost [] | 6 | 0 | Query | select * from test01
|
| 2020-03-31 22:31:26.128924 | root[root] @ localhost [] | 6 | 0 | Query | select id, name from test01 whe
re id = 1 |
| 2020-03-31 22:32:15.736558 | root[root] @ localhost [] | 6 | 0 | Query | select * from mysql.general_log
|
+----------------------------+---------------------------+-----------+-----------+--------------+--------------------------------
----------+
3 rows in set (0.01 sec)
既然有記錄到表中，自然也有記錄到檔案中，只需要做如下設定：
set global general_log_file = '/tmp/mysql_general.log'; --設定檔案路徑
set global log_output = 'file'; --設定記錄到檔案
可通過如下命令查看檔案路徑：
mysql> show variables like '%general_log%';
+------------------+------------------------+
| Variable_name | Value |
+------------------+------------------------+
| general_log | ON |
| general_log_file | /tmp/mysql_general.log |
+------------------+------------------------+
2 rows in set (0.00 sec)
同樣執行以上兩條SQL：
select * from test01;
select id, name from test01 where id = 1;
查看檔案內容，得到如下結果：
chenyc@DESKTOP-Q5J25HR:~$ sudo cat /tmp/mysql_general.log
/usr/sbin/mysqld, Version: 5.7.29-0ubuntu0.18.04.1 ((Ubuntu)). started with:
Tcp port: 3306 Unix socket: /var/run/mysqld/mysqld.sock
Time Id Command Argument
2020-03-31T14:35:49.793176Z 6 Query show variables like '%general_log%'
2020-03-31T14:37:20.241374Z 6 Query select * from test01
2020-03-31T14:37:21.408617Z 6 Query select id, name from test01 where id = 1
轉載請註明出處，本文鏈接：https://www.uj5u.com/shujuku/61037.html
標籤：MySQL