pt-query-digest分析Mysql慢查询，Query-Digest-UI生成报表

文章分类

技术相关

随笔

随笔

专题文章

微信公众平台

文章存档

热门标签

分类：数据库 2015-03-25 19:26:17 颜色：橙色　默认　　字号：大中小阅读(5079) | 评论(0)

慢查询日志分析

1、可以使用MySQL自带的mysqldumpslow工具。使用很简单，可以跟-help来查看具体的用法。

# -s：排序方式。c , t , l , r 表示记录次数、时间、查询时间的多少、返回的记录数排序；
#                             ac , at , al , ar 表示相应的倒叙；
# -t：返回前面多少条的数据；
# -g：包含什么，大小写不敏感的；
mysqldumpslow -s r -t 10  /slowquery.log     #slow记录最多的10个语句
mysqldumpslow -s t -t 10 -g "left join"  /slowquery.log     #按照时间排序前10中含有"left join"的

2、使用pt-query-digest 工具

Percona Toolkit 是一组高级的命令行工具，用来管理 MySQL 和系统任务，主要包括：

1、验证主节点和复制数据的一致性
2、有效的对记录行进行归档
3、找出重复的索引
4、总结 MySQL 服务器
5、从日志和 tcpdump 中分析查询
6、问题发生时收集重要的系统信息

2.1、下载

pt-query-digest是一个perl脚本，只需下载并赋权即可执行。

 [root@test1 ]# wget percona.com/get/pt-query-digest 
 [root@test1 ]# chmod 744 pt-query-digest

基本语法：pt-query-digest [OPTION...] [FILE]

   常用选项:
                  —filter    对输入的慢查询按指定的字符串进行匹配过滤后，在进行分析
                  —limit    限制输出结果百分比或数量，默认值是20，即将最慢的20条语句输出
                  —host    HostName
                  —user    用户名
                  —password    密码
                  —history    将分析结果保存到表中，分析结果比较详细
                  —review    将分析结果保存到表中
                  —output    分析结果输出类型
                  —since    从什么时间开始分析，值为字符串
                  —until    截止时间，配合since一起分析

缺点：对系统资源开销较大（可以将慢查询日志拷贝至其他地方分析）

举例1（在测试库中进行）、

     pt-query-digest /usr/local/mysql3307/data/slow_my3307.log

运行工具可能会遇到下面的错误：

这是因为缺少相应包，.pm包实际上perl的包，运行下面的命令安装即可：

yum install -y perl-Time-HiRes

(1)直接分析慢查询文件:

pt-query-digest slow.log

(2)分析最近12小时内的查询：
pt-query-digest  --since=12h  slow.log

(3)分析指定时间范围内的查询：

pt-query-digest --since '2014-04-17 09:30:00' --until '2014-04-17 10:00:00' slow.log

(4)分析指含有select语句的慢查询
pt-query-digest--filter '$event->{fingerprint} =~ m/^select/i' slow.log

