【原創】MySQL之slowlog

摩雲飛發表於2016-05-11
MySql

慢查詢有什麼用？   
      它能記錄下所有執行超過long_query_time時間的SQL語句，幫你找到執行慢的SQL，方便我們對這些SQL進行優化。   

測試用 MySQL 版本。   
Server version: 5.6.10-log Source distribution   

未做任何慢日誌設定時。   
?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
mysql> show variables like "%query%";    
+------------------------------+--------------------------------------+
| Variable_name                | Value                                |
+------------------------------+--------------------------------------+
| binlog_rows_query_log_events | OFF                                  | 
| ft_query_expansion_limit     | 20                                   | 
| have_query_cache             | YES                                  | 
| long_query_time              | 10.000000                            | 
| query_alloc_block_size       | 8192                                 | 
| query_cache_limit            | 1048576                              | 
| query_cache_min_res_unit     | 4096                                 | 
| query_cache_size             | 1048576                              | 
| query_cache_type             | OFF                                  | 
| query_cache_wlock_invalidate | OFF                                  | 
| query_prealloc_size          | 8192                                 | 
| slow_query_log               | OFF                                  | 
| slow_query_log_file          | /usr/local/mysql/data/Betty-slow.log | 
+------------------------------+--------------------------------------+
13 rows in set (0.01 sec)
 
mysql>

修改配置檔案，開啟 slow log 。  

?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
[root@Betty data]# vi /etc/my.cnf           
 
# For advice on how to change settings please see
# http://dev.mysql.com/doc/refman/5.6/en/server-configuration-defaults.html
# *** DO NOT EDIT THIS FILE. It`s a template which will be copied to the
# *** default location during install, and will be replaced if you
# *** upgrade to a newer version of MySQL.
 
[mysqld]
 
# Remove leading # and set to the amount of RAM for the most important data
# cache in MySQL. Start at 70% of total RAM for dedicated server, else 10%.
# innodb_buffer_pool_size = 128M
 
# Remove leading # to turn on a very important data integrity option: logging
# changes to the binary log between backups.
log_bin=mysql-bin
 
slow_query_log=on
slow_query_log_file=mysql-slow
long_query_time=2
 
# These are commonly set, remove the # and set as required.
# basedir = .....
# datadir = .....
# port = .....
# server_id = .....
# socket = .....
 
# Remove leading # to set options mainly useful for reporting servers.
# The server defaults are faster for transactions and fast SELECTs.
# Adjust sizes as needed, experiment to find the optimal values.
# join_buffer_size = 128M
# sort_buffer_size = 2M
# read_rnd_buffer_size = 2M 
 
sql_mode=NO_ENGINE_SUBSTITUTION,STRICT_TRANS_TABLES
 
[mysql]
socket = /tmp/mysql.sock

重啟 MySQL 。  

?
1
2
3
4
[root@Betty data]# /etc/init.d/mysql restart
Shutting down MySQL..                                      [  OK  ]
Starting MySQL.                                            [  OK  ]
[root@Betty data]#

檢視 slow log 。  

?
1
2
[root@Betty data]# ll mysql-slow 
-rw-rw---- 1 mysql mysql 719 Sep  6 12:43 mysql-slow

重新檢視系統變數值。  

?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
mysql> 
mysql> show variables like "%query%";
+------------------------------+------------+
| Variable_name                | Value      |
+------------------------------+------------+
| binlog_rows_query_log_events | OFF        | 
| ft_query_expansion_limit     | 20         | 
| have_query_cache             | YES        | 
| long_query_time              | 2.000000   | 
| query_alloc_block_size       | 8192       | 
| query_cache_limit            | 1048576    | 
| query_cache_min_res_unit     | 4096       | 
| query_cache_size             | 1048576    | 
| query_cache_type             | OFF        | 
| query_cache_wlock_invalidate | OFF        | 
| query_prealloc_size          | 8192       | 
| slow_query_log               | ON         | 
| slow_query_log_file          | mysql-slow | 
+------------------------------+------------+
13 rows in set (0.00 sec)
 
mysql>

檢視新生成的 slow log 的內容。  

?
1
2
3
4
5
[root@Betty data]# cat mysql-slow 
/usr/local/mysql/bin/mysqld, Version: 5.6.10-log (Source distribution). started with:
Tcp port: 0  Unix socket: (null)
Time                 Id Command    Argument
[root@Betty data]#

測試 slow log 。

?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
mysql> 
mysql> select 1;
+---+
| 1 |
+---+
| 1 | 
+---+
1 row in set (0.00 sec)
 
mysql> 
mysql> select sleep(1);
+----------+
| sleep(1) |
+----------+
|        0 | 
+----------+
1 row in set (1.00 sec)
 
