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

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

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

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

查看所有标签

猜你喜欢:

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

码农书籍

《裂变：秒懂人工智能的基础课》

王天一 / 电子工业出版社·博文视点 / 2018-6-13 / 59.00元

人工智能是指通过普通计算机程序实现的人类智能技术，这一学科不仅具有非凡的科学意义，对人类自身生存方式的影响也在不断加深。本书作为人工智能领域的入门读物，内容围绕人工智能的核心框架展开，具体包括数学基础知识、机器学习算法、人工神经网络原理、深度学习方法与实例、深度学习之外的人工智能和实践应用场景等模块。本书力图为人工智能初学者提供关于这一领域的全面认识，也为进一步的深入研究建立坚实的基础。一起来看看《《裂变：秒懂人工智能的基础课》》这本书的介绍吧!

码农工具

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

《裂变：秒懂人工智能的基础课》

HTML 编码/解码

Base64 编码/解码

UNIX 时间戳转换