慢查詢日誌概述 所謂慢查詢日誌,就是用於記錄MySQL中響應時間超過設定閾值的SQL語句,通過打開慢查詢開關,MySQL會將大於閾值的SQL記錄在日誌中,以便於分析性能。 慢查詢日誌選項預設是關閉的,如果要開啟,則需要手動設置。 慢查詢日誌選項不建議一直開啟,因為記錄日誌意味著IO操作,本身對性能有 ...
慢查詢日誌概述
所謂慢查詢日誌,就是用於記錄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