mysql> 
mysql> 
mysql> select sleep(3); 
+----------+
| sleep(3) |
+----------+
|        0 | 
+----------+
1 row in set (3.00 sec)
 
mysql> 
mysql> select sleep(4); 
+----------+
| sleep(4) |
+----------+
|        0 | 
+----------+
1 row in set (4.01 sec)
 
mysql> 
mysql> 
mysql> select sleep(5); 
+----------+
| sleep(5) |
+----------+
|        0 | 
+----------+
1 row in set (5.00 sec)
 
mysql> select sleep(2); 
+----------+
| sleep(2) |
+----------+
|        0 | 
+----------+
1 row in set (2.01 sec)
 
mysql> 
mysql> select sleep(1); 
+----------+
| sleep(1) |
+----------+
|        0 | 
+----------+
1 row in set (1.00 sec)
 
mysql> select 2;       
+---+
| 2 |
+---+
| 2 | 
+---+
1 row in set (0.00 sec)
 
mysql>

檢視此時 slow log 的內容。  

?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
[root@Betty data]# cat mysql-slow 
/usr/local/mysql/bin/mysqld, Version: 5.6.10-log (Source distribution). started with:
Tcp port: 0  Unix socket: (null)
Time                 Id Command    Argument
# Time: 130906 12:52:51
# User@Host: root[root] @ localhost []  Id:     1
# Query_time: 3.002864  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1378443171;
select sleep(3);
# Time: 130906 12:53:01
# User@Host: root[root] @ localhost []  Id:     1
# Query_time: 4.001943  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1378443181;
select sleep(4);
# Time: 130906 12:53:09
# User@Host: root[root] @ localhost []  Id:     1
# Query_time: 5.002093  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1378443189;
select sleep(5);
# Time: 130906 12:53:15
# User@Host: root[root] @ localhost []  Id:     1
# Query_time: 2.002984  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1378443195;
select sleep(2);
[root@Betty data]#


實驗：  

a. 使用 mysql 自帶慢查詢日誌分析工具 mysqldumpslow 。  

?
1
2
3
4
5
6
7
[root@Betty data]# mysqldumpslow mysql-slow 
 
Reading mysql slow query log from mysql-slow
Count: 4  Time=3.50s (14s)  Lock=0.00s (0s)  Rows=1.0 (4), root[root]@localhost
  select sleep(N)
 
[root@Betty data]#


b. 使用 hackmysql.com 推出的一款日誌分析工具 mysqlsla 。  

?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
[root@Betty data]# mysqlsla -lt slow mysql-slow 
Report for slow logs: mysql-slow
4 queries total, 1 unique
Sorted by `t_sum`
Grand Totals: Time 14 s, Lock 0 s, Rows sent 4, Rows Examined 0
 
______________________________________________________________________ 001 ___
Count         : 4  (100.00%)
Time          : 14.009884 s total, 3.502471 s avg, 2.002984 s to 5.002093 s max  (100.00%)
Lock Time (s) : 0 total, 0 avg, 0 to 0 max  (0.00%)
Rows sent     : 1 avg, 1 to 1 max  (100.00%)
Rows examined : 0 avg, 0 to 0 max  (0.00%)
Database      : 
Users         : 
        root@localhost  : 100.00% (4) of query, 100.00% (4) of all users
 
Query abstract:
SET timestamp=N; SELECT sleep(N);
 
Query sample:
SET timestamp=1378443171;
select sleep(3);
[root@Betty data]#


c. 使用德國人寫的 mysql_explain_slow_log 。（不知道為什麼未統計出資訊）  

?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
[root@Betty WGET_DIR]# ./mysql_explain_slow_log --user=root --password= --socket=/tmp/mysql.sock < /usr/local/mysql/data/mysql-slow     
mysql_explain_slow_log
======================
 
Index usage ------------------------------------
 
Queries causing table scans -------------------
 
Sum: 0 table scans
 
Summary ---------------------------------------
 
Select:         0 queries
Update:         0 queries
Load:   0 queries
 
Logfile:        26 lines
Started:        Fri Sep  6 15:59:13 2013
Finished:       Fri Sep  6 15:59:13 2013
[root@Betty WGET_DIR]#


d.    google code 上的一個分析工具 mysql_filter_slow_log （最後更新日期為2007年），提供了 python 和 php 兩種可執行的指令碼。   

?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
[root@Betty WGET_DIR]# python mysql_filter_slow_log.py /usr/local/mysql/data/mysql-slow --no-duplicates --sort-execution-count --top=10
# Execution count: 1 time on 2013-09-06 16:07:23.
# Column       : avg | max | sum
# Query time   :   5 |   5 |   5
# Lock time    :   0 |   0 |   0
# Rows examined:   0 |   0 |   0
# Rows sent    :   1 |   1 |   1
# User@Host: root[root] @ localhost []  Id:     1
 
