MySQLとPostgreSQLにおけるログの確認方法

TPCCなどをダウンロードして参照のみ、更新と参照、参照と更新の比率変更等して様々な負荷をかけてベンチマークする方が良いと思うが、カジュアルにベンチマークしたいケースもあると思います。毎回、同じ方法でベンチマークする事で、ある程度サーバーの構成変更時のパフォーマンスの変化を把握できるのでMySQLやPostgreSQLにバンドルされているベンチマークツールも便利なベンチマークオプションとして使える。取得したログを簡単に確認したり、実際に運用中のシステムのログも定期的に確認出来れば尚便利。そんなニーズに対して、カジュアルにメモしておきました。

PostgreSQL


postgres@ubuntu:~$ pgbench -i scaffold
NOTICE: table "pgbench_history" does not exist, skipping
NOTICE: table "pgbench_tellers" does not exist, skipping
NOTICE: table "pgbench_accounts" does not exist, skipping
NOTICE: table "pgbench_branches" does not exist, skipping
creating tables...
100000 of 100000 tuples (100%) done (elapsed 0.28 s, remaining 0.00 s)
vacuum...
set primary keys...
done.

postgres@ubuntu:~$ psql scaffold -c "\d"
List of relations
Schema | Name | Type | Owner
--------+------------------+-------+----------
public | pgbench_accounts | table | postgres
public | pgbench_branches | table | postgres
public | pgbench_history | table | postgres
public | pgbench_tellers | table | postgres
(4 rows)

postgres@ubuntu:~$

postgres@ubuntu:~$ pgbench -c 30 -t 1000 scaffold
starting vacuum...end.
transaction type:
scaling factor: 1
query mode: simple
number of clients: 30
number of threads: 1
number of transactions per client: 1000
number of transactions actually processed: 30000/30000
latency average = 41.333 ms
tps = 725.808779 (including connections establishing)
tps = 726.545616 (excluding connections establishing)
postgres@ubuntu:~$

root@ubuntu:/var/log/postgresql# pgbadger postgresql-10-main.log
[========================>] Parsed 96663 bytes of 96663 (100.00%), queries: 0, events: 301
LOG: Ok, generating html report...
root@ubuntu:/var/log/postgresql# ls -l
total 1392
-rw-r--r-- 1 root root 1324353 May 24 10:34 out.html
-rw-r----- 1 postgres adm 96663 May 24 10:23 postgresql-10-main.log

pgbadger
*メモ:それぞれのパッケージは、aptもしくはyumでインストールしています。

pgbadgerのアウトプット
pgbadger

MySQL

負荷をかけてログを記録


[root@GA02 admin]# /usr/local/mysql/bin/mysqlslap --no-defaults --create-schema=SQLSLAP --auto-generate-sql --auto-generate-sql-add-autoincrement --engine=InnoDB --number-int-cols=3 --number-char-cols=5 --concurrency=30 --auto-generate-sql-write-number=1000 --auto-generate-sql-execute-number=1000 --auto-generate-sql-load-type=mixed -u root -p
Enter password:
Benchmark
Running for engine InnoDB
Average number of seconds to run all queries: 19.724 seconds
Minimum number of seconds to run all queries: 19.724 seconds
Maximum number of seconds to run all queries: 19.724 seconds
Number of clients running queries: 30
Average number of queries per client: 1000

[root@GA02 admin]#

mysqldumpslow (MySQL Default)でログ解析


[root@GA02 data]# mysqldumpslow -s  c /usr/local/mysql/data/mysql-slow.log 

Reading mysql slow query log from /usr/local/mysql/data/mysql-slow.log
Count: 17349  Time=0.03s (463s)  Lock=0.00s (5s)  Rows=0.0 (0), root[root]@localhost
  INSERT INTO t1 VALUES (NULL,N,N,N,'S','S','S','S','S')

Count: 13375  Time=0.00s (2s)  Lock=0.00s (1s)  Rows=1.0 (13375), root[root]@localhost
  SELECT intcol1,intcol2,intcol3,charcol1,charcol2,charcol3,charcol4,charcol5 FROM t1 WHERE id =  'S'

Count: 31  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (30), root[root]@localhost
  #

Count: 31  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  administrator command: Quit

Percona Tool Kitでログ解析


