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

栏目: 数据库 · Mysql · 发布时间: 6年前

内容简介：慢查询日志会将查询过程中超出你设置的时间的查询记录下来，以便供开发者进行分析和优化。1. 开启慢查询1.1 查看当前设置

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

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

Linux公社的RSS地址： https://www.linuxidc.com/rssFeed.aspx

本文永久更新链接地址： https://www.linuxidc.com/Linux/2019-03/157373.htm

以上就是本文的全部内容，希望本文的内容对大家的学习或者工作能带来一定的帮助，也希望大家多多支持码农网

查看所有标签

猜你喜欢:

本站部分资源来源于网络，本站转载出于传递更多信息之目的，版权归原作者或者来源机构所有，如转载稿涉及版权问题，请联系我们。

码农书籍

Domain-Driven Design

Eric Evans / Addison-Wesley Professional / 2003-8-30 / USD 74.99

"Eric Evans has written a fantastic book on how you can make the design of your software match your mental model of the problem domain you are addressing. "His book is very compatible with XP. It is n......一起来看看《Domain-Driven Design》这本书的介绍吧!

码农工具

Base64 编码/解码

XML、JSON 在线转换

在线XML、JSON转换工具