MySQL日志分析工具

娟斌心

　　MySQL的性能从查看日志开始。硬件配置低常常导致这样的问题，但事实上大多数情况并不在这里。某些“慢"SQL阻塞了其他语句的执行，优化查询是第一步需要做的。
　　“工欲善其事必先利其器”，MySQL自身的一款mysqldumpslow 查询日志分析器，该工具不但陈旧，验证规范不准确。今天要说的是Percona 的工具pt-query-digest,它能够分析慢查询日志内容，生成查询报告，过滤，重放或传送一些查询语句至MySQL,PostgreSQL,memcached或者其他。
　　基本语法：pt-query-digest [OPTION...] [FILE]
　　pt-query-digest [OPTION...] [FILE]
　　缺点： 对系统资源开销较大（可以将慢查询日志拷贝至其他地方分析）
　　举例1（在测试库中进行）、
　　

　　
pt-query-digest /usr/local/mysql3307/data/slow_my3307.log
　　
# 120.6s user time, 1.4s system time, 59.63M rss, 103.21M vsz
　　
# Current date: Fri Aug  3 12:21:26 2012
　　
# Hostname: XXXX
　　
# Files: /usr/local/mysql3307/data/slow_my3307.log
　　
# Overall: 515.52k total, 240 unique, 0.12 QPS, 0.00x concurrency ________
　　
# Time range: 2012-06-14 06:41:25 to 2012-08-03 12:21:26
　　
# Attribute          total     min     max     avg     95%  stddev  median
　　
# ============     ======= ======= ======= ======= ======= ======= =======
　　

　　
# Exec time          4742s    64us     16s     9ms    40ms    35ms   287us
　　
# Lock time            20s    13us    98ms    38us    49us   370us    23us
　　
# Rows sent          5.22M       0   1.10k   10.62   51.63   54.93    0.99
　　
# Rows examine       8.29G       0 101.66k  16.86k  97.04k  33.18k  964.41

　　
# Query>　　

　　部分解释如下：
　　第一行表示分析该日志所使用的时间。该文件中一共拥有515.52k慢查询（测试的情况稍稍多了点。。），其中有240个完全不同类型的查询，在该时间段内每秒处理的查询数量：0.12（关于区别完全不同的查询稍后讨论）
　　接下来是：
　　比较严重SQL的分析部分：
　　

　　
# Profile

　　
# Rank Query>　　
# ==== ================== =============== ====== ====== ==== ===== =======
　　
#    1 0xF32359E9A4679928 2680.8630 56.5% 116551 0.0230 1.00  0.05 SELECT user_bloods
　　
#    2 0xB05F93CEB2DED5F5 1908.3559 40.2%  62714 0.0304 1.00  0.00 SELECT user_bloods
　　
#    4 0x85E98D19B3A42237   28.8959  0.6%     12 2.4080 0.83 11.49 SELECT appfuse.titems
　　
# MISC 0xMISC              123.5087  2.6% 336240 0.0004   NS   0.0
　　

　　其中挑出最为严重的 4个SQL语句，（可以通过参数 --limit 进行设置）它所有语句响应时间总和，调用比例，查询类型等
　　接下来是单个语句的分析：
　　

　　
String:
　　
# Databases    YYY
　　
# Hosts
　　
# Users        XXX
　　
# Query_time distribution
　　
#   1us
　　
#  10us
　　
# 100us  ################################################################
　　
#   1ms
　　
#  10ms
　　
# 100ms
　　
#    1s  ########################
　　
#  10s+  ########
　　

　　可以看到在 在数据库YYY中用户XX 利用该语句查询的响应时间分布图，10S+ 还是很多的。
　　最后是分析情况：
　　

　　
# Tables
　　
#    SHOW TABLE STATUS FROM `YYY` LIKE 'titems'\G
　　
#    SHOW CREATE TABLE `ZZZ`.`titems`\G
　　
# EXPLAIN /*!50100 PARTITIONS*/
　　
select * from `ZZZ`.`titems`  limit 0,1000\G
　　

　　# 号部分是分析步骤，最后语句可以再前面 加上 explain 进行复制，进一步分析。
　　举例二：
　　--review 参数
　　该参数可以讲分析结果保存在某个数据表中，这样我们可以为查询做出标记，并且当第二次加上 --review 时，如果存在相同的语句分析，就不会记录到数据表中，
　　表结构如下：
　　

　　
pt-query-digest  -P 3307 -u root --password='XXXXXX' --review h=localhost,D=test,t=store --limit 5 /usr/local/mysql3307/data/slow_my3307.log
　　

　　CREATE TABLE query_review (
　　

　　
checksum     BIGINT UNSIGNED NOT NULL PRIMARY KEY,    fingerprint  TEXT NOT NULL,    sample       TEXT NOT NULL,    first_seen   DATETIME,    last_seen    DATETIME,    reviewed_by  VARCHAR(20),    reviewed_on  DATETIME,    comments     TEXT )
　　

　　checksum 一个64位校验码对应于finigerprint
　　举例：
　　

　　
checksum: 16449492566044263938

　　
fingerprint: select>
　　
sample: select>　　
first_seen: 2012-06-14 07:31:28
　　
last_seen: 2012-08-03 10:44:32
　　
reviewed_by: NULL
　　
reviewed_on: NULL
　　
comments: NULL
　　

　　举例三：
　　只收集：select 语句，并将其应用于其他的MySQLserver，并分析出耗时最长的SQL:
　　

　　
pt-query-digest   /usr/local/mysql3307/data/slow_my3307.log --execute h=localhost -u root --password='mj20100913' --filter '$event->{fingerprint} =~ m/^select/'
　　

　　(这个可以讲线上的 日志分析出来，并应用于测试的服务器上，模仿线上的真是环境)
　　举例四：
　　将processlist 收集出来 并输出到其他文件：
　　

　　
pt-query-digest --processlist h=localhost -u root --password='XXXXX' --print --no-report
　　

　　（这个默认是每秒进行一次连接并记录，可设置，如果连接失败会等待1秒在继续连接）
　　所有参数 可以通过--help看到。
　　本文未详细解释参数信息，并未列出memcached 地址（详细看这里：http://code.google.com/p/maatkit/wiki/EventAttributes），有兴趣的话大家可以参考官方文档：http://www.percona.com/doc/percona-toolkit/2.1/pt-query-digest.html#cmdoption-pt-query-digest--interval