[root@GA02 admin]# wget https://repo.percona.com/yum/percona-release-latest.noarch.rpm
--2020-05-24 13:51:20--  https://repo.percona.com/yum/percona-release-latest.noarch.rpm
repo.percona.com (repo.percona.com) をDNSに問いあわせています... 167.71.118.3, 157.245.119.64, 167.99.233.229
repo.percona.com (repo.percona.com)|167.71.118.3|:443 に接続しています... 接続しました。
HTTP による接続要求を送信しました、応答を待っています... 200 OK
長さ: 17684 (17K) [application/x-redhat-package-manager]
`percona-release-latest.noarch.rpm' に保存中

100%[==============================================================================================================================================================================================>] 17,684      --.-K/s 時間 0s      

2020-05-24 13:51:21 (51.5 GB/s) - `percona-release-latest.noarch.rpm' へ保存完了 [17684/17684]

[root@GA02 admin]# yum install percona-release-latest.noarch.rpm 
読み込んだプラグイン:fastestmirror, priorities
percona-release-latest.noarch.rpm を調べています: percona-release-1.0-18.noarch
次のリポジトリーへの更新として percona-release-latest.noarch.rpm を設定します: percona-release-0.1-4.noarch
依存性の解決をしています
--> トランザクションの確認を実行しています。
---> パッケージ percona-release.noarch 0:0.1-4 を 更新
---> パッケージ percona-release.noarch 0:1.0-18 を アップデート
--> 依存性解決を終了しました。

依存性を解決しました

========================================================================================================================================================================================================================================
 Package                                                  アーキテクチャー                                バージョン                                      リポジトリー                                                             容量
========================================================================================================================================================================================================================================
更新します:
 percona-release                                          noarch                                          1.0-18                                          /percona-release-latest.noarch                                           22 k

トランザクションの要約
========================================================================================================================================================================================================================================
更新  1 パッケージ

合計容量: 22 k
Is this ok [y/d/N]: y
Downloading packages:
Running transaction check
Running transaction test
Transaction test succeeded
Running transaction
  更新します              : percona-release-1.0-18.noarch                                                                                                                                                                           1/2 
* Enabling the Percona Original repository
<*> All done!
The percona-release package now contains a percona-release script that can enable additional repositories for our newer products.
For example, to enable the Percona Server 8.0 repository use:
  percona-release setup ps80
Note: To avoid conflicts with older product versions, the percona-release setup command may disable our original repository for some products.
For more information, please visit:
  https://www.percona.com/doc/percona-repo-config/percona-release.html
  整理中                  : percona-release-0.1-4.noarch                                                                                                                                                                            2/2 
  検証中                  : percona-release-1.0-18.noarch                                                                                                                                                                           1/2 
  検証中                  : percona-release-0.1-4.noarch                                                                                                                                                                            2/2 
更新:
  percona-release.noarch 0:1.0-18                                                                                                                                                                                                       
完了しました!
[root@GA02 admin]# 

[root@GA02 admin]# yum install percona-toolkit
読み込んだプラグイン:fastestmirror, priorities
percona-release-noarch                                                                                                                                                                                           | 2.9 kB  00:00:00     
percona-release-x86_64                                                                                                                                                                                           | 2.9 kB  00:00:00     
Loading mirror speeds from cached hostfile
 * base: mirrors.cat.net
 * epel: ftp.jaist.ac.jp
 * extras: mirrors.cat.net
 * updates: mirrors.cat.net
依存性の解決をしています
--> トランザクションの確認を実行しています。
---> パッケージ percona-toolkit.x86_64 0:3.2.0-1.el7 を インストール
--> 依存性解決を終了しました。

依存性を解決しました

========================================================================================================================================================================================================================================
 Package                                                  アーキテクチャー                                バージョン                                              リポジトリー                                                     容量
========================================================================================================================================================================================================================================
インストール中:
 percona-toolkit                                          x86_64                                          3.2.0-1.el7                                             percona-release-x86_64                                           12 M

トランザクションの要約
========================================================================================================================================================================================================================================
インストール  1 パッケージ