SET timestamp=1378454843;select sleep(5);
 
# Execution count: 1 time on 2013-09-06 16:07:15.
# Column       : avg | max | sum
# Query time   :   4 |   4 |   4
# Lock time    :   0 |   0 |   0
# Rows examined:   0 |   0 |   0
# Rows sent    :   1 |   1 |   1
# User@Host: root[root] @ localhost []  Id:     1
 
SET timestamp=1378454835;select sleep(4);
 
# Execution count: 1 time on 2013-09-06 16:07:01.
# Column       : avg | max | sum
# Query time   :   3 |   3 |   3
# Lock time    :   0 |   0 |   0
# Rows examined:   0 |   0 |   0
# Rows sent    :   1 |   1 |   1
# User@Host: root[root] @ localhost []  Id:     1
 
SET timestamp=1378454821;select sleep(3);
 
# Execution count: 1 time on 2013-09-06 16:07:28.
# Column       : avg | max | sum
# Query time   :   2 |   2 |   2
# Lock time    :   0 |   0 |   0
# Rows examined:   0 |   0 |   0
# Rows sent    :   1 |   1 |   1
# User@Host: root[root] @ localhost []  Id:     1
 
SET timestamp=1378454848;select sleep(2);
 
[root@Betty WGET_DIR]#


e. 使用 percona-toolkit 中的 pt-query-digest （在《高效能MySQL》中多次提出，值得使用的工具）。   

?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
[root@Betty data]# pt-query-digest --user=root  mysql-slow             
 
# 120ms user time, 10ms system time, 20.21M rss, 68.70M vsz
# Current date: Mon Sep  9 13:21:38 2013
# Hostname: Betty
# Files: mysql-slow
# Overall: 4 total, 1 unique, 0.15 QPS, 0.52x concurrency ________________
# Time range: 2013-09-06 16:07:01 to 16:07:28
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time            14s      2s      5s      4s      5s      1s      4s
# Lock time              0       0       0       0       0       0       0
# Rows sent              4       1       1       1       1       0       1
# Rows examine           0       0       0       0       0       0       0
# Query size            60      15      15      15      15       0      15
 
# Profile
# Rank Query ID           Response time  Calls R/Call V/M   Item
# ==== ================== ============== ===== ====== ===== ======
#    1 0xF9A57DD5A41825CA 14.0097 100.0%     4 3.5024  0.36 SELECT
 
# Query 1: 0.15 QPS, 0.52x concurrency, ID 0xF9A57DD5A41825CA at byte 548
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.36
# Time range: 2013-09-06 16:07:01 to 16:07:28
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count        100       4
# Exec time    100     14s      2s      5s      4s      5s      1s      4s
# Lock time      0       0       0       0       0       0       0       0
# Rows sent    100       4       1       1       1       1       0       1
# Rows examine   0       0       0       0       0       0       0       0
# Query size   100      60      15      15      15      15       0      15
# String:
# Hosts        localhost
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
# EXPLAIN /*!50100 PARTITIONS*/
select sleep(5)G
[root@Betty data]#


慢查詢配置項   

?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
# I.e. you could add the following lines under the [mysqld] section of your my.ini or my.cnf configuration file:
 
# Log all queries taking more than 3 seconds
long_query_time=3  # minimum: 1, default: 10
 
# MySQL >= 5.1.21 (or patched): 3 seconds = 3000000 microseconds
# long_query_time=3.000000  # minimum: 0.000001 (1 microsecond)
 
# Activate the Slow Query Log
slow_query_log  # >= 5.1.29
# log-slow-queries  # deprecated since 5.1.29
 
# Write to a custom file name (>= 5.1.29)
# slow_query_log_file=file_name  # default: /data_dir/host_name-slow.log
 
# Log all queries without indexes
# log-queries-not-using-indexes
 
# Log only queries which examine at least N rows (>= 5.1.21)
# min_examined_row_limit=1000  # default: 0
 
# Log slow OPTIMIZE TABLE, ANALYZE TABLE, and ALTER TABLE statements
# log-slow-admin-statements
 
# Log slow queries executed by replication slaves (>= 5.1.21)
# log-slow-slave-statements
 
# MySQL 5.1.6 through 5.1.20 had a default value of log-output=TABLE, so you should force
# Attention: logging to TABLE only includes whole seconds information
log-output=FILE
 
 
## Admin query for online activation is possible since MySQL 5.1 (without server restart)
## SET @@global.slow_query_log=1
## SET @@global.long_query_time=1
 
 
## Show current variables related to the Slow Query Log
## SHOW GLOBAL VARIABLES WHERE Variable_name REGEXP `admin|min_examined|log_output|log_queries|log_slave|long|slow_quer`




