登录 |  注册 |  繁體中文


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

分类: 数据库 颜色:橙色 默认  字号: 阅读(2907) | 评论(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抓取mysqltcp协议数据,然后再分析
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生成的,这些语句有助于分析问题。


3Query-Digest-UI

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

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

基于AJAXWeb界面,需要php环境。

配置Query-Digest-UI

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

 3.1  以下导入DB

pt-query-digest --review h=localhost,D=percona,t=query_review,p=pass,u=percona
 
--history h=localhost,D=percona,t=query_review_history,p=pass,u=percona  mysqld-slow-queries.log
 

查看表结果:

 

 




姓 名: *
邮 箱:
内 容: *
验证码: 点击刷新 *   

回到顶部