総ダウンロード容量: 12 M
インストール容量: 12 M
Is this ok [y/d/N]: y
Downloading packages:
警告: /var/cache/yum/x86_64/7/percona-release-x86_64/packages/percona-toolkit-3.2.0-1.el7.x86_64.rpm: ヘッダー V4 RSA/SHA256 Signature、鍵 ID 8507efa5: NOKEY========================================-] 184 kB/s |  12 MB  00:00:00 ETA 
percona-toolkit-3.2.0-1.el7.x86_64.rpm の公開鍵がインストールされていません
percona-toolkit-3.2.0-1.el7.x86_64.rpm                                                                                                                                                                           |  12 MB  00:00:50     
file:///etc/pki/rpm-gpg/PERCONA-PACKAGING-KEY から鍵を取得中です。
Importing GPG key 0x8507EFA5:
 Userid     : "Percona MySQL Development Team (Packaging key) <mysql-dev@percona.com>"
 Fingerprint: 4d1b b29d 63d9 8e42 2b21 13b1 9334 a25f 8507 efa5
 Package    : percona-release-1.0-18.noarch (@/percona-release-latest.noarch)
 From       : /etc/pki/rpm-gpg/PERCONA-PACKAGING-KEY
上記の処理を行います。よろしいでしょうか? [y/N]y
Running transaction check
Running transaction test
Transaction test succeeded
Running transaction
  インストール中          : percona-toolkit-3.2.0-1.el7.x86_64                                                                                                                                                                      1/1 
  検証中                  : percona-toolkit-3.2.0-1.el7.x86_64                                                                                                                                                                      1/1 
インストール:
  percona-toolkit.x86_64 0:3.2.0-1.el7                                                                                                                                                                                                  
完了しました!
[root@GA02 admin]# 

pt-query-digestのアウトプット


[root@GA02 data]# pt-query-digest /usr/local/mysql/data/mysql-slow.log --no-version-check

# 20.9s user time, 50ms system time, 31.58M rss, 232.37M vsz
# Current date: Sun May 24 14:19:42 2020
# Hostname: GA02
# Files: /usr/local/mysql/data/mysql-slow.log
# Overall: 30.76k total, 9 unique, 242.22 QPS, 3.73x concurrency _________
# Time range: 2020-05-24T05:07:09 to 2020-05-24T05:09:16
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           474s     1us   221ms    15ms    34ms    15ms    20ms
# Lock time             7s       0   179ms   230us   332us     4ms   103us
# Rows sent         14.04k       0     999    0.47    0.99    5.52       0
# Rows examine      14.04k       0     999    0.47    0.99    5.52       0
# Query size        12.96M      17     707  441.72  685.39  291.70  685.39

# Profile
# Rank Query ID                        Response time  Calls R/Call V/M   I
# ==== =============================== ============== ===== ====== ===== =
#    1 0x76F7DD6D2A72EB7BCAEC22E79B... 468.9853 99.0% 17349 0.0270  0.00 INSERT t?
# MISC 0xMISC                            4.5256  1.0% 13413 0.0003   0.0 <8 ITEMS>

# Query 1: 667.27 QPS, 18.04x concurrency, ID 0x76F7DD6D2A72EB7BCAEC22E79B0EFD3B at byte 988485
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2020-05-24T05:08:50 to 2020-05-24T05:09:16
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         56   17349
# Exec time     99    469s     1ms   221ms    27ms    38ms    11ms    26ms
# Lock time     75      5s       0   179ms   309us   384us     5ms   108us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size    90  11.67M     704     707  705.36  685.39       0  685.39
# String:
# Databases    SQLSLAP
# Hosts        localhost
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ###
#  10ms  ################################################################
# 100ms  #
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `SQLSLAP` LIKE 't1'\G
#    SHOW CREATE TABLE `SQLSLAP`.`t1`\G
INSERT INTO t1 VALUES (NULL,633998215,1598162325,1839677468,'l4dgQpQ2FFmHegccMlq0FmNIrmjthL1IPWzrCHuRYgk2KDWaqKb57qNyczrAKlSl7JcJcMe8uN26SYhItGF0yXybWhdqQxRQHvltIGuCfwJzTs9M0OEyv4PHl274sQ','W9M7ugNokudvtyn2CnJQmEMBO76N3yqZzCZtkwaSrBGc93XDjqfLwtOK0WkwKaLJeu5MrfiaiyAjuZwdNRyKKMYClG85iMHKGMaztHPR7SA11yWPPKddj9pKQqH8CQ','LKgvKZ4d0C52570cOHw1uXAkjSQ1TeJqy0lAPqoQ2lKzsLR8WG9PnC1NYRG1xbrvbdy1ReJLNfC8sgGFwIgbMhyu0EwxinsHGiAbKLoct1klhs0d2Y4O53J5972run','13L3eiPRAISuv1eoWhKaxQTGNfFIMA5F5QJj0k2A2WwxNRlt8yS5GpEfSTxjXuycD9CDtEGnd4d0XEufCEdS3j0O4p7ckx4x7G2sNAg0FH0mXmIc0nwwWoKaeJ2E87','3FFx0e8YWNpN1C9JgA6T6SHI3vdx1lw4tC2liAH5PySQ2dejfcCd5Lv0HOxA2uFnyHYYJhdcf52ZbYGE9KkEifErw31qx8dnH1KSax4DvzmWXvcY7KmhssOowIWlQz')\G
[root@GA02 data]# 

