MySQL开启慢查询日志并使用pt-query-digest 分析

慢查询日志会将查询过程中超出你设置的时间的查询记录下来，以便供开发者进行分析和优化。

1. 开启慢查询

1.1 查看当前设置

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            | 16777216                                | | query_cache_type            | OFF                                    | | query_cache_wlock_invalidate | OFF                                    | | query_prealloc_size          | 8192                                    | | slow_query_log              | OFF                                    | | slow_query_log_file          | /var/lib/mysql/lgj-Lenovo-G470-slow.log | +------------------------------+-----------------------------------------+

三个参数

• slow_query_log  ON/OFF ,使能开关
• slow_query_log_file  慢查询日志目录和文件名称
• long_query_time    超过该时间则进行记录，5.1之前只设置到秒，5.1开始支持毫秒。

注意，开启慢查询会影响性能，因此应当在某一段时间内开启，记录一段时间后关闭掉。

1.2 配置

linuxidc@www.linuxidc.com:~/db-analysis$ whereis mysql mysql: /usr/bin/mysql /usr/lib/mysql /etc/mysql /usr/local/mysql /usr/share/mysql /usr/share/man/man1/mysql.1.gz

我的配置文件在/etc/mysql目录下的my.cnf

配置

[mysqld] port=3307 skip-grant-tables !includedir /etc/mysql/conf.d/ !includedir /etc/mysql/mysql.conf.d/

#打开慢查询 slow_query_log = ON #设置超时时间为0，也就是记录所有的查询 long_query_time = 0

设置完后保存，重新启动mysql

service mysql  restart

重新查看参数，已经更改。

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              | 0.000000                                | | query_alloc_block_size      | 8192                                    | | query_cache_limit            | 1048576                                | | query_cache_min_res_unit    | 4096                                    | | query_cache_size            | 16777216                                | | query_cache_type            | OFF                                    | | query_cache_wlock_invalidate | OFF                                    | | query_prealloc_size          | 8192                                    | | slow_query_log              | ON                                      | | slow_query_log_file          | /var/lib/mysql/lgj-Lenovo-G470-slow.log | +------------------------------+-----------------------------------------+

1.3 查询

 随便执行一条查询语句，然后查看慢查询日志。

/usr/sbin/mysqld, Version: 5.7.25-0Ubuntu0.18.04.2 ((Ubuntu)). started with: Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock Time                Id Command    Argument /usr/sbin/mysqld, Version: 5.7.25-0ubuntu0.18.04.2-log ((Ubuntu)). started with: Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock Time                Id Command    Argument /usr/sbin/mysqld, Version: 5.7.25-0ubuntu0.18.04.2-log ((Ubuntu)). started with: Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock Time                Id Command    Argument ; # Time: 2019-02-27T14:07:42.841770Z # User@Host: skip-grants user[lgj] @ localhost []  Id:    2 # Query_time: 0.016232  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0 SET timestamp=1551276462; ; # Time: 2019-02-27T14:07:51.774192Z # User@Host: skip-grants user[lgj] @ localhost []  Id:    2 # Query_time: 0.000485  Lock_time: 0.000221 Rows_sent: 1  Rows_examined: 1 SET timestamp=1551276471; select * from user; # Time: 2019-02-27T14:07:55.839223Z # User@Host: skip-grants user[lgj] @ localhost []  Id:    2 # Query_time: 0.000564  Lock_time: 0.000259 Rows_sent: 1  Rows_examined: 1 SET timestamp=1551276475; # 查询语句 select * from user; # 记录时间 # Time: 2019-02-27T14:08:07.404666Z # User@Host: skip-grants user[lgj] @ localhost []  Id:    2 #查询时间  锁表时间  # Query_time: 0.006318  Lock_time: 0.000435 Rows_sent: 13  Rows_examined: 1026 SET timestamp=1551276487;

从上面可以获知查询时间和锁表时间，但是如果文件比较大，查找时间最长的查询将会非常麻烦，需要使用相关的工具来进行分析。

2. qt-query-digest的使用

2.1 安装 •  创建目录： mkdir db-analysis && cd db-analysis • 下载 pt-query-digest: curl -LO https://percona.com/get/pt-query-digest •  设置执行权限：chmod +x pt-query-digest •  将慢查询日志的文件复制到当前的目录下 •  执行分析：  ./pt-query-digest lgj-Lenovo-G470-slow.log

结果

# 220ms user time, 10ms system time, 33.67M rss, 90.27M vsz # Current date: Wed Feb 27 22:55:05 2019 # Hostname: lgj-Lenovo-G470 # Files: lgj-Lenovo-G470-slow.log # Overall: 9 total, 7 unique, 0.24 QPS, 0.00x concurrency ________________ # Time range: 2019-02-27T14:07:29 to 2019-02-27T14:08:07 # Attribute          total    min    max    avg    95%  stddev  median # ============    ======= ======= ======= ======= ======= ======= ======= # Exec time          185ms  225us  122ms    21ms  122ms    37ms    6ms # Lock time            2ms      0  485us  186us  467us  166us  159us # Rows sent            50      0      13    5.56  12.54    5.25    0.99 # Rows examine      2.03k      0  1.00k  230.44 1012.63  419.72    0.99 # Query size          198      11      32      22  31.70    7.35  17.65

