MySql开启慢查询日志并使用pt-query-digest 分析
程序员文章站
2022-04-28 21:37:46
慢查询日志会将查询过程中超出你设置的时间的查询记录下来，以便供开发者进行分析和优化。 1. 开启慢查询 1.1 查看当前设置 输出 三个参数 slow_query_log ON/OFF ,使能开关 slow_query_log_file 慢查询日志目录和文件名称 long_query_time 超过 ......
慢查询日志会将查询过程中超出你设置的时间的查询记录下来，以便供开发者进行分析和优化。
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=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;
从上面可以获知查询时间和锁表时间，但是如果文件比较大，查找时间最长的查询将会非常麻烦，需要使用相关的工具来进行分析。
《高性能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-digest
结果
# 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