========= 我是分割線 =========    

下面給出網上一篇流傳已久的部落格文章，供參考（做了部分修正）。
參考：《 五款常用mysql slow log分析工具的比較 》，原文寫於2008年。       

mysql slow log 分析工具的比較       

mysql 中的 slow log 是用來記錄執行時間較長(超過 long_query_time 秒)的 sql 的一種日誌工具。       

啟用 slow log       
在 my.cnf 中設定

?
1
2
3
[mysqld]
slow_query_log=on
slow_query_log_file=mysql-slow

重啟 MySQL 服務。

五款常用工具       

  1. mysqldumpslow
  2. mysqlsla
  3. myprofi
  4. mysql-explain-slow-log
  5. mysql-log-filter


mysqldumpslow

      mysql官方提供的慢查詢日誌分析工具。輸出圖表如下：       
       
主要功能包括統計不同慢 sql 的       

  • 出現次數(Count)
  • 執行耗費的平均時間和累計總耗費時間(Time)
  • 等待鎖耗費的時間(Lock)
  • 傳送給客戶端的行總數(Rows)
  • 掃描的行總數(Rows)
  • 使用者以及sql語句本身(抽象了一下格式，比如 limit 1, 20 用 limit N,N 表示)


mysqlsla

      hackmysql.com 推出的一款日誌分析工具(該網站還維護了 mysqlreport，mysqlidxchk 等比較實用的mysql 工具)。       
       
      整體來說，功能非常強大。輸出的資料包表非常有利於分析慢查詢的原因，包括執行頻率、資料量、查詢消耗等。       

格式說明如下：       

  • 總查詢次數 (queries total)，去重後的 sql 數量 (unique)
  • 輸出報表的內容排序(sorted by)
  • 最重大的慢 sql 統計資訊，包括平均執行時間、等待鎖時間、結果行的總數、掃描的行總數。
  • Count — sql 的執行次數及佔總的 slow log 數量的百分比。
  • Time — 執行時間，包括總時間、平均時間、最小、最大時間、時間佔到總慢 sql 時間的百分比。
  • 95% of Time — 去除最快和最慢的 sql，覆蓋率佔 95% 的 sql 的執行時間。
  • Lock Time — 等待鎖的時間。
  • 95% of Lock — 95% 的慢 sql 等待鎖時間。
  • Rows sent — 結果行統計數量，包括平均、最小、最大數量。
  • Rows examined — 掃描的行數量。
  • Database — 屬於哪個資料庫。
  • Users — 哪個使用者、IP、佔到所有使用者執行的 sql 百分比。
  • Query abstract — 抽象後的 sql 語句。
  • Query sample — sql 語句。

除了以上的輸出，官方還提供了很多定製化引數，是一款不可多得的好工具。       


mysql-explain-slow-log

      德國人寫的一個 perl 指令碼。       
http://www.willamowius.de/mysql-tools.html       
http://www.bt285.cn/content.php?id=1196863       
       

       
功能上有點瑕疵。不僅把所有的 slow log 列印到螢幕上，而且統計也只有數量而已，不推薦使用。

mysql-log-filter

      google code 上找到的一個分析工具，提供了 python 和 php 兩種可執行的指令碼。       
http://code.google.com/p/mysql-log-filter/ 
           功能上比官方的 mysqldumpslow 多了查詢時間的統計資訊(平均、最大、累計)，其他功能都與 mysqldumpslow 類似。       
      特色功能除了統計資訊外，還針對輸出內容做了排版和格式化，保證整體輸出的簡潔。喜歡簡潔報表的朋友，推薦使用一下。

myprofi

      純 php 寫的一個開源分析工具.專案在 sourceforge 上。       
http://myprofi.sourceforge.net/   ==>  已變為 http://sourceforge.net/projects/myprofi/ 
 
      功能上，列出了總的慢查詢次數和型別、去重後的 sql 語句、執行次數及其佔總的 slow log 數量的百分比。     
      從整體輸出樣式來看，比 mysql-log-filter 還要簡潔，省去了很多不必要的內容。對於只想看 sql 語句及執行次數的使用者來說，比較推薦。       

總結：   

工具/功能
 一般統計資訊
 高階統計資訊
 指令碼
 優勢
mysqldumpslow
 支援
 不支援
 perl
 mysql官方自帶
mysqlsla
 支援
 支援
 perl
 功能強大,資料包表齊全,定製化能力強
mysql-explain-slow-log
 支援
 不支援
 perl
 無
mysql-log-filter
 支援
 部分支援
 python or php
 不失功能的前提下,保持輸出簡潔
myprofi
 支援
 不支援
 php
 非常精簡




相關文章