# Profile # Rank Query ID                          Response time Calls R/Call V/M  # ==== ================================= ============= ===== ====== ===== #    1 0x751417D45B8E80EE5CBA2034458B...  0.1223 66.1%    1 0.1223  0.00 SHOW DATABASES #    2 0xA11944C87A6A5C16FB38455BF703...  0.0320 17.3%    1 0.0320  0.00 SELECT #    3 0x898255B1BE4F8C3044AE35A18286...  0.0155  8.4%    1 0.0155  0.00 ADMIN INIT DB #    4 0xE77769C62EF669AA7DD5F6760F2D...  0.0134  7.3%    2 0.0067  0.00 SHOW VARIABLES # MISC 0xMISC                            0.0018  1.0%    4 0.0004  0.0 <3 ITEMS>

# Query 1: 0 QPS, 0x concurrency, ID 0x751417D45B8E80EE5CBA2034458B5BC9 at byte 1471 # This item is included in the report because it matches --limit. # Scores: V/M = 0.00 # Time range: all events occurred at 2019-02-27T14:07:42 # Attribute    pct  total    min    max    avg    95%  stddev  median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count        11      1 # Exec time    66  122ms  122ms  122ms  122ms  122ms      0  122ms # Lock time      6  110us  110us  110us  110us  110us      0  110us # Rows sent    20      10      10      10      10      10      0      10 # Rows examine  0      10      10      10      10      10      0      10 # Query size    7      14      14      14      14      14      0      14 # String: # Databases    microblog # Hosts        localhost # Users        skip-grants user # Query_time distribution #  1us #  10us # 100us #  1ms #  10ms # 100ms  ################################################################ #    1s #  10s+ show databases\G

# Query 2: 0 QPS, 0x concurrency, ID 0xA11944C87A6A5C16FB38455BF7035609 at byte 1008 # This item is included in the report because it matches --limit. # Scores: V/M = 0.00 # Time range: all events occurred at 2019-02-27T14:07:42 # Attribute    pct  total    min    max    avg    95%  stddev  median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count        11      1 # Exec time    17    32ms    32ms    32ms    32ms    32ms      0    32ms # Lock time      0      0      0      0      0      0      0      0 # Rows sent      2      1      1      1      1      1      0      1 # Rows examine  0      0      0      0      0      0      0      0 # Query size    8      17      17      17      17      17      0      17 # String: # Hosts        localhost # Users        skip-grants user # Query_time distribution #  1us #  10us # 100us #  1ms #  10ms  ################################################################ # 100ms #    1s #  10s+ # EXPLAIN /*!50100 PARTITIONS*/ SELECT DATABASE()\G

# Query 3: 0 QPS, 0x concurrency, ID 0x898255B1BE4F8C3044AE35A182869033 at byte 1225 # This item is included in the report because it matches --limit. # Scores: V/M = 0.00 # Time range: all events occurred at 2019-02-27T14:07:42 # Attribute    pct  total    min    max    avg    95%  stddev  median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count        11      1 # Exec time      8    15ms    15ms    15ms    15ms    15ms      0    15ms # Lock time      0      0      0      0      0      0      0      0 # Rows sent      0      0      0      0      0      0      0      0 # Rows examine  0      0      0      0      0      0      0      0 # Query size    15      30      30      30      30      30      0      30 # String: # Databases    microblog # Hosts        localhost # Users        skip-grants user # Query_time distribution #  1us #  10us # 100us #  1ms #  10ms  ################################################################ # 100ms #    1s #  10s+ administrator command: Init DB\G

# Query 4: 0.05 QPS, 0.00x concurrency, ID 0xE77769C62EF669AA7DD5F6760F2D2EBB at byte 775 # This item is included in the report because it matches --limit. # Scores: V/M = 0.00 # Time range: 2019-02-27T14:07:30 to 2019-02-27T14:08:07 # Attribute    pct  total    min    max    avg    95%  stddev  median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count        22      2 # Exec time      7    13ms    6ms    7ms    7ms    7ms  559us    7ms # Lock time    54  920us  435us  485us  460us  485us    35us  460us # Rows sent    52      26      13      13      13      13      0      13 # Rows examine  98  2.00k  1.00k  1.00k  1.00k  1.00k      0  1.00k # Query size    29      58      29      29      29      29      0      29 # String: # Databases    microblog # Hosts        localhost # Users        skip-grants user # Query_time distribution #  1us #  10us # 100us #  1ms  ################################################################ #  10ms # 100ms #    1s #  10s+ show variables like "%query%"\G