MySQLのエラーログ含めてGUIで確認するのであればこんなツールもあります。
Percona Monitoring and Management
MySQL Enterprise Monitor


MYSQLの運用・管理ツール検証

Percona Toolkit

最新版のPercona Toolkitをダウンロード
http://www.percona.com/downloads/percona-toolkit/LATEST/

[root@HOME001 mysql]# wget http://www.percona.com/redir/downloads/percona-toolkit/LATEST/percona-toolkit-2.1.8.tar.gz
--2013-01-31 14:03:47--  http://www.percona.com/redir/downloads/percona-toolkit/LATEST/percona-toolkit-2.1.8.tar.gz
www.percona.com をDNSに問いあわせています... 74.121.199.234
www.percona.com|74.121.199.234|:80 に接続しています... 接続しました。
HTTP による接続要求を送信しました、応答を待っています... 302 Found
場所: /downloads/percona-toolkit/LATEST/percona-toolkit-2.1.8.tar.gz [続く]
--2013-01-31 14:03:47--  http://www.percona.com/downloads/percona-toolkit/LATEST/percona-toolkit-2.1.8.tar.gz
www.percona.com:80 への接続を再利用します。
HTTP による接続要求を送信しました、応答を待っています... 200 OK
長さ: 1477253 (1.4M) [application/x-gzip]
`percona-toolkit-2.1.8.tar.gz' に保存中

100%[=======================================================================>] 1,477,253    441K/s 時間 3.3s

2013-01-31 14:03:51 (441 KB/s) - `percona-toolkit-2.1.8.tar.gz' へ保存完了 [1477253/1477253]

[root@HOME001 mysql]#

percona-toolkitのインストール

[root@HOME001 mysql]# tar -zxvf percona-toolkit-2.1.8.tar.gz
percona-toolkit-2.1.8/
percona-toolkit-2.1.8/MANIFEST
percona-toolkit-2.1.8/INSTALL
percona-toolkit-2.1.8/Changelog
percona-toolkit-2.1.8/docs/
percona-toolkit-2.1.8/docs/percona-toolkit.pod
percona-toolkit-2.1.8/Makefile.PL
percona-toolkit-2.1.8/README
省略...
percona-toolkit-2.1.8/bin/pt-slave-restart
percona-toolkit-2.1.8/bin/pt-query-digest
percona-toolkit-2.1.8/bin/pt-online-schema-change
percona-toolkit-2.1.8/bin/pt-fk-error-logger
percona-toolkit-2.1.8/bin/pt-pmp
percona-toolkit-2.1.8/bin/pt-stalk
percona-toolkit-2.1.8/bin/pt-show-grants
percona-toolkit-2.1.8/bin/pt-config-diff
percona-toolkit-2.1.8/COPYING
percona-toolkit-2.1.8/lib/
[root@HOME001 mysql]#

[root@HOME001 mysql]# cd percona-toolkit-2.1.8
[root@HOME001 percona-toolkit-2.1.8]#


[root@HOME001 percona-toolkit-2.1.8]# perl Makefile.PL
Checking if your kit is complete...
Looks good
Warning: prerequisite DBD::mysql 3 not found.
Writing Makefile for percona-toolkit
[root@HOME001 percona-toolkit-2.1.8]#


[root@HOME001 percona-toolkit-2.1.8]# cpan -i DBD::mysql
CPAN: Storable loaded ok (v2.20)
Going to read '/root/.cpan/Metadata'
  Database was generated on Thu, 31 Jan 2013 05:07:28 GMT
Running install for module 'DBD::mysql'
CPAN: Data::Dumper loaded ok (v2.124)
'YAML' not installed, falling back to Data::Dumper and Storable to read prefs '/root/.cpan/prefs'
Running make for C/CA/CAPTTOFU/DBD-mysql-4.022.tar.gz
CPAN: Digest::SHA loaded ok (v5.47)
CPAN: Compress::Zlib loaded ok (v2.02)
Checksum for /root/.cpan/sources/authors/id/C/CA/CAPTTOFU/DBD-mysql-4.022.tar.gz ok
CPAN: Archive::Tar loaded ok (v1.58)
DBD-mysql-4.022/

