Percona-tookit学习笔记（三）

标签：percona-tookit

pt-query-digest

功能：

    根据一些规则分析查询语句，对可能的问题提出建议

说明：

    pt-query-digest可以从普通MySQL日志，慢查询日志以及二进制日志中分析查询，甚至可以从SHOW PROCESSLIST和MySQL协议的tcpdump中进行分析，如果没有指定文件，它从标准输入流（STDIN）中读取数据。

整体概要（Overall）

示例：

# pt-query-digest/usr/local/mariadb/var/node2-slow.log > /root/mysql-slow.log

# 这个部分是一个大致的概要信息(类似loadrunner给出的概要信息)，通过它可以对当前MySQL的查询性能做一个初步的评估，比如各个指标的最大值(max)，平# 均值(min)，95%分布值，中位数(median)，标准偏差(stddev)。这些指标有查询的执行时间（Exec time），锁占用的时间（Lock time），MySQL执行器需要# 检查的行数（Rowsexamine），最后返回给客户端的行数（Rows sent），查询的大小。

# 290ms user time, 20ms system time, 26.31Mrss, 215.15M vsz

# Current date: Mon May  9 14:18:13 2016

# Hostname: localhost.localdomain

# Files: /data/mysql/localhost-slow.log

# Overall: 17 total, 4 unique,0.00 QPS, 0.00x concurrency _______________  整体概要信息

# 上一行的含义：17个操作，4个语句，QPS太低了，所以显示为0

# Time range: 2016-04-10 19:57:45 to2016-04-29 14:27:38

# Attribute          total     min    max     avg     95% stddev  median

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

# Exec time          2751s     27s   938s    162s    464s   223s     60s

# Lock time            2ms    43us  434us   120us   424us  124us    53us

# Rows sent         81.79k      47 20.74k   4.81k  20.37k  7.99k  329.68

# Rows examine     345.13k      47 75.68k  20.30k  72.41k 30.48k  329.68

# Query size         2.34k      25    881     141  284.79 212.96   38.53

下面是查询的摘要信息（Profile）

这个部分对所有”重要”的查询(通常是比较慢的查询)做了个一览表:

每个查询都有一个Query ID，这个ID通过Hash计算出来的。pt-query-digest是根据这个所谓的Fingerprint来group by的。

# Profile

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

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

#   1 0x1F830B61B2FB68F0 2238.7287 81.4%    8 279.8411 28... SELECT ecs_goods

#    2 0x1FADF8A6BD46B153  244.0573 8.9%     4  61.0143 0.00 SELECT create_sn admin_user agent_sn

#   3 0xB1A36F5B279696D1 241.4298  8.8%     4 60.3574  0.00 SELECT ecs_goods

# MISC 0xMISC               26.8954  1.0%    1  26.8954   0.0 <1 ITEMS>

如下图：

Rank            整个分析中该“语句”的排名，一般也就是性能最差的。

Response time   “语句”的响应时间以及整体占比情况。

Calls           该“语句”的执行次数。

R/Call          每次执行的平均响应时间【ResponseTime/Calls】。

V/M             响应时间的差异平均对比率。

Item            显示了其他2个占比较低而不值得单独显示的查询的统计数据。

下面是每条SQL的详细报告

这个部分会列出Profile表中每个查询的详细信息：

# Query 1: 0.00 QPS, 0.00x concurrency, ID0x1F830B61B2FB68F0 at byte 0 __

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

# Scores: V/M = 286.15

# Time range: 2016-04-10 19:57:45 to2016-04-26 12:51:19

# Attribute    pct  total     min     max    avg     95%  stddev median

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

# Count         47       8

# Exec time     81  2239s     40s    938s   280s    918s    283s   285s

# Lock time     16  345us    43us    44us   43us    42us       0   42us

# Rows sent      3  2.47k      47     489 316.38  487.09  113.03 329.68

# Rows examine   0  2.47k      47     489 316.38  487.09  113.03 329.68

# Query size     8    200      25      25     25      25       0     25

# String:

# Databases    b2b

# Hosts        116.228.235.114

# Users        b2b (5/62%), b2b_user (3/37%)

# Query_time distribution

#  1us

# 10us

# 100us

#  1ms

# 10ms

# 100ms

#   1s

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

# Tables

#   SHOW TABLE STATUS FROM `b2b` LIKE ‘ecs_goods‘\G

#   SHOW CREATE TABLE `b2b`.`ecs_goods`\G

# EXPLAIN /*!50100 PARTITIONS*/

SELECT * FROM `ecs_goods`\G

# Query 2: 0.25 QPS, 15.25x concurrency, ID0x1FADF8A6BD46B153 at byte 4730

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

