慢查询日志会将查询过程中超出你设置的时间的查询记录下来,以便供开发者进行分析和优化。
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