省略・・

Appending installation info to /usr/lib/perl5/perllocal.pod
  CAPTTOFU/DBD-mysql-4.022.tar.gz
  /usr/bin/make install  -- OK
Warning (usually harmless): 'YAML' not installed, will not store persistent state
[root@HOME001 percona-toolkit-2.1.8]#


[root@HOME001 percona-toolkit-2.1.8]# perl -MDBD::mysql -e 'print "$DBD::mysql::VERSION\n"'
4.022
[root@HOME001 percona-toolkit-2.1.8]#


[root@HOME001 percona-toolkit-2.1.8]# perl Makefile.PL
Writing Makefile for percona-toolkit
[root@HOME001 percona-toolkit-2.1.8]# 


[root@HOME001 percona-toolkit-2.1.8]# make
cp bin/pt-mysql-summary blib/script/pt-mysql-summary
/usr/bin/perl -MExtUtils::MY -e 'MY->fixin(shift)' -- blib/script/pt-mysql-summary
cp bin/pt-kill blib/script/pt-kill
/usr/bin/perl -MExtUtils::MY -e 'MY->fixin(shift)' -- blib/script/pt-kill
cp bin/pt-online-schema-change blib/script/pt-online-schema-change
/usr/bin/perl -MExtUtils::MY -e 'MY->fixin(shift)' -- blib/script/pt-online-schema-change
cp bin/pt-trend blib/script/pt-trend

省略...

Manifying blib/man1/pt-variable-advisor.1p
Manifying blib/man1/pt-index-usage.1p
Manifying blib/man1/pt-tcp-model.1p
Manifying blib/man1/pt-duplicate-key-checker.1p
Manifying blib/man1/pt-config-diff.1p
Manifying blib/man1/pt-stalk.1p
[root@HOME001 percona-toolkit-2.1.8]#


[root@HOME001 percona-toolkit-2.1.8]# make install
Installing /usr/local/share/man/man1/pt-tcp-model.1p
Installing /usr/local/share/man/man1/pt-mysql-summary.1p
Installing /usr/local/share/man/man1/pt-slave-delay.1p
Installing /usr/local/share/man/man1/pt-log-player.1p
Installing /usr/local/share/man/man1/pt-online-schema-change.1p
省略...
Installing /usr/local/bin/pt-ioprofile
Installing /usr/local/bin/pt-tcp-model
Installing /usr/local/bin/pt-table-sync
Installing /usr/local/bin/pt-find
Installing /usr/local/bin/pt-kill
Appending installation info to /usr/lib/perl5/perllocal.pod
[root@HOME001 percona-toolkit-2.1.8]#


[root@HOME001 bin]# which pt-query-digest
/usr/local/bin/pt-query-digest
[root@HOME001 bin]#

検証用のSlowログを意図的に作成してみる。
動的設定はGLOBALで設定しているので既存セッションには有効になっていないが。
既存設定を即時変更する場合は、globalオプションを付けなければOK。

mysql> show variables like 'long%';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 1.000000 |
+-----------------+----------+
1 row in set (0.00 sec)

mysql>


mysql> set global long_query_time=0;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like 'long%';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 1.000000 |
+-----------------+----------+
1 row in set (0.00 sec)

別セッションからは反映されている事を確認。

mysql> show variables like 'long%';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 0.000000 |
+-----------------+----------+
1 row in set (0.01 sec)

mysql>

幾つかQueryを実行したので、こちらをpt-query-digestで確認。

SET timestamp=1359610105;
show variables like 'long%';
# Time: 130131 14:28:32
# User@Host: root[root] @ localhost []
# Query_time: 0.000441  Lock_time: 0.000108 Rows_sent: 39  Rows_examined: 39
SET timestamp=1359610112;
select * from test.TABLE001;
# Time: 130131 14:29:08
# User@Host: root[root] @ localhost []
# Query_time: 0.433720  Lock_time: 0.000131 Rows_sent: 0  Rows_examined: 1
SET timestamp=1359610148;
delete from test.TABLE001 where id = 39;
# Time: 130131 14:29:12
# User@Host: root[root] @ localhost []
# Query_time: 0.000011  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 1
SET timestamp=1359610152;
# administrator command: Quit;