(5把查询保存到query_review表

pt-query-digest --user=root --password=abc123 --review h=localhost,D=test,t=query_review slow.log

(6)把查询保存到query_history表
pt-query-digest --user=root --password=abc123 --history h=localhost,D=test,t=query_ history slow.log

(7)通过tcpdump抓取mysql的tcp协议数据，然后再分析
tcpdump -s 65535 -x -nn -q -tttt -i any -c 1000 port 3306 > mysql.tcp.txt
pt-query-digest --type tcpdump mysql.tcp.txt> slow_report9.log

(8)分析binlog
mysqlbinlog mysql-bin.000093 > mysql-bin000093.sql
pt-query-digest --type=binlog mysql-bin000093.sql > slow_report10.log

(11)分析general log
pt-query-digest --type=genlog localhost.log > slow_report11.log

2.2 结果解释

第一部分是摘要：

# 620ms user time, 10ms system time, 19.76M rss, 115.84M vsz

# Current date: Wed Mar 20 16:09:35 2013

# Hostname: srv-nc-ssh1

# Files: slow.log

# Overall: 371 total, 35 unique, 0.00 QPS, 0.05x concurrency _____________

# Time range: 2013-03-18 14:08:55 to 2013-03-19 12:23:36

# Attribute total min max avg 95% stddev median

# ============ ======= ======= ======= ======= ======= ======= =======

# Exec time 3959s 1s 73s 11s 37s 12s 7s

# Lock time 246s 0 42s 663ms 204us 4s 66us

# Rows sent 37.53M 0 6.10M 103.58k 485.50k 580.16k 0

# Rows examine 71.32M 0 6.10M 196.86k 961.27k 607.20k 0

# Rows affecte 1.03M 0 973.91k 2.83k 0.99 49.98k 0.99

# Rows read 37.53M 0 6.10M 103.58k 485.50k 580.16k 0

# Bytes sent 4.48G 14 383.55M 12.36M 101.56M 45.74M 13.83

# Tmp tables 110 0 5 0.30 0.99 0.79 0

# Tmp disk tbl 12 0 1 0.03 0 0.18 0

# Tmp tbl size 21.67M 0 1009.90k 59.82k 245.21k 158.04k 0

# Query size 71.10k 31 983 196.25 400.73 100.16 166.51

对于第一部分摘要的解释：

========================================================================================================

# 620ms user time, 10ms system time, 19.76M rss, 115.84M vsz

该工具执行日志分析的用户时间，系统时间，物理内存占用大小，虚拟内存占用大小。

# Hostname: srv-nc-ssh1

运行分析工具的主机名

# Files: slow.log

被分析的文件名

# Overall: 371 total, 35 unique, 0.00 QPS, 0.05x concurrency _____________

语句总数量（371），唯一的语句（35），Qps, 并发数

# Time range: 2013-03-18 14:08:55 to 2013-03-19 12:23:36

日志记录的时间范围

# Attribute total min max avg 95% stddev median

在这些值中，最有意义的恐怕就是95%了，与中位数类似，它也是把所有值从小到大排列，位置位于95%的那个数。

#Row sent 发送到客户端的行数

#Query size 查询的字符大小

========================================================================================================

继续看第二部分：

# Profile

# Rank Query ID Response time Calls R/Call Apdx V/M

Item# ==== ================== =============== ===== ======= ==== ===== =======

# 1 0x3BE81BF6A30F4C74 1702.9604 43.0% 182 9.3569 0.15 5.91 INSERT u_search_record

# 2 0x861AC23E20A17B65 1490.0836 37.6% 54 27.5941 0.05 13.54 SELECT UNION t_ask_price_info t_vouch_info t_cust_book t_hn_info

# 3 0xD43C719B4CE15C37 96.9039 2.4% 14 6.9217 0.11 1.42 SELECT u_car_info t_stas_auc_car

# 4 0x414D67056BE15CF4 58.2516 1.5% 20 2.9126 0.40 0.56 INSERT u_auction_back_cache

# 5 0x4A78E978D2543BCD 56.5418 1.4% 3 18.8473 0.00 3.14 SELECT t_cust_book

# 6 0x3A12FD01A8D9DA10 52.8541 1.3% 3 17.6180 0.00 0.00 SELECT t_auction_back_cache

# 7 0x9186BF39CBE58A0E 50.4508 1.3% 3 16.8169 0.00 0.01 SELECT t_check_result

# 8 0x68738A978FAB0D06 42.6112 1.1% 6 7.1019 0.17 4.66 SELECT t_sys_config t_hn_info t_hn_quote_list u_car_info

# 9 0x65EBDC4319D9955A 36.9794 0.9% 1 36.9794 0.00 0.00 INSERT SELECT t_hn_info t_hn_audit_quote

# 10 0x5203D60E3716D608 35.1022 0.9% 5 7.0204 0.00 0.05 SELECT mina_send

# 11 0x64C380BEB00DFB63 28.7720 0.7% 12 2.3977 0.50 0.40 SELECT u_vehicle_type

# 12 0xCDDA52E5A6B9F0B7 27.5927 0.7% 3 9.1976 0.00 0.00 SELECT rbvehicle

# 13 0xA5E766B81112B13A 27.5218 0.7% 4 6.8804 0.12 3.51 SELECT u_auction_back_cache

# 14 0x597A26236611758F 26.7460 0.7% 3 8.9153 0.00 0.65 SELECT t_hn_audit_quote t_ask_price_info

# 15 0x443D2230FC99811C 25.2928 0.6% 3 8.4309 0.00 0.00 SELECT t_hn_quote_list

Response: 总的响应时间。
time: 该查询在本次分析中总的时间占比。
calls: 执行次数，即本次分析总共有多少条这种类型的查询语句。
R/Call: 平均每次执行的响应时间。
Item : 查询对象

这一部分显示了最慢的十六种类型的SQL语句。

我这里最慢的是INSERT INTO u_search_record…… 共有182条语句，虽然每次插入的数据都是不同的，但也被归于同一类型的语句了。

第三部分最重要了。

以排名第一的SQL为例

# Query 1: 0.00 QPS, 0.02x concurrency, ID 0x3BE81BF6A30F4C74 at byte 121216

# This item is included in the report because it matches --limit.

# Scores: Apdex = 0.15 [1.0], V/M = 5.91

# Query_time sparkline: |

# Time range: 2013-03-18 15:53:08 to 2013-03-19 12:23:36

# Attribute pct total min max avg 95% stddev median

# ============ === ======= ======= ======= ======= ======= ======= =======

# Count 49 182

# Exec time 43 1703s 1s 42s 9s 21s 7s 8s

# Lock time 0 12ms 41us 133us 64us 84us 15us 60us

# Rows sent 0 0 0 0 0 0 0 0

# Rows examine 0 0 0 0 0 0 0 0

# Rows affecte 0 182 1 1 1 1 0 1

# Rows read 0 0 0 0 0 0 0 0

# Bytes sent 0 2.49k 14 14 14 14 0 14

# Tmp tables 0 0 0 0 0 0 0 0

# Tmp disk tbl 0 0 0 0 0 0 0 0

# Tmp tbl size 0 0 0 0 0 0 0 0

# Query size 44 31.47k 166 291 177.04 192.76 24.93 158.58

# String:

# Databases xinche

# Hosts

# InnoDB trxID 855383 (1/0%), 85538E (1/0%), 855391 (1/0%)... 179 more

# Last errno 0

# Users carsingweb

# Query_time distribution

# 1us

# 10us

# 100us

# 1ms

# 10ms

# 100ms

# 1s #################################################################

# 10s+ #############################################

# Tables

# SHOW TABLE STATUS FROM `xinche` LIKE 'u_search_record'G# SHOW CREATE TABLE `xinche`.`u_search_record`G

insert into u_search_record (ip, uri, params, create_date) values ('127.0.0.1', '/car/car!ajaxGetCarInfo.action', '[{"carinfo.id":["91202"]}]', '2013-03-18 17:17:08')G

从上面可以看出，共有182条语句

[95%]Exec time是21s，时间长得比较离谱了

数据库为xinche，用户名为carsingweb

然后是query time的分布图，这个图太恶心了，不过也可以看得出来大部分是处于1-10s之间的，还有

一些超过10秒了。

最后是几条SQL语句，是pt-query-digest生成的，这些语句有助于分析问题。

3、Query-Digest-UI

为了方便查看结果，可以把结果导入数据库,再利用Query-Digest-UI查看

项目地址 https://github.com/kormoc/Query-Digest-UI

基于AJAX的Web界面，需要php环境。

配置Query-Digest-UI：

修改配置文件数据库信息： cp config.php.example config.php