# Scores: V/M = 0.00

# Time range: 2016-04-28 15:17:28 to15:17:44

# Attribute    pct  total     min     max    avg     95%  stddev median

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

# Count         23       4

# Exec time      8   244s     61s     61s    61s     60s       0    60s

# Lock time     62    1ms   193us   434us  318us   424us   112us  424us

# Rows sent     94 77.67k  16.33k  20.74k 19.42k  20.37k   1.81k 20.37k

# Rows examine  86 297.44k 71.27k  75.68k  74.36k 72.41k   1.49k  72.41k

# Query size    48  1.13k     290     290    290     290       0    290

# String:

# Databases    KF_Mobile

# Hosts        116.228.235.114

# Users        KF_Mobile_user

# Query_time distribution

#  1us

# 10us

# 100us

#  1ms

# 10ms

# 100ms

#   1s

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

# Tables

#   SHOW TABLE STATUS FROM `KF_Mobile` LIKE ‘create_sn‘\G

#   SHOW CREATE TABLE `KF_Mobile`.`create_sn`\G

#   SHOW TABLE STATUS FROM `KF_Mobile` LIKE ‘admin_user‘\G

#   SHOW CREATE TABLE `KF_Mobile`.`admin_user`\G

#   SHOW TABLE STATUS FROM `KF_Mobile` LIKE ‘agent_sn‘\G

#   SHOW CREATE TABLE `KF_Mobile`.`agent_sn`\G

# EXPLAIN /*!50100 PARTITIONS*/

#select * from (

 select distincts.*,u.OEM_name,u.admin_account,IFNULL(i.active_state,‘00‘) AS state fromcreate_sn s left

 joinadmin_user u on s.agent_id=u.agent_id left join agent_sn i on i.sn_num=s.sn_num

 ##)n

 ##WHERE n.agent_id=‘84872355‘ order byn.create_date desc 84872355\G

# Query 3: 0.00 QPS, 0.00x concurrency, ID0xB1A36F5B279696D1 at byte 6896

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

# Scores: V/M = 0.00

# Time range: 2016-04-25 19:13:19 to2016-04-29 14:27:38

# Attribute    pct  total     min     max    avg     95%  stddev median

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

# Count         23       4

# Exec time      8   241s     60s     60s    60s     60s       0    60s

# Lock time     12  263us    53us   100us   65us    98us    19us   54us

# Rows sent      1  1.26k     322     326 323.75  313.99       0 313.99

# Rows examine   0  1.26k     322     326 323.75  313.99       0 313.99

# Query size     6    156      39      39     39      39       0     39

# String:

# Databases    b2b

# Hosts        116.228.235.114

# Users        b2b (2/50%), b2b_user (2/50%)

# Query_time distribution

#  1us

#  10us

# 100us

#  1ms

# 10ms

# 100ms

#   1s

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

# Tables

#   SHOW TABLE STATUS FROM `b2b` LIKE ‘ecs_goods‘\G

#   SHOW CREATE TABLE `b2b`.`ecs_goods`\G

# EXPLAIN /*!50100 PARTITIONS*/

SELECT * FROM `ecs_goods` LIMIT 0, 1000\

另外，可以从tcpdump中分析：

因为慢日志方式需要重新连接,而生产环境重启中间件是非常昂贵的操作。

所以在数据库服务器上抓包分析也是一种不错的选择。

pt-query-digest对于抓包有一定的格式。(-x -nn -q -tttt)
-s:源端口
-c:抓包的数量

操作步骤：

1、抓包
    tcpdump-s 65535 -x -nn -q -tttt -i any -c 100000 port 3306 > mysql.tcp.dmp
2、分析
    pt-query-digest--limit 20 --type tcpdump mysql.tcp.dmp

还有一些其他方法，没仔细搞过，贴一下吧：

1、从PROCESSLIST中查询某个MySQL中最慢的查询：

pt-query-digest -processlisth=host1 【操作失败，不知道原因】

2、从一台机器上讲slow log保存到另外一台机器上待稍后详细分析：

pt-query-digest --reviewh=host2 --no-report /usr/local/mariadb/var/node2-slow.log
建议：当slow log很大的时候最好还是将日志文件移到其他机器上进行分析。

还可以跟一些过滤条件。详见官方文档：http://www.percona.com/doc/percona-toolkit/2.2/pt-query-digest.html

另外结合一些第三方工具还能生成相应的报表，可以参考这里：

http://biancheng.dnbcw.info/mysql/433514.html

http://blog.csdn.net/seteor/article/details/24017913

Percona-tookit学习笔记（三）

标签：percona-tookit

原文地址：http://lee90.blog.51cto.com/10414478/1772165