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