Slowログのサンプルが集まったのでlong_query_timeの設定を戻す。

mysql> set global long_query_time=1;
Query OK, 0 rows affected (0.00 sec)

mysql>

mysql> show variables like 'long%';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 1.000000 |
+-----------------+----------+
1 row in set (0.00 sec)

mysql> exit

Slowログをpt-query-digestにて解析してみる。

[root@HOME001 data]# /usr/local/bin/pt-query-digest /usr/local/mysql/data/home001-mysql-slow.log

# 380ms user time, 30ms system time, 13.71M rss, 19.34M vsz
# Current date: Thu Jan 31 14:33:10 2013
# Hostname: HOME001.localdomain
# Files: /usr/local/mysql/data/home001-mysql-slow.log
# Overall: 11 total, 7 unique, 0.06 QPS, 0.00x concurrency _______________
# Time range: 2013-01-31 14:26:02 to 14:29:12
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time          901ms    11us   461ms    82ms   433ms   171ms   865us
# Lock time            1ms       0   166us   104us   152us    53us   125us
# Rows sent            122       0      39   11.09   38.53   16.89    0.99
# Rows examine         161       0      39   14.64   38.53   18.20    0.99
# Query size           377      27      63   34.27   40.45   10.82   26.08

# Profile
# Rank Query ID           Response time Calls R/Call Apdx V/M   Item
# ==== ================== ============= ===== ====== ==== ===== ==========
#    1 0x677853E0D6CB8C75  0.4610 51.2%     1 0.4610 1.00  0.00 UPDATE test.TABLE?
#    2 0x16CB61E3D2F803A3  0.4337 48.1%     1 0.4337 1.00  0.00 DELETE test.TABLE?
# MISC 0xMISC              0.0064  0.7%     9 0.0007   NS   0.0 <5 ITEMS>

# Query 1: 0 QPS, 0x concurrency, ID 0x677853E0D6CB8C75 at byte 3035 _____
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
# Query_time sparkline: |     ^  |
# Time range: all events occurred at 2013-01-31 14:28:19
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          9       1
# Exec time     51   461ms   461ms   461ms   461ms   461ms       0   461ms
# Lock time     11   137us   137us   137us   137us   137us       0   137us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine  24      39      39      39      39      39       0      39
# Query size    16      63      63      63      63      63       0      63
# String:
# Hosts        localhost
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms  ################################################################
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `test` LIKE 'TABLE001'\G
#    SHOW CREATE TABLE `test`.`TABLE001`\G
update test.TABLE001 set comment = 'test percona-toolkit-2.1.8'\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select  comment = 'test percona-toolkit-2.1.8' from test.TABLE001 \G

# Query 2: 0 QPS, 0x concurrency, ID 0x16CB61E3D2F803A3 at byte 3653 _____
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
# Query_time sparkline: |     ^  |
# Time range: all events occurred at 2013-01-31 14:29:08
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          9       1
# Exec time     48   434ms   434ms   434ms   434ms   434ms       0   434ms
# Lock time     11   131us   131us   131us   131us   131us       0   131us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       1       1       1       1       1       0       1
# Query size    10      39      39      39      39      39       0      39
# String:
# Hosts        localhost
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms  ################################################################
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `test` LIKE 'TABLE001'\G
#    SHOW CREATE TABLE `test`.`TABLE001`\G
delete from test.TABLE001 where id = 39\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select * from  test.TABLE001 where id = 39\G
[root@HOME001 data]#

percona

参考サイト
pt-query-digest
tcpdumpとmk-query-digestでMySQLのクエリ解析
実録MySQLのチューニング 春の陣
Maatkitはtcpdumpを食べられる上,memcachedも咀嚼出来る

その他
mk-table-checksum – Perform an online replication consistency check,
maatkitでレプリケーションデータの整合性を確認
Tracking long running transactions in MySQL

関連情報
mysqldumpslow

[root@HOME001 data]# mysqldumpslow -t 3 -l /usr/local/mysql/data/home001-mysql-slow.log

Reading mysql slow query log from /usr/local/mysql/data/home001-mysql-slow.log
Count: 1  Time=0.46s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  update test.TABLE001 set comment = 'S'

Count: 1  Time=0.43s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  delete from test.TABLE001 where id = N

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  select @@version_comment limit N

[root@HOME001 data]#