mysql ptquerydigest_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 配置

lgj@lgj-Lenovo-G470:~/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=3307skip-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: 0SET 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: 1SET 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: 1SET 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: 1026SET timestamp=1551276487;

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

《高性能mysql》推荐使用 qt-query-digest 工具

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-digestlgj-Lenovo-G470-slow.log

结果

# 220ms user time, 10ms system time, 33.67M rss, 90.27M vsz

# Current date: Wed Feb27 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 avg95%stddev median

#============ ======= ======= ======= ======= ======= ======= =======# Exec time 185ms 225us 122ms 21ms 122ms 37ms 6ms

# Lock time 2ms0485us 186us 467us 166us 159us

# Rows sent50 0 13 5.56 12.54 5.25 0.99# Rows examine2.03k 0 1.00k 230.44 1012.63 419.72 0.99# Query size198 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.00SHOW DATABASES

#2 0xA11944C87A6A5C16FB38455BF703... 0.0320 17.3% 1 0.0320 0.00SELECT

#3 0x898255B1BE4F8C3044AE35A18286... 0.0155 8.4% 1 0.0155 0.00ADMIN INIT DB

#4 0xE77769C62EF669AA7DD5F6760F2D... 0.0134 7.3% 2 0.0067 0.00SHOW VARIABLES

# MISC 0xMISC0.0018 1.0% 4 0.0004 0.0 <3 ITEMS># Query1: 0 QPS, 0x concurrency, ID 0x751417D45B8E80EE5CBA2034458B5BC9 at byte 1471# This item is includedin 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 avg95%stddev median

#============ === ======= ======= ======= ======= ======= ======= =======# Count11 1# Exec time66 122ms 122ms 122ms 122ms 122ms 0122ms

# Lock time6 110us 110us 110us 110us 110us 0110us

# Rows sent20 10 10 10 10 10 0 10# Rows examine0 10 10 10 10 10 0 10# Query size7 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

# Query2: 0 QPS, 0x concurrency, ID 0xA11944C87A6A5C16FB38455BF7035609 at byte 1008# This item is includedin 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 avg95%stddev median

#============ === ======= ======= ======= ======= ======= ======= =======# Count11 1# Exec time17 32ms 32ms 32ms 32ms 32ms 032ms

# Lock time0 0 0 0 0 0 0 0# Rows sent2 1 1 1 1 1 0 1# Rows examine0 0 0 0 0 0 0 0# Query size8 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

# Query3: 0 QPS, 0x concurrency, ID 0x898255B1BE4F8C3044AE35A182869033 at byte 1225# This item is includedin 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 avg95%stddev median

#============ === ======= ======= ======= ======= ======= ======= =======# Count11 1# Exec time8 15ms 15ms 15ms 15ms 15ms 015ms

# Lock time0 0 0 0 0 0 0 0# Rows sent0 0 0 0 0 0 0 0# Rows examine0 0 0 0 0 0 0 0# Query size15 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

# Query4: 0.05 QPS, 0.00x concurrency, ID 0xE77769C62EF669AA7DD5F6760F2D2EBB at byte 775# This item is includedin 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 avg95%stddev median

#============ === ======= ======= ======= ======= ======= ======= =======# Count22 2# Exec time713ms 6ms 7ms 7ms 7ms 559us 7ms

# Lock time54920us 435us 485us 460us 485us 35us 460us

# Rows sent52 26 13 13 13 13 0 13# Rows examine98 2.00k 1.00k 1.00k 1.00k 1.00k 0 1.00k

# Query size29 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