2015年4月30日木曜日

MySQL 5.7.5から複数のユーザーレベルロック(get_lock関数のアレ)を取れるようになった

今までは

mysql56 1> SELECT @@pseudo_thread_id;
+--------------------+
| @@pseudo_thread_id |
+--------------------+
|                  3 |
+--------------------+
1 row in set (0.00 sec)

mysql56 1>SELECT get_lock('yoku0825', 1);
+-------------------------+
| get_lock('yoku0825', 1) |
+-------------------------+
|                       1 |
+-------------------------+
1 row in set (0.02 sec)

mysql56 2> SELECT is_used_lock('yoku0825');
+--------------------------+
| is_used_lock('yoku0825') |
+--------------------------+
|                        3 |
+--------------------------+
1 row in set (0.00 sec)

こんなロックを取った状態で次のロックを取ると


mysql56 1> SELECT get_lock('yoku08253', 1);
+--------------------------+
| get_lock('yoku08253', 1) |
+--------------------------+
|                        1 |
+--------------------------+
1 row in set (0.00 sec)

mysql56 2> SELECT is_used_lock('yoku0825');
+--------------------------+
| is_used_lock('yoku0825') |
+--------------------------+
|                     NULL |
+--------------------------+
1 row in set (0.00 sec)

何も言われずに古い方のロックはリリースされていた。
これが、


mysql57 1> SELECT @@pseudo_thread_id;
+--------------------+
| @@pseudo_thread_id |
+--------------------+
|                 89 |
+--------------------+
1 row in set (0.01 sec)

mysql57 1> SELECT get_lock('yoku0825', 1);
+-------------------------+
| get_lock('yoku0825', 1) |
+-------------------------+
|                       1 |
+-------------------------+
1 row in set (0.02 sec)

mysql57 2> SELECT is_used_lock('yoku0825');
+--------------------------+
| is_used_lock('yoku0825') |
+--------------------------+
|                       89 |
+--------------------------+
1 row in set (0.01 sec)

mysql57 1> SELECT get_lock('yoku08253', 1);
+--------------------------+
| get_lock('yoku08253', 1) |
+--------------------------+
|                        1 |
+--------------------------+
1 row in set (0.00 sec)

mysql57 2> SELECT is_used_lock('yoku0825');
+--------------------------+
| is_used_lock('yoku0825') |
+--------------------------+
|                       89 |
+--------------------------+
1 row in set (0.00 sec)

複数取っても勝手にリリースされなくなった。
ユーザーロックの状態もperformance_schemaで見られるようになった的なことが書いてあるんだけど

mysql57 2> SELECT * FROM performance_schema.metadata_locks;
Empty set (0.00 sec)

mysql57 2> SELECT @@performance_schema_max_metadata_locks;
+-----------------------------------------+
| @@performance_schema_max_metadata_locks |
+-----------------------------------------+
|                                      -1 |
+-----------------------------------------+
1 row in set (0.00 sec)


あれれ…まあいいや。
-1はautosizedって書いてある けど、実際autoでいくつに設定されたんだかよくわからん。。


ところでアレだ。ロックを順次取れるようになると必ず現れてくるアイツ。そう、アイツ。

mysql57 2> SELECT get_lock('yoku0826', 1);
+-------------------------+
| get_lock('yoku0826', 1) |
+-------------------------+
|                       1 |
+-------------------------+
1 row in set (0.00 sec)

mysql57 2> SELECT get_lock('yoku08253', 1000);

mysql57 1> SELECT get_lock('yoku0826', 1);
ERROR 3058 (HY000): Deadlock found when trying to get user-level lock; try rolling back transaction/releasing locks and restarting lock acquisition.

Error 3058番。ちゃんと検出してくれるのはありがたいんだけど、この間も2番目のスレッドはget_lock関数で待ちっぱなしの状態で勝手にリリースはしてくれない。
release_lockかrelease_all_locksでリリースしてやらないとダメ。


mysql57 1> SELECT release_all_locks();
+---------------------+
| release_all_locks() |
+---------------------+
|                   2 |
+---------------------+
1 row in set (0.00 sec)

mysql57 2> SELECT get_lock('yoku08253', 1000);
+-----------------------------+
| get_lock('yoku08253', 1000) |
+-----------------------------+
|                           1 |
+-----------------------------+
1 row in set (1 min 30.79 sec)

InnoDBのデッドロックと違って *勝手にリリースしてくれない* ので、エラーをハンドルしたらrelease_lockするか接続を閉じればロックは開放されるのでそうしなければならない。
そう、お前のことだ、 *つなぎっぱなしのConnector/J氏*


MySQL :: MySQL 5.7 Release Notes :: Changes in MySQL 5.7.5 (2014-09-25, Milestone 15)

ここで"get_lock"って探すと詳しく書いてありました。

MySQL 5.7.6以降では暗黙のテンポラリーテーブルがあふれると死ぬ

MySQL 5.7.6から、JOINした時とかに作る暗黙のテンポラリーテーブルでMemoryストレージエンジンで収まらなくなった時に固定化するテンポラリーテーブル(Created_tmp_disk_tablesがカウントアップされるアレ)のストレージエンジンがInnoDBになった。

MySQL :: MySQL 5.7 Reference Manual :: 8.4.4 How MySQL Uses Internal Temporary Tables
MySQL :: MySQL 5.7 Reference Manual :: 5.1.4 Server System Variables

テンポラリーテーブル用(こっちはCREATE TEMPORARY TABLEで作るやつも含んだ言い方だと思いねえ)のテーブルスペースはREDOロギングを無効化してあったりといいこともたくさんあるんだけれど、mysqldを再起動しない限りibtmp1ファイルは決して小さくならない。



こんなエラーを見たことはないだろうか。俺はある。設定が古いサーバーだと特によくある。

mysql57> SELECT @@internal_tmp_disk_storage_engine;
+------------------------------------+
| @@internal_tmp_disk_storage_engine |
+------------------------------------+
| MYISAM                             |
+------------------------------------+
1 row in set (0.00 sec)

mysql57> SELECT * FROM (SELECT * FROM t1 WHERE val LIKE 'abc%') AS t1, (SELECT * FROM t1 WHERE val LIKE 'def%') AS t2 ORDER BY t1.num;
ERROR 126 (HY000): Incorrect key file for table '/tmp/#sql_2974_0.MYI'; try to repair it


$ tail error.log
..
2015-04-30T14:59:45.558360+09:00 87 [ERROR] /usr/mysql/5.7.7/bin/mysqld: Incorrect key file for table '/tmp/#sql_2974_0.MYI'; try to repair it
2015-04-30T14:59:45.573411+09:00 87 [ERROR] Got an error from unknown thread, /home/yoku0825/mysql-5.7.7-rc/storage/myisam/mi_write.c:223


暗黙のテンポラリーテーブルがtmpdirに作られて、容量が足りなくなるとこうなる。

$ ll /tmp
合計 792816
-rw-r----- 1 yoku0825 yoku0825 402935808  4月 30 14:59 2015 #sql_2974_0.MYD
-rw-r----- 1 yoku0825 yoku0825      1024  4月 30 14:59 2015 #sql_2974_0.MYI
-rw-rw-r-- 1 yoku0825 yoku0825 408888897  4月 30 14:45 2015 md5
drwx------ 2 yoku0825 tmux         4096  4月 17 15:45 2015 tmux-3012

$ df -h
Filesystem            Size  Used Avail Use% Mounted on
/dev/mapper/vg_00-lv_root
                       42G   40G   33M 100% /


暗黙のテンポラリーテーブルがDiskを食いきってクエリーがアボートされるとストレージ容量は元に戻る。
internal_tmp_disk_storage_engine= MyISAMのとき(MySQL 5.7.5とそれ以前)はこんな動作だった。

ところがInnoDBになるとibtmp1にこのデータを書くし、ibtmp1はmysqldの再起動まで容量が空かないので、

mysql57> SELECT @@internal_tmp_disk_storage_engine;
+------------------------------------+
| @@internal_tmp_disk_storage_engine |
+------------------------------------+
| INNODB                             |
+------------------------------------+
1 row in set (0.03 sec)

mysql57> SELECT * FROM (SELECT * FROM t1 WHERE val LIKE 'abc%') AS t1, (SELECT * FROM t1 WHERE val LIKE 'def%') AS t2 ORDER BY t1.num;
ERROR 1114 (HY000): The table '/tmp/#sql_2974_0' is full

$ tail error.log
..
2015-04-30T15:04:22.549484+09:00 87 [ERROR] InnoDB: posix_fallocate(): Failed to preallocate data for file ./ibtmp1, desired size 67108864 bytes. Operating system error number 28. Check that the disk is not full or a disk quota exceeded. Make sure the file system supports this function. Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2015-04-30T15:04:22.590070+09:00 87 [Warning] InnoDB: 1048576 bytes should have been written. Only 794624 bytes written. Retrying again to write the rem

クエリーがアボートしても容量は開放されていない。


$ ll /usr/mysql/5.7.7/data/ibtmp1
-rw-r----- 1 yoku0825 yoku0825 485236736  4月 30 15:04 2015 /usr/mysql/5.7.7/data/ibtmp1

$ df -h
Filesystem            Size  Used Avail Use% Mounted on
/dev/mapper/vg_00-lv_root
                       42G   40G   17M 100% /


ベンチマーク取りながらうっかり100%突っ込んだ人とかならわかると思うんだけれど、DiskがFullな状態で更新かけるとbinlogに書き込もうとしたときにそこで詰まって

mysql57> INSERT INTO t1 VALUES (0, 'test');

何も言わずにmysqldは応答を返さない。


(gdb) bt
#0  0x00000038862aca3d in nanosleep () at ../sysdeps/unix/syscall-template.S:82
#1  0x00000038862ac8b0 in __sleep (seconds=0) at ../sysdeps/unix/sysv/linux/sleep.c:138
#2  0x0000000000e9a111 in wait_for_free_space (filename=0x7f3d6f428690 "./bin.000002", errors=)
    at /home/yoku0825/mysql-5.7.7-rc/mysys/errors.c:85
#3  0x0000000000e9147c in my_write (Filedes=19, Buffer=0x7f3d5772e0c2 "", Count=108, MyFlags=52)
    at /home/yoku0825/mysql-5.7.7-rc/mysys/my_write.c:90
#4  0x0000000000e7f579 in inline_mysql_file_write (info=0x1cfc0c8, need_append_buffer_lock=)
    at /home/yoku0825/mysql-5.7.7-rc/include/mysql/psi/mysql_file.h:1136
#5  my_b_flush_io_cache (info=0x1cfc0c8, need_append_buffer_lock=)
    at /home/yoku0825/mysql-5.7.7-rc/mysys/mf_iocache.c:1537
#6  0x0000000000e2a317 in MYSQL_BIN_LOG::flush_cache_to_file (this=0x1cfbdc0, end_pos_var=0x7f3d6fda9520)
    at /home/yoku0825/mysql-5.7.7-rc/sql/binlog.cc:8187
#7  0x0000000000e39a14 in MYSQL_BIN_LOG::ordered_commit (this=0x1cfbdc0, thd=0x7f3d55ffa000, all=,
    skip_commit=) at /home/yoku0825/mysql-5.7.7-rc/sql/binlog.cc:8467
#8  0x0000000000e39c62 in MYSQL_BIN_LOG::write_binlog_and_commit_engine (this=0x1cfbdc0, thd=0x7f3d55ffa000,
    all=) at /home/yoku0825/mysql-5.7.7-rc/sql/binlog.cc:7858
#9  0x0000000000e3a1d4 in MYSQL_BIN_LOG::commit (this=, thd=0x7f3d55ffa000, all=)
    at /home/yoku0825/mysql-5.7.7-rc/sql/binlog.cc:7643
#10 0x000000000079dc60 in ha_commit_trans (thd=0x7f3d55ffa000, all=,
    ignore_global_read_lock=) at /home/yoku0825/mysql-5.7.7-rc/sql/handler.cc:1615
#11 0x0000000000d1c0fe in trans_commit_stmt (thd=)
    at /home/yoku0825/mysql-5.7.7-rc/sql/transaction.cc:395
#12 0x0000000000c687ec in mysql_execute_command (thd=0x7f3d55ffa000) at /home/yoku0825/mysql-5.7.7-rc/sql/sql_parse.cc:4591
#13 0x0000000000c6acb0 in mysql_parse (thd=0x7f3d55ffa000, parser_state=)
    at /home/yoku0825/mysql-5.7.7-rc/sql/sql_parse.cc:5159
#14 0x0000000000c6c1c6 in dispatch_command (command=COM_QUERY, thd=0x7f3d55ffa000,
    packet=0x7f3d55c1b011 "INSERT INTO t1 VALUES (0, 'test')", packet_length=33)
    at /home/yoku0825/mysql-5.7.7-rc/sql/sql_parse.cc:1249
#15 0x0000000000d3a1dc in handle_connection (arg=)
    at /home/yoku0825/mysql-5.7.7-rc/sql/conn_handler/connection_handler_per_thread.cc:298
#16 0x0000000000f066b7 in pfs_spawn_thread (arg=0x7f3d693a2210)
    at /home/yoku0825/mysql-5.7.7-rc/storage/perfschema/pfs.cc:2147
#17 0x00000038866079d1 in start_thread (arg=0x7f3d6fdac700) at pthread_create.c:301
#18 0x00000038862e88fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115

$ tail error.log
2015-04-30T15:12:50.592458+09:00 87 [ERROR] Disk is full writing './bin.000002' (Errcode: 28 - No space left on device). Waiting for someone to free space...
2015-04-30T15:12:50.592539+09:00 87 [ERROR] Retry in 60 secs. Message reprinted in 600 secs
2015-04-30T15:22:50.705673+09:00 87 [ERROR] Disk is full writing './bin.000002' (Errcode: 28 - No space left on device). Waiting for someone to free space...
2015-04-30T15:22:50.705730+09:00 87 [ERROR] Retry in 60 secs. Message reprinted in 600 secs
2015-04-30T15:32:50.831917+09:00 87 [ERROR] Disk is full writing './bin.000002' (Errcode: 28 - No space left on device). Waiting for someone to free space...
2015-04-30T15:32:50.831991+09:00 87 [ERROR] Retry in 60 secs. Message reprinted in 600 secs
2015-04-30T15:42:50.963577+09:00 87 [ERROR] Disk is full writing './bin.000002' (Errcode: 28 - No space left on device). Waiting for someone to free space...
2015-04-30T15:42:50.963636+09:00 87 [ERROR] Retry in 60 secs. Message reprinted in 600 secs
2015-04-30T15:52:51.098086+09:00 87 [ERROR] Disk is full writing './bin.000002' (Errcode: 28 - No space left on device). Waiting for someone to free space...
2015-04-30T15:52:51.098142+09:00 87 [ERROR] Retry in 60 secs. Message reprinted in 600 secs

ああ、一応ちゃんとリトライアウトはあるのか、よかった。。 主人をibtmp1に殺されてからはや1時間くらいになりますが、リトライ *アウト* はしてなかった。まだクエリーはエラーになってくれない。たぶん、これからもなってくれない。

デフォルトのまま使うと間違ってでっかい暗黙のテンポラリーテーブル作るクエリー投げちゃった、てへ☆ が笑い事でなくなるので、

innodb_tmp_data_file_pathをautoextendじゃない形でサイズを決め打っておくか(innodb_data_file_pathと同じノリで記述できる。暗黙のデフォルトはibtmp1:12M:autoextend。コールドパラメーターなのでMySQLの再起動が必要) または internal_tmp_disk_storage_engineをMyISAMにセットしておくか(こっちはオンラインでOK)

秘伝のmy.cnfにinnodb_tmp_data_file_pathを足しておくか。。

2015年4月3日金曜日

MySQL 5.7のEXPLAINでようやく変なUsing whereが消えた

や、EXPLAINの説明用の資料作ってて気付いたんですが、こんなサンプルテーブルに対して


mysql56> show create table cards\G
*************************** 1. row ***************************
       Table: cards
Create Table: CREATE TABLE `cards` (
  `seq` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `suite` varchar(6) NOT NULL,
  `number` tinyint(3) unsigned NOT NULL,
  UNIQUE KEY `seq` (`seq`),
  KEY `suite` (`suite`)
) ENGINE=InnoDB AUTO_INCREMENT=101 DEFAULT CHARSET=utf8
1 row in set (0.00 sec)

mysql56> SELECT * FROM cards ORDER BY _rowid LIMIT 3;
+-----+--------------+--------+
| seq | suite        | number |
+-----+--------------+--------+
|   1 | ダイヤ       |      2 |
|   2 | クラブ       |      9 |
|   3 | スペード     |      3 |
+-----+--------------+--------+
3 rows in set (0.01 sec)

WHERE句だけをインデックスで解決するクエリーをEXPLAIN取ると

mysql56> explain extended SELECT * FROM cards WHERE suite= 'ハート' ORDER BY number;
+----+-------------+-------+------+---------------+-------+---------+-------+------+----------+----------------------------------------------------+
| id | select_type | table | type | possible_keys | key   | key_len | ref   | rows | filtered | Extra                                              |
+----+-------------+-------+------+---------------+-------+---------+-------+------+----------+----------------------------------------------------+
|  1 | SIMPLE      | cards | ref  | suite         | suite | 20      | const |   31 |   100.00 | Using index condition; Using where; Using filesort |
+----+-------------+-------+------+---------------+-------+---------+-------+------+----------+----------------------------------------------------+
1 row in set, 1 warning (0.00 sec)

mysql56> SELECT * FROM cards WHERE suite= 'ハート' ORDER BY number;
..
31 rows in set (0.00 sec)

mysql56> SHOW SESSION STATUS LIKE 'handler%';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Handler_commit             | 1     |
| Handler_delete             | 0     |
| Handler_discover           | 0     |
| Handler_external_lock      | 2     |
| Handler_mrr_init           | 0     |
| Handler_prepare            | 0     |
| Handler_read_first         | 0     |
| Handler_read_key           | 1     |
| Handler_read_last          | 0     |
| Handler_read_next          | 31    |
| Handler_read_prev          | 0     |
| Handler_read_rnd           | 0     |
| Handler_read_rnd_next      | 0     |
| Handler_rollback           | 0     |
| Handler_savepoint          | 0     |
| Handler_savepoint_rollback | 0     |
| Handler_update             | 0     |
| Handler_write              | 0     |
+----------------------------+-------+
18 rows in set (0.00 sec)

こんな風になるじゃないですか。31行をインデックスからフェッチしてUsing filesort。

それはいいんですが、インデックスだけでWHERE句を解決しているにも関わらずUsing whereが出るし、filteredは100.00以外の値を見た記憶がない。これ5.5からずっとそうだったし、バグなのか仕様なのかよくわからない。

これが5.7では、


mysql57> explain extended SELECT * FROM cards WHERE suite= 'ハート' ORDER BY number;
+----+-------------+-------+------------+------+---------------+-----------+---------+-------+------+----------+---------------------------------------+
| id | select_type | table | partitions | type | possible_keys | key       | key_len | ref   | rows | filtered | Extra                                 |
+----+-------------+-------+------------+------+---------------+-----------+---------+-------+------+----------+---------------------------------------+
|  1 | SIMPLE      | cards | NULL       | ref  | idx_suite     | idx_suite | 17      | const |  100 |    31.00 | Using index condition; Using filesort |
+----+-------------+-------+------------+------+---------------+-----------+---------+-------+------+----------+---------------------------------------+
1 row in set, 2 warnings (0.00 sec)

mysql57> SELECT * FROM cards WHERE suite= 'ハート' ORDER BY number;
..
31 rows in set (0.00 sec)

mysql57> SHOW SESSION STATUS LIKE 'handler%';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Handler_commit             | 1     |
| Handler_delete             | 0     |
| Handler_discover           | 0     |
| Handler_external_lock      | 2     |
| Handler_mrr_init           | 0     |
| Handler_prepare            | 0     |
| Handler_read_first         | 0     |
| Handler_read_key           | 1     |
| Handler_read_last          | 0     |
| Handler_read_next          | 31    |
| Handler_read_prev          | 0     |
| Handler_read_rnd           | 0     |
| Handler_read_rnd_next      | 0     |
| Handler_rollback           | 0     |
| Handler_savepoint          | 0     |
| Handler_savepoint_rollback | 0     |
| Handler_update             | 0     |
| Handler_write              | 0     |
+----------------------------+-------+
18 rows in set (0.00 sec)

こうなってました。
テーブル全体がrowsの100件で、31.00%がフィルターされてってことなんでしょうかね? 変なUsing whereは姿を見せなくなっています。


とはいえなんかこのfilteredカラム、ちょっと謎で、インデックスだけで解決できないクエリーにすると

mysql57> explain extended SELECT * FROM cards WHERE suite = 'ハート' AND number = 1 ORDER BY number;
+----+-------------+-------+------------+------+---------------+-----------+---------+-------+------+----------+-------------+
| id | select_type | table | partitions | type | possible_keys | key       | key_len | ref   | rows | filtered | Extra       |
+----+-------------+-------+------------+------+---------------+-----------+---------+-------+------+----------+-------------+
|  1 | SIMPLE      | cards | NULL       | ref  | idx_suite     | idx_suite | 17      | const |   31 |    10.00 | Using where |
+----+-------------+-------+------------+------+---------------+-----------+---------+-------+------+----------+-------------+
1 row in set, 2 warnings (0.00 sec)

mysql57> SELECT * FROM cards WHERE suite = 'ハート' AND number = 1 ORDER BY number;
+-----+-----------+--------+
| seq | suite     | number |
+-----+-----------+--------+
|  41 | ハート    |      1 |
|  47 | ハート    |      1 |
|  50 | ハート    |      1 |
|  59 | ハート    |      1 |
|  96 | ハート    |      1 |
+-----+-----------+--------+
5 rows in set (0.00 sec)

rows= インデックスで解決できた31件、filterd= 10.00%は31 * 10.00% < 5とちょっと誤差が大きすぎる気がします。どうやって計算してるんだろ。

2015年4月1日水曜日

pt-online-schema-change(と、pt-table-checksumとかもろもろ)の--recursion-methodについて

pt-online-schema-change(以下、pt-osc)をはじめとするPercona Toolkitのツール群には、--recursion-methodというオプションがあります。

pt-online-schema-change — Percona Toolkit Documentation


暗黙のデフォルトは"processlist,hosts"で、なんとなくprocesslist(SHOW PROCESSLISTからBinlog Dump Threadのホスト名を引っ張り挙げる)とhosts(SHOW SLAVE HOSTSの結果からホスト名とポート番号を引っ張り挙げる)をよしなにミックスしてくれそうな雰囲気なれど。

これ残念ながら単にprocesslistだけ指定した時と同じ結果になります。

( ´-`).oO(全くトリアージされる気はしないけど、一応ばぐれぽも上げた
Bug #1438641 “Default value of --recursion-method, “processlist,...” : Bugs : Percona Toolkit

まあそれはいいとして、各--recursion-method個別の動作。動作環境は127.0.0.1:64057に5.7なマスター, 127.10.0.1:64056 に5.6なスレーブがぶら下がっている。


* processlist

$ PTDEBUG=1 pt-online-schema-change --execute --alter "Engine = InnoDB" h=127.10.0.1,D=d1,t=t1,u=root,P=64057 --recursion-method=processlist
..
# MasterSlave:4031 30199 Recursion methods: processlist
# MasterSlave:4041 30199 Connected to D=d1,P=64057,h=127.0.0.1,t=t1,u=root
# MasterSlave:4050 30199 SELECT @@SERVER_ID
# MasterSlave:4052 30199 Working on server ID 1057
# MasterSlave:4085 30199 Looking for slaves on D=d1,P=64057,h=127.0.0.1,t=t1,u=root using methods processlist
# MasterSlave:4092 30199 Finding slaves with _find_slaves_by_processlist
# MasterSlave:4154 30199 DBI::db=HASH(0x3051a08) SHOW GRANTS FOR CURRENT_USER()
# MasterSlave:4184 30199 DBI::db=HASH(0x3051a08) SHOW PROCESSLIST
..
# MasterSlave:4097 30199 Found 1 slaves
..
# MasterSlave:4041 30199 Connected to D=d1,P=64057,h=127.10.0.1,u=root
# MasterSlave:4050 30199 SELECT @@SERVER_ID
# MasterSlave:4052 30199 Working on server ID 1057
# MasterSlave:4058 30199 Server ID seen, or not what master said
..

mysql57> show processlist;
+----+------+------------------+------+------------------+------+----------------+------------------+
| Id | User | Host             | db   | Command          | Time | State          | Info             |
+----+------+------------------+------+------------------+------+----------------+------------------+
| 39 | root | 127.10.0.1:45008 | NULL | Binlog Dump GTID |  112 | Writing to net | NULL             |
| 46 | root | localhost        | NULL | Query            |    0 | starting       | show processlist |
+----+------+------------------+------+------------------+------+----------------+------------------+
2 rows in set (0.02 sec)

SHOW PROCESSLISTの結果からCommand =~ /Binlog Dump/なスレッドのHost部からホスト名を引いている。それ以外のパラメーターはもともとマスターに接続するために指定したDSN(h=127.0.0.1,D=d1,t=t1,u=root,P=64057)を流用するらしい。
なので、IPアドレスは127.10.0.1向きになっているけどポート番号がそのまま。

というわけで、
  * マスターに接続するDSNに明示的にポートを指定している場合で
    * スレーブでポート番号が違う場合
  * マスターに接続するDSNに明示的にポートを指定していない場合(S= でソケットを指定しているとか)で
    * スレーブが標準ポート(3306)以外を使っている場合
はprocesslistではスレーブの自動検出に失敗する。


* hosts

$ PTDEBUG=1 pt-online-schema-change --execute --alter "Engine = InnoDB" h=127.0.0.1,D=d1,t=t1,u=root,P=64057 --recursion-method=hosts
..
# MasterSlave:4031 30218 Recursion methods: hosts
# MasterSlave:4041 30218 Connected to D=d1,P=64057,h=127.0.0.1,t=t1,u=root
# MasterSlave:4050 30218 SELECT @@SERVER_ID
# MasterSlave:4052 30218 Working on server ID 1057
# MasterSlave:4085 30218 Looking for slaves on D=d1,P=64057,h=127.0.0.1,t=t1,u=root using methods hosts
# MasterSlave:4092 30218 Finding slaves with _find_slaves_by_hosts
# MasterSlave:4126 30218 DBI::db=HASH(0x3260a08) SHOW SLAVE HOSTS
# MasterSlave:4130 30218 Found some SHOW SLAVE HOSTS info
..
# MasterSlave:4097 30218 Found 1 slaves
# MasterSlave:4074 30218 Recursing from D=d1,P=64057,h=127.0.0.1,t=t1,u=root to D=d1,P=64056,h=,u=root
..
Cannot connect to D=d1,P=64056,h=,u=root
# pt_online_schema_change:8027 30218 0 slaves found
..

mysql57> show slave hosts;
+-----------+------+-------+-----------+--------------------------------------+
| Server_id | Host | Port  | Master_id | Slave_UUID                           |
+-----------+------+-------+-----------+--------------------------------------+
|      1056 |      | 64056 |      1057 | 5ceebb66-c191-11e4-b66a-001a4aa000e2 |
+-----------+------+-------+-----------+--------------------------------------+
1 row in set (0.00 sec)

SHOW SLAVE HOSTSの結果からHostとPortをパースして接続に行く。一見万能そうだが、--report-hostを指定していない場合は空欄になってしまって上手くパースできていない("Cannot connect to D=d1,P=64056,h=,u=root")
あと、MySQL 5.5.23からは--report-portを指定しなかった場合は暗黙のデフォルトとしてmysqldのポートが使われるのだが、それ以前の場合は3306が暗黙のデフォルトとして使われてしまうし、5.5.3より前のバージョンはそもそも--report-hostが設定されていない場合はSHOW SLAVE HOSTSに全く表示されない。

というわけで--report-hostと--report-portが正しく設定されている場合(5.5.23以降はreport-portは未指定でもいい)のみ使えるrecursion-methodで、これらはオンラインで変更できないオプションなので、pt-oscのためだけに変更するのはなんかコレジャナイ感しかしない。

MySQL :: MySQL 5.5 Reference Manual :: 13.7.5.34 SHOW SLAVE HOSTS Syntax


* dsn

というわけで、↑の条件を満たさない(非標準ポートで使っていて、--report-hostや--report-portが全てのmysqldに行き渡っているわけではない)場合に使えるrecursion-methodってこれしか残らないと思うんだけど、ぐぐっても(英語ですら)ほとんど情報がなかった。


mysql57> create table mysql.slave (id int, dsn varchar(255));
Query OK, 0 rows affected (0.67 sec)

mysql57> INSERT INTO mysql.slave VALUES (1, 'h=127.0.0.1,P=64056,u=root');
Query OK, 1 row affected (0.23 sec)

mysql57> SELECT * FROM mysql.slave;
+------+----------------------------+
| id   | dsn                        |
+------+----------------------------+
|    1 | h=127.0.0.1,P=64056,u=root |
+------+----------------------------+
1 row in set (0.12 sec)

ここは下準備。別にmysqlスキーマに作らなくてもいいし、テーブル名も何でもいい。pt-oscのオプションで任意の値を指定できる。
カラムも(マニュアルには色々書いてあるけど)`id`カラムと`dsn`カラムさえあればそれでいい。発行されるクエリーはSELECT dsn FROM .. ORDER BY idだったので、それが結果を返しさえすればOKだ。今のところは。


$ PTDEBUG=1 pt-online-schema-change --execute --alter "Engine = InnoDB" h=127.0.0.1,D=d1,t=t1,u=root,P=64057 --recursion-method="dsn=D=mysql,t=slave"
..
# MasterSlave:4598 30328 DSN table DSN: D=mysql,t=slave
..
# MasterSlave:4619 30328 SELECT dsn FROM `mysql`.`slave` ORDER BY id
# MasterSlave:4624 30328 DSN from DSN table: h=127.0.0.1,P=64056,u=root
..
# pt_online_schema_change:8027 30328 1 slaves found
# pt_online_schema_change:8052 30328 Will check slave lag on all slaves
# pt_online_schema_change:8070 30328 Checking slave replication filters
# MasterSlave:4268 30328 DBI::db=HASH(0x2a07458) SHOW MASTER STATUS
# MasterSlave:4272 30328 binlog_do_db= file=bin.000006 position=234290939 executed_gtid_set=5ceebb66-c191-11e4-b66a-001a4aa000e2:1-13,
# ecb991db-cb86-11e4-b75b-001a4aa000e2:1-613048 binlog_ignore_db=
# MasterSlave:4244 30328 DBI::db=HASH(0x2a07458) SHOW SLAVE STATUS
# MasterSlave:4570 30328 DBI::db=HASH(0x2a07458) SHOW VARIABLES LIKE 'slave_skip_errors'
..

この通り、--recursion-method="dsn=.."で指定したスキーマ, テーブルにクエリーを発行してそこからDSNを拾う。processlistの時と同じく、テーブルのdsnカラムに指定されていない部分はマスターに接続するときに使ったDSNをそのまま流用するらしい。ホスト名とポート番号だけでなくユーザーとパスワードも指定しておいた方がいい(や、rootでどのホストからでもアクセスできるならいいけど)

また、これをやっておくと多少遅延してもいいけど性能の悪いバックアップ用のスレーブのラグに引きずられて、pt-osc自体の進行が遅くなる…とかいうのも防げる。ビバ。

ちなみに接続先のDSNを間違えて、レプリケーションのつながっていないホストに接続してしまうと、

Waiting forever for new table `d1`.`_t1_new` to replicate to myhost...

( ´-`).oO(マスターで_t1_newをCREATE TABLEした後にスレーブで_t1_newが作られてるか確認してスリープしながら無限ループしてるだけ(なので、すさまじく遅延したレプリケーション環境では出うる)んだけど本当にforever待ってしまうという。。

2015年3月31日火曜日

MySQLのperformance_schemaをフルパワーにするとどんな情報が見られるのか

日々の覚書: MySQLのperformance_schemaでどれくらいの情報が見られるのか の続き。


* events_stages_summary_by_account_by_event_name
* events_stages_summary_by_host_by_event_name
* events_stages_summary_by_thread_by_event_name
* events_stages_summary_by_user_by_event_name
* events_stages_summary_global_by_event_name

mysql> SELECT * FROM events_stages_summary_by_account_by_event_name WHERE count_star <> 0 ORDER BY sum_timer_wait DESC LIMIT 3;
+------------+-----------+-------------------------+------------+----------------+----------------+----------------+----------------+
| USER       | HOST      | EVENT_NAME              | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
+------------+-----------+-------------------------+------------+----------------+----------------+----------------+----------------+
| isucon2app | localhost | stage/sql/Sending data  |       2509 | 39308705666000 |              0 |    15667080000 |   178525262000 |
| isucon2app | localhost | stage/sql/freeing items |       3000 |  7854180396000 |              0 |     2618060000 |    25104133000 |
| isucon2app | localhost | stage/sql/System lock   |       2743 |  2691080812000 |              0 |      981072000 |   244085523000 |
+------------+-----------+-------------------------+------------+----------------+----------------+----------------+----------------+
3 rows in set (0.00 sec)

デフォルトではOFFになっていたステージの情報(5.5まででいうprofiling)の情報が見られるようになる。
はかどりそうだけど、event_stageの情報をdigest(つまりクエリー単位)でサマライズして見られたらもっと良かったのになぁ。。
profileと同じようにピンポイントで有効にすれば本来いいはず。


* events_waits_summary_by_account_by_event_name
* events_waits_summary_by_host_by_event_name
* events_waits_summary_by_instance
* events_waits_summary_by_thread_by_event_name
* events_waits_summary_by_user_by_event_name
* events_waits_summary_global_by_event_name

mysql> SELECT * FROM events_waits_summary_by_account_by_event_name WHERE count_star <> 0 and event_name <> 'idle' and user = 'isucon2app' ORDER BY sum_timer_wait DESC;
+------------+-----------+------------------------------------------+------------+----------------+----------------+----------------+----------------+
| USER       | HOST      | EVENT_NAME                               | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
+------------+-----------+------------------------------------------+------------+----------------+----------------+----------------+----------------+
| isucon2app | localhost | wait/io/table/sql/handler                |   32424969 | 41901091208900 |          49280 |        1292060 |   107226966770 |
| isucon2app | localhost | wait/io/socket/sql/client_connection     |       6455 |  8661436551845 |         510125 |     1341818170 |    25122662950 |
| isucon2app | localhost | wait/io/file/innodb/innodb_log_file      |        364 |  1616073950645 |        8077685 |     4439763405 |   418325359760 |
| isucon2app | localhost | wait/io/file/innodb/innodb_data_file     |        657 |  1146723865595 |        1064525 |     1745393650 |   209724324810 |
| isucon2app | localhost | wait/synch/mutex/innodb/trx_mutex        |     699706 |    41160329980 |          20790 |          58520 |     3020631845 |
| isucon2app | localhost | wait/synch/mutex/mysys/THR_LOCK::mutex   |       9634 |    11706377760 |          26950 |        1215060 |    10035856215 |
| isucon2app | localhost | wait/lock/table/sql/handler              |      11344 |     6277293330 |          26950 |         553245 |      126401660 |
| isucon2app | localhost | wait/synch/mutex/innodb/trx_undo_mutex   |      82384 |     4336347400 |          24640 |          52360 |       41428695 |
| isucon2app | localhost | wait/synch/mutex/sql/THD::LOCK_thd_data  |      18669 |     2553290740 |          25410 |         136675 |       45770340 |
| isucon2app | localhost | wait/io/file/sql/FRM                     |        225 |      605735515 |         199045 |        2691920 |       43222025 |
| isucon2app | localhost | wait/synch/rwlock/innodb/fil_space_latch |        675 |       66989230 |          24640 |          98945 |         846615 |
| isucon2app | localhost | wait/io/file/sql/dbopt                   |          4 |       31597335 |         232925 |        7899045 |       27579475 |
| isucon2app | localhost | wait/synch/rwlock/sql/MDL_lock::rwlock   |         20 |        2514050 |          81235 |         125510 |         405405 |
+------------+-----------+------------------------------------------+------------+----------------+----------------+----------------+----------------+
13 rows in set (0.00 sec)

さっきとそんなに塩梅は変わらないものの、mutexの情報とか増えてる。

↓吊るしで同じクエリーを叩くとこれだけしか情報は出ない。

mysql> SELECT * FROM events_waits_summary_by_account_by_event_name WHERE count_star <> 0 and event_name <> 'idle' and user = 'isucon2app' ORDER BY sum_timer_wait DESC;
+------------+-----------+--------------------------------------+------------+----------------+----------------+----------------+----------------+
| USER       | HOST      | EVENT_NAME                           | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
+------------+-----------+--------------------------------------+------------+----------------+----------------+----------------+----------------+
| isucon2app | localhost | wait/io/table/sql/handler            |   30563374 | 30001032268130 |          48125 |         981365 |    65554244140 |
| isucon2app | localhost | wait/io/file/innodb/innodb_log_file  |        362 |   941252670050 |        7715785 |     2600145240 |    61855393600 |
| isucon2app | localhost | wait/io/file/innodb/innodb_data_file |        386 |   769021622600 |         872795 |     1992283755 |   110223802535 |
| isucon2app | localhost | wait/lock/table/sql/handler          |      10640 |     3912227935 |          25410 |         367675 |      136991855 |
| isucon2app | localhost | wait/io/file/sql/FRM                 |        160 |      453758305 |         201355 |        2835910 |       42650685 |
| isucon2app | localhost | wait/io/file/sql/dbopt               |          4 |       24409000 |         222530 |        6102250 |       21301280 |
+------------+-----------+--------------------------------------+------------+----------------+----------------+----------------+----------------+
6 rows in set (0.00 sec)



* mutex_instances

mysql> SELECT * FROM mutex_instances;
+-------------------------------------------------+-----------------------+---------------------+
| NAME                                            | OBJECT_INSTANCE_BEGIN | LOCKED_BY_THREAD_ID |
+-------------------------------------------------+-----------------------+---------------------+
| wait/synch/mutex/mysys/my_thread_var::mutex     |       140714335799552 |                NULL |
| wait/synch/mutex/mysys/my_thread_var::mutex     |       140714402908416 |                NULL |
| wait/synch/mutex/sql/TABLE_SHARE::LOCK_ha_data  |       140714805632408 |                NULL |
| wait/synch/mutex/mysys/THR_LOCK::mutex          |       140714805616856 |                NULL |
| wait/synch/mutex/sql/TABLE_SHARE::LOCK_ha_data  |       140714805660792 |                NULL |
| wait/synch/mutex/mysys/THR_LOCK::mutex          |       140714805657816 |                NULL |
| wait/synch/mutex/sql/TABLE_SHARE::LOCK_ha_data  |       140714805659576 |                NULL |
| wait/synch/mutex/mysys/THR_LOCK::mutex          |       140714805645720 |                NULL |
| wait/synch/mutex/sql/TABLE_SHARE::LOCK_ha_data  |       140714805679048 |                NULL |
| wait/synch/mutex/mysys/THR_LOCK::mutex          |       140714805586648 |                NULL |
| wait/synch/mutex/sql/TABLE_SHARE::LOCK_ha_data  |       140714805601848 |                NULL |
| wait/synch/mutex/mysys/THR_LOCK::mutex          |       140714805602632 |                NULL |
| wait/synch/mutex/mysys/my_thread_var::mutex     |       140714201581952 |                NULL |
| wait/synch/mutex/sql/MDL_wait::LOCK_wait_status |              36850088 |                NULL |
| wait/synch/mutex/sql/THD::LOCK_thd_data         |              36853576 |                NULL |
| wait/synch/mutex/sql/MDL_wait::LOCK_wait_status |              42562344 |                NULL |
| wait/synch/mutex/sql/THD::LOCK_thd_data         |              42565832 |                NULL |
| wait/synch/mutex/sql/MDL_wait::LOCK_wait_status |              42577160 |                NULL |
| wait/synch/mutex/sql/THD::LOCK_thd_data         |              42580648 |                NULL |
| wait/synch/mutex/sql/MDL_wait::LOCK_wait_status |              42740984 |                NULL |
| wait/synch/mutex/sql/THD::LOCK_thd_data         |              42744472 |                NULL |
| wait/synch/mutex/sql/TABLE_SHARE::LOCK_ha_data  |       140714604308568 |                NULL |
| wait/synch/mutex/sql/TABLE_SHARE::LOCK_ha_data  |       140714604309576 |                NULL |
| wait/synch/mutex/sql/MDL_wait::LOCK_wait_status |              42529224 |                NULL |
| wait/synch/mutex/sql/THD::LOCK_thd_data         |              42532712 |                NULL |
| wait/synch/mutex/sql/MDL_wait::LOCK_wait_status |              42595464 |                NULL |
| wait/synch/mutex/sql/THD::LOCK_thd_data         |              42598952 |                NULL |
+-------------------------------------------------+-----------------------+---------------------+
27 rows in set (0.00 sec)

これはむしろクエリー流している最中に見て、locked_by_thread_idが埋まりがちだったらインスタンスを分けるとかしたほうがいいのかしら。


パッと見これくらいなので、普段は吊るしのまま(バックグラウンドスレッドはOFFにしてもいい)か、setup_instrumentsのWHERE name LIKE 'stage%'を有効にだけしておいて、実際に計測したいときにsetup_consumersのevents_stages_currentをYesにしてやればいいですかね。


前にそんなことちょっと書いたなぁと思いつつ。
performance_schema_instrumentの設定方法 | GMOメディア エンジニアブログ
performance_schema_instrumentの設定方法 | GMOメディア エンジニアブログ

MySQLのperformance_schemaでどれくらいの情報が見られるのか

MySQL :: MySQL 5.6 Reference Manual :: 22 MySQL Performance Schema

5.6以降「よくなったよ!」「確かにね! でもメモリー」「」みたいな感じで扱われて結局まだONにしているインスタンスの少ないPerformance Schemaなのでちょっと練習中。

tpcc-mysqlとかでやると割と綺麗なクエリーをしているので面白い情報が出ない(ibdata1のfsyncに時間がかかってることなんて知ってるよ! って感じになる)ので、isucon2のアプリで試してみることにしますた。モリスさん++

livedoor Techブログ : 自家製 #isucon2 のつくりかた


MySQLは5.6がいいのでMySQL :: Download MySQL Yum Repositoryで入れる。

$ sudo yum localinstall -y http://dev.mysql.com/get/mysql-community-release-el6-5.noarch.rpm
$ sudo yum install -y mysql-community-*

らくちん。
吊るしでPerformance Schemaはいくらか有効になっているので(中の人いわく、「よく使いそうなものはデフォルトでONになっている」)まずはそのまま見てみる。めぼしそうなもの(とりあえずcount_starカラムが0じゃないレコードを含むテーブル)を探してみるとこんなのがあった。

↓にずらーと出力結果ばかり並べているので先に結論。

events_statements_summary_by_digest マジ優秀。
これを見るためだけに(メモリーが許すなら)performance_schemaをONにしておく価値はある。


* events_statements_summary_by_account_by_event_name
* events_statements_summary_by_host_by_event_name
* events_statements_summary_by_thread_by_event_name
* events_statements_summary_by_user_by_event_name
* events_statements_summary_global_by_event_name

mysql> SELECT * FROM events_statements_summary_by_account_by_event_name WHERE count_star <> 0 ORDER BY sum_timer_wait DESC LIMIT 3;
+------------+-----------+----------------------+------------+----------------+----------------+----------------+----------------+---------------+------------+--------------+-------------------+---------------+-------------------+-----------------------------+------------------------+----------------------+----------------------------+------------------+------------------------+-----------------+-----------------------+----------------+---------------+---------------+-------------------+------------------------+
| USER       | HOST      | EVENT_NAME           | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT | SUM_LOCK_TIME | SUM_ERRORS | SUM_WARNINGS | SUM_ROWS_AFFECTED | SUM_ROWS_SENT | SUM_ROWS_EXAMINED | SUM_CREATED_TMP_DISK_TABLES | SUM_CREATED_TMP_TABLES | SUM_SELECT_FULL_JOIN | SUM_SELECT_FULL_RANGE_JOIN | SUM_SELECT_RANGE | SUM_SELECT_RANGE_CHECK | SUM_SELECT_SCAN | SUM_SORT_MERGE_PASSES | SUM_SORT_RANGE | SUM_SORT_ROWS | SUM_SORT_SCAN | SUM_NO_INDEX_USED | SUM_NO_GOOD_INDEX_USED |
+------------+-----------+----------------------+------------+----------------+----------------+----------------+----------------+---------------+------------+--------------+-------------------+---------------+-------------------+-----------------------------+------------------------+----------------------+----------------------------+------------------+------------------------+-----------------+-----------------------+----------------+---------------+---------------+-------------------+------------------------+
| isucon2app | localhost | statement/sql/select |       2738 | 35991922775000 |       83997000 |    13145333000 |   160056655000 |  195344000000 |          0 |            0 |                 0 |       1653914 |          29363625 |                           0 |                    557 |                  556 |                          0 |                0 |                      0 |            1558 |                     0 |              0 |          4986 |           557 |              1558 |                      0 |
| isucon2app | localhost | statement/sql/insert |        148 |  3698267239000 |       81107000 |    24988292000 |  1354468459000 |  113248000000 |          0 |            0 |             82048 |             0 |                 0 |                           0 |                      0 |                    0 |                          0 |                0 |                      0 |               0 |                     0 |              0 |             0 |             0 |                 0 |                      0 |
| isucon2app | localhost | statement/sql/update |         94 |  1648364786000 |     5976157000 |    17535795000 |    42219182000 |    5534000000 |          0 |            0 |                94 |             0 |            385118 |                           0 |                      0 |                    0 |                          0 |                0 |                      0 |               0 |                     0 |             94 |            94 |             0 |                 0 |                      0 |
+------------+-----------+----------------------+------------+----------------+----------------+----------------+----------------+---------------+------------+--------------+-------------------+---------------+-------------------+-----------------------------+------------------------+----------------------+----------------------------+------------------+------------------------+-----------------+-----------------------+----------------+---------------+---------------+-------------------+------------------------+
3 rows in set (0.00 sec)

mysql> SELECT * FROM events_statements_summary_by_account_by_event_name WHERE count_star <> 0 ORDER BY sum_timer_wait DESC LIMIT 1\G
*************************** 1. row ***************************
                       USER: isucon2app
                       HOST: localhost
                 EVENT_NAME: statement/sql/select
                 COUNT_STAR: 2738
             SUM_TIMER_WAIT: 35991922775000
             MIN_TIMER_WAIT: 83997000
             AVG_TIMER_WAIT: 13145333000
             MAX_TIMER_WAIT: 160056655000
              SUM_LOCK_TIME: 195344000000
                 SUM_ERRORS: 0
               SUM_WARNINGS: 0
          SUM_ROWS_AFFECTED: 0
              SUM_ROWS_SENT: 1653914
          SUM_ROWS_EXAMINED: 29363625
SUM_CREATED_TMP_DISK_TABLES: 0
     SUM_CREATED_TMP_TABLES: 557
       SUM_SELECT_FULL_JOIN: 556
 SUM_SELECT_FULL_RANGE_JOIN: 0
           SUM_SELECT_RANGE: 0
     SUM_SELECT_RANGE_CHECK: 0
            SUM_SELECT_SCAN: 1558
      SUM_SORT_MERGE_PASSES: 0
             SUM_SORT_RANGE: 0
              SUM_SORT_ROWS: 4986
              SUM_SORT_SCAN: 557
          SUM_NO_INDEX_USED: 1558
     SUM_NO_GOOD_INDEX_USED: 0
1 row in set (0.00 sec)

うーん、ちょっと大まかすぎるかな。。sum_sort_scanとかsum_sort_merge_passesとかは出てるから、どちらかというと全体の傾向をグラフにした方がいいような気がする(や、それならinformation_schemaで今のところ足りてるけど、こっちはupdateかselectか分けて見られるってことだよね)


* events_statements_summary_by_digest

mysql> SELECT * FROM events_statements_summary_by_digest WHERE count_star <> 0 ORDER BY sum_timer_wait DESC LIMIT 3;
+-------------+----------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------+----------------+----------------+----------------+----------------+---------------+------------+--------------+-------------------+---------------+-------------------+-----------------------------+------------------------+----------------------+----------------------------+------------------+------------------------+-----------------+-----------------------+----------------+---------------+---------------+-------------------+------------------------+---------------------+---------------------+
| SCHEMA_NAME | DIGEST                           | DIGEST_TEXT                                                                                                                                                                                                                                                                                                                                                                                        | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT | SUM_LOCK_TIME | SUM_ERRORS | SUM_WARNINGS | SUM_ROWS_AFFECTED | SUM_ROWS_SENT | SUM_ROWS_EXAMINED | SUM_CREATED_TMP_DISK_TABLES | SUM_CREATED_TMP_TABLES | SUM_SELECT_FULL_JOIN | SUM_SELECT_FULL_RANGE_JOIN | SUM_SELECT_RANGE | SUM_SELECT_RANGE_CHECK | SUM_SELECT_SCAN | SUM_SORT_MERGE_PASSES | SUM_SORT_RANGE | SUM_SORT_ROWS | SUM_SORT_SCAN | SUM_NO_INDEX_USED | SUM_NO_GOOD_INDEX_USED | FIRST_SEEN          | LAST_SEEN           |
+-------------+----------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------+----------------+----------------+----------------+----------------+---------------+------------+--------------+-------------------+---------------+-------------------+-----------------------------+------------------------+----------------------+----------------------------+------------------+------------------------+-----------------+-----------------------+----------------+---------------+---------------+-------------------+------------------------+---------------------+---------------------+
| isucon2     | 68ff5779415a5d171d700f4a20fd47d0 | SELECT `stock` . `seat_id` , `variation` . `name` AS `v_name` , `ticket` . `name` AS `t_name` , `artist` . `name` AS `a_name` FROM `stock` JOIN `variation` ON `stock` . `variation_id` = `variation` . `id` JOIN `ticket` ON `variation` . `ticket_id` = `ticket` . `id` JOIN `artist` ON `ticket` . `artist_id` = `artist` . `id` WHERE `order_id` IS NOT NULL ORDER BY `order_id` DESC LIMIT ?  |        556 | 19618662892000 |    12253383000 |    35285364000 |   160056655000 |   62943000000 |          0 |            0 |                 0 |          4931 |          22848064 |                           0 |                    556 |                  556 |                          0 |                0 |                      0 |             556 |                     0 |              0 |          4931 |           556 |               556 |                      0 | 2015-03-31 14:50:03 | 2015-03-31 14:50:21 |
| isucon2     | 32f72c3a9a23b6bdf3847bbdddeb16c7 | SELECT COUNT ( * ) FROM `variation` INNER JOIN `stock` ON `stock` . `variation_id` = `variation` . `id` WHERE `variation` . `ticket_id` = ? AND `stock` . `order_id` IS NULL                                                                                                                                                                                                                       |        351 |  8184198181000 |     6442619000 |    23316803000 |    50954069000 |   27705000000 |          0 |            0 |                 0 |           351 |           2878902 |                           0 |                      0 |                    0 |                          0 |                0 |                      0 |             351 |                     0 |              0 |             0 |             0 |               351 |                      0 | 2015-03-31 14:50:03 | 2015-03-31 14:50:21 |
| isucon2     | 886e82ad6d641a9be797d0b5b1f2bf73 | SELECT `seat_id` , `order_id` FROM `stock` WHERE `variation_id` = ?                                                                                                                                                                                                                                                                                                                                |        402 |  5404182832000 |     3303525000 |    13443240000 |    38198522000 |   13646000000 |          0 |            0 |                 0 |       1646592 |           1646592 |                           0 |                      0 |                    0 |                          0 |                0 |                      0 |               0 |                     0 |              0 |             0 |             0 |                 0 |                      0 | 2015-03-31 14:50:06 | 2015-03-31 14:50:21 |
+-------------+----------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------+----------------+----------------+----------------+----------------+---------------+------------+--------------+-------------------+---------------+-------------------+-----------------------------+------------------------+----------------------+----------------------------+------------------+------------------------+-----------------+-----------------------+----------------+---------------+---------------+-------------------+------------------------+---------------------+---------------------+
3 rows in set (0.00 sec)

mysql> SELECT * FROM events_statements_summary_by_digest WHERE count_star <> 0 ORDER BY sum_timer_wait DESC LIMIT 1\G
*************************** 1. row ***************************
                SCHEMA_NAME: isucon2
                     DIGEST: 68ff5779415a5d171d700f4a20fd47d0
                DIGEST_TEXT: SELECT `stock` . `seat_id` , `variation` . `name` AS `v_name` , `ticket` . `name` AS `t_name` , `artist` . `name` AS `a_name` FROM `stock` JOIN `variation` ON `stock` . `variation_id` = `variation` . `id` JOIN `ticket` ON `variation` . `ticket_id` = `ticket` . `id` JOIN `artist` ON `ticket` . `artist_id` = `artist` . `id` WHERE `order_id` IS NOT NULL ORDER BY `order_id` DESC LIMIT ?
                 COUNT_STAR: 556
             SUM_TIMER_WAIT: 19618662892000
             MIN_TIMER_WAIT: 12253383000
             AVG_TIMER_WAIT: 35285364000
             MAX_TIMER_WAIT: 160056655000
              SUM_LOCK_TIME: 62943000000
                 SUM_ERRORS: 0
               SUM_WARNINGS: 0
          SUM_ROWS_AFFECTED: 0
              SUM_ROWS_SENT: 4931
          SUM_ROWS_EXAMINED: 22848064
SUM_CREATED_TMP_DISK_TABLES: 0
     SUM_CREATED_TMP_TABLES: 556
       SUM_SELECT_FULL_JOIN: 556
 SUM_SELECT_FULL_RANGE_JOIN: 0
           SUM_SELECT_RANGE: 0
     SUM_SELECT_RANGE_CHECK: 0
            SUM_SELECT_SCAN: 556
      SUM_SORT_MERGE_PASSES: 0
             SUM_SORT_RANGE: 0
              SUM_SORT_ROWS: 4931
              SUM_SORT_SCAN: 556
          SUM_NO_INDEX_USED: 556
     SUM_NO_GOOD_INDEX_USED: 0
                 FIRST_SEEN: 2015-03-31 14:50:03
                  LAST_SEEN: 2015-03-31 14:50:21
1 row in set (0.00 sec)

これは判りやすい。ステートメント(pt-query-digestみたいに可変部分は握りつぶしてくれる)単位でSelect_scanやSum_rows_examinedが見られる。ステキ。
Percona Serverのスローログ + pt-query-digest並みの情報量な気がする。パーセンタイルな情報はないけどまあいいや。


* events_waits_summary_by_account_by_event_name
* events_waits_summary_by_host_by_event_name
* events_waits_summary_by_instance
* events_waits_summary_by_thread_by_event_name
* events_waits_summary_by_user_by_event_name
* events_waits_summary_global_by_event_name

mysql> SELECT * FROM events_waits_summary_by_account_by_event_name WHERE count_star <> 0 AND event_name <> 'idle' ORDER BY sum_timer_wait DESC LIMIT 3;
+------------+-----------+--------------------------------------+------------+----------------+----------------+----------------+----------------+
| USER       | HOST      | EVENT_NAME                           | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
+------------+-----------+--------------------------------------+------------+----------------+----------------+----------------+----------------+
| isucon2app | localhost | wait/io/table/sql/handler            |   29763732 | 28437697326885 |          48125 |         955185 |  1355498746525 |
| isucon2app | localhost | wait/io/file/innodb/innodb_data_file |        417 |  2104885627075 |        2718100 |     5047687260 |  1191383874065 |
| isucon2app | localhost | wait/io/file/innodb/innodb_log_file  |        350 |   865270214655 |        7838215 |     2472200500 |    58576612710 |
+------------+-----------+--------------------------------------+------------+----------------+----------------+----------------+----------------+
3 rows in set (0.00 sec)

mysql> SELECT * FROM events_waits_summary_by_account_by_event_name WHERE count_star <> 0 AND event_name <> 'idle' ORDER BY sum_timer_wait DESC LIMIT 1\G
*************************** 1. row ***************************
          USER: isucon2app
          HOST: localhost
    EVENT_NAME: wait/io/table/sql/handler
    COUNT_STAR: 29763732
SUM_TIMER_WAIT: 28437697326885
MIN_TIMER_WAIT: 48125
AVG_TIMER_WAIT: 955185
MAX_TIMER_WAIT: 1355498746525
1 row in set (0.00 sec)

どこのイベントで待ちが発生したかの情報なんだけど、なんかやっぱりちょっと粒度が荒い。
ibdata1で待ってるのは知ってるよ! でもdouble write切れないんだよ! って感じ。


* file_summary_by_event_name

mysql> SELECT * FROM file_summary_by_event_name WHERE count_star <> 0 ORDER BY sum_timer_wait DESC LIMIT 3;
+--------------------------------------+------------+----------------+----------------+----------------+----------------+------------+----------------+----------------+----------------+----------------+--------------------------+-------------+-----------------+-----------------+-----------------+-----------------+---------------------------+------------+----------------+----------------+----------------+----------------+
| EVENT_NAME                           | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT | COUNT_READ | SUM_TIMER_READ | MIN_TIMER_READ | AVG_TIMER_READ | MAX_TIMER_READ | SUM_NUMBER_OF_BYTES_READ | COUNT_WRITE | SUM_TIMER_WRITE | MIN_TIMER_WRITE | AVG_TIMER_WRITE | MAX_TIMER_WRITE | SUM_NUMBER_OF_BYTES_WRITE | COUNT_MISC | SUM_TIMER_MISC | MIN_TIMER_MISC | AVG_TIMER_MISC | MAX_TIMER_MISC |
+--------------------------------------+------------+----------------+----------------+----------------+----------------+------------+----------------+----------------+----------------+----------------+--------------------------+-------------+-----------------+-----------------+-----------------+-----------------+---------------------------+------------+----------------+----------------+----------------+----------------+
| wait/io/file/innodb/innodb_data_file |       1519 |  2481586224040 |              0 |     1633697065 |  1191383874065 |        163 |     3469540305 |              0 |       21285495 |      896338905 |                  4734976 |        1029 |    206577099575 |               0 |       200755170 |     20881438270 |                 119422976 |        327 |  2271539584160 |              0 |     6946603895 |  1191383874065 |
| wait/io/file/innodb/innodb_log_file  |        434 |  1022073887450 |              0 |     2355008810 |    58576612710 |          6 |       27545210 |              0 |        4590740 |       22502480 |                    69632 |         211 |    262934620795 |               0 |      1246135275 |     58576612710 |                   7907840 |        217 |   759111721445 |              0 |     3498210485 |    41712168190 |
| wait/io/file/sql/FRM                 |       1663 |   374523815050 |              0 |      225209600 |   205524644710 |        739 |   124995936065 |              0 |      169141665 |    29619563050 |                   167156 |         105 |       176487850 |               0 |         1680525 |        15076215 |                     26609 |        819 |   249351391135 |              0 |      304458000 |   205524644710 |
+--------------------------------------+------------+----------------+----------------+----------------+----------------+------------+----------------+----------------+----------------+----------------+--------------------------+-------------+-----------------+-----------------+-----------------+-----------------+---------------------------+------------+----------------+----------------+----------------+----------------+
3 rows in set (0.00 sec)

mysql> SELECT * FROM file_summary_by_event_name WHERE count_star <> 0 ORDER BY sum_timer_wait DESC LIMIT 1\G
*************************** 1. row ***************************
               EVENT_NAME: wait/io/file/innodb/innodb_data_file
               COUNT_STAR: 1519
           SUM_TIMER_WAIT: 2481586224040
           MIN_TIMER_WAIT: 0
           AVG_TIMER_WAIT: 1633697065
           MAX_TIMER_WAIT: 1191383874065
               COUNT_READ: 163
           SUM_TIMER_READ: 3469540305
           MIN_TIMER_READ: 0
           AVG_TIMER_READ: 21285495
           MAX_TIMER_READ: 896338905
 SUM_NUMBER_OF_BYTES_READ: 4734976
              COUNT_WRITE: 1029
          SUM_TIMER_WRITE: 206577099575
          MIN_TIMER_WRITE: 0
          AVG_TIMER_WRITE: 200755170
          MAX_TIMER_WRITE: 20881438270
SUM_NUMBER_OF_BYTES_WRITE: 119422976
               COUNT_MISC: 327
           SUM_TIMER_MISC: 2271539584160
           MIN_TIMER_MISC: 0
           AVG_TIMER_MISC: 6946603895
           MAX_TIMER_MISC: 1191383874065
1 row in set (0.00 sec)

WAIT, READ, WRITE, MISCに分かれているので多少見やすそうだけど、粒度が荒くてちょっとつらい。
対して、↓の


* file_summary_by_instance

mysql> SELECT * FROM file_summary_by_instance WHERE count_star <> 0 ORDER BY sum_timer_wait DESC LIMIT 3;
+----------------------------------+--------------------------------------+-----------------------+------------+----------------+----------------+----------------+----------------+------------+----------------+----------------+----------------+----------------+--------------------------+-------------+-----------------+-----------------+-----------------+-----------------+---------------------------+------------+----------------+----------------+----------------+----------------+
| FILE_NAME                        | EVENT_NAME                           | OBJECT_INSTANCE_BEGIN | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT | COUNT_READ | SUM_TIMER_READ | MIN_TIMER_READ | AVG_TIMER_READ | MAX_TIMER_READ | SUM_NUMBER_OF_BYTES_READ | COUNT_WRITE | SUM_TIMER_WRITE | MIN_TIMER_WRITE | AVG_TIMER_WRITE | MAX_TIMER_WRITE | SUM_NUMBER_OF_BYTES_WRITE | COUNT_MISC | SUM_TIMER_MISC | MIN_TIMER_MISC | AVG_TIMER_MISC | MAX_TIMER_MISC |
+----------------------------------+--------------------------------------+-----------------------+------------+----------------+----------------+----------------+----------------+------------+----------------+----------------+----------------+----------------+--------------------------+-------------+-----------------+-----------------+-----------------+-----------------+---------------------------+------------+----------------+----------------+----------------+----------------+
| /var/lib/mysql/ibdata1           | wait/io/file/innodb/innodb_data_file |       140132153275264 |        819 |  1604593676840 |        2331560 |     1959210715 |  1191383874065 |        157 |     3398451980 |        3504655 |       21645855 |      896338905 |                  4636672 |         626 |    181296946215 |         7489790 |       289611630 |     20881438270 |                  88735744 |         36 |  1419898278645 |        2331560 |    39441618755 |  1191383874065 |
| /var/lib/mysql/ib_logfile0       | wait/io/file/innodb/innodb_log_file  |       140132153275968 |        431 |  1022063454720 |         382690 |     2371376700 |    58576612710 |          6 |       27545210 |         382690 |        4590740 |       22502480 |                    69632 |         211 |    262934620795 |         7044730 |      1246135275 |     58576612710 |                   7907840 |        214 |   759101288715 |         934780 |     3547202120 |    41712168190 |
| /var/lib/mysql/isucon2/stock.ibd | wait/io/file/innodb/innodb_data_file |       140132153361152 |        310 |   273430299835 |        3560095 |      882033075 |     9891016520 |          0 |              0 |              0 |              0 |              0 |                        0 |         239 |     12590424770 |         8717170 |        52679550 |       827383095 |                  15532032 |         71 |   260839875065 |        3560095 |     3673800900 |     9891016520 |
+----------------------------------+--------------------------------------+-----------------------+------------+----------------+----------------+----------------+----------------+------------+----------------+----------------+----------------+----------------+--------------------------+-------------+-----------------+-----------------+-----------------+-----------------+---------------------------+------------+----------------+----------------+----------------+----------------+
3 rows in set (0.00 sec)

mysql> SELECT * FROM file_summary_by_instance WHERE count_star <> 0 ORDER BY sum_timer_wait DESC LIMIT 1\G
*************************** 1. row ***************************
                FILE_NAME: /var/lib/mysql/ibdata1
               EVENT_NAME: wait/io/file/innodb/innodb_data_file
    OBJECT_INSTANCE_BEGIN: 140132153275264
               COUNT_STAR: 819
           SUM_TIMER_WAIT: 1604593676840
           MIN_TIMER_WAIT: 2331560
           AVG_TIMER_WAIT: 1959210715
           MAX_TIMER_WAIT: 1191383874065
               COUNT_READ: 157
           SUM_TIMER_READ: 3398451980
           MIN_TIMER_READ: 3504655
           AVG_TIMER_READ: 21645855
           MAX_TIMER_READ: 896338905
 SUM_NUMBER_OF_BYTES_READ: 4636672
              COUNT_WRITE: 626
          SUM_TIMER_WRITE: 181296946215
          MIN_TIMER_WRITE: 7489790
          AVG_TIMER_WRITE: 289611630
          MAX_TIMER_WRITE: 20881438270
SUM_NUMBER_OF_BYTES_WRITE: 88735744
               COUNT_MISC: 36
           SUM_TIMER_MISC: 1419898278645
           MIN_TIMER_MISC: 2331560
           AVG_TIMER_MISC: 39441618755
           MAX_TIMER_MISC: 1191383874065
1 row in set (0.00 sec)

こっちはファイル名まで見られるのでいくらか良い感じ。更新が集中しているテーブルとか見られる。グラフ化したい。


* objects_summary_global_by_type

mysql> SELECT * FROM objects_summary_global_by_type WHERE count_star <> 0 ORDER BY sum_timer_wait DESC LIMIT 3;
+-------------+---------------+---------------+------------+----------------+----------------+----------------+----------------+
| OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME   | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
+-------------+---------------+---------------+------------+----------------+----------------+----------------+----------------+
| TABLE       | isucon2       | stock         |   29755167 | 25975000162265 |          38885 |         872795 |    60737987310 |
| TABLE       | isucon2       | order_request |        343 |  2256830278395 |         177870 |     6579680030 |  1355498746525 |
| TABLE       | isucon2       | artist        |       3653 |   139255591860 |          25795 |       38120775 |    14495216505 |
+-------------+---------------+---------------+------------+----------------+----------------+----------------+----------------+
3 rows in set (0.00 sec)

mysql> SELECT * FROM objects_summary_global_by_type WHERE count_star <> 0 ORDER BY sum_timer_wait DESC LIMIT 1\G
*************************** 1. row ***************************
   OBJECT_TYPE: TABLE
 OBJECT_SCHEMA: isucon2
   OBJECT_NAME: stock
    COUNT_STAR: 29755167
SUM_TIMER_WAIT: 25975000162265
MIN_TIMER_WAIT: 38885
AVG_TIMER_WAIT: 872795
MAX_TIMER_WAIT: 60737987310
1 row in set (0.00 sec)

こっちはファイルに触れる触れないに関わらずテーブル単位で待ちが発生した回数と時間の累計。
バッファプールだけで完結するSELECTならundoのためにibdata1とib_logfileに触ることはあっても.ibdファイルには触らないだろうから、とかそんなところが違うんだと思う。


* table_io_waits_summary_by_index_usage
* table_io_waits_summary_by_table

mysql> SELECT * FROM table_io_waits_summary_by_index_usage WHERE count_star <> 0 ORDER BY sum_timer_wait DESC LIMIT 3;
+-------------+---------------+---------------+----------------+------------+----------------+----------------+----------------+----------------+------------+----------------+----------------+----------------+----------------+-------------+-----------------+-----------------+-----------------+-----------------+-------------+-----------------+-----------------+-----------------+-----------------+--------------+------------------+------------------+------------------+------------------+--------------+------------------+------------------+------------------+------------------+--------------+------------------+------------------+------------------+------------------+
| OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME   | INDEX_NAME     | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT | COUNT_READ | SUM_TIMER_READ | MIN_TIMER_READ | AVG_TIMER_READ | MAX_TIMER_READ | COUNT_WRITE | SUM_TIMER_WRITE | MIN_TIMER_WRITE | AVG_TIMER_WRITE | MAX_TIMER_WRITE | COUNT_FETCH | SUM_TIMER_FETCH | MIN_TIMER_FETCH | AVG_TIMER_FETCH | MAX_TIMER_FETCH | COUNT_INSERT | SUM_TIMER_INSERT | MIN_TIMER_INSERT | AVG_TIMER_INSERT | MAX_TIMER_INSERT | COUNT_UPDATE | SUM_TIMER_UPDATE | MIN_TIMER_UPDATE | AVG_TIMER_UPDATE | MAX_TIMER_UPDATE | COUNT_DELETE | SUM_TIMER_DELETE | MIN_TIMER_DELETE | AVG_TIMER_DELETE | MAX_TIMER_DELETE |
+-------------+---------------+---------------+----------------+------------+----------------+----------------+----------------+----------------+------------+----------------+----------------+----------------+----------------+-------------+-----------------+-----------------+-----------------+-----------------+-------------+-----------------+-----------------+-----------------+-----------------+--------------+------------------+------------------+------------------+------------------+--------------+------------------+------------------+------------------+------------------+--------------+------------------+------------------+------------------+------------------+
| TABLE       | isucon2       | stock         | NULL           |   23155059 | 15405691875035 |          51590 |         665280 |    60737987310 |   23073139 | 14505802679445 |          51590 |         628320 |    29693793745 |       81920 |    899889195590 |         3240930 |        10984820 |     60737987310 |    23073139 |  14505802679445 |           51590 |          628320 |     29693793745 |        81920 |     899889195590 |          3240930 |         10984820 |      60737987310 |            0 |                0 |                0 |                0 |                0 |            0 |                0 |                0 |                0 |                0 |
| TABLE       | isucon2       | stock         | variation_seat |    6596170 | 10556789714240 |          48125 |        1600060 |    35806416030 |    6596170 | 10556789714240 |          48125 |        1600060 |    35806416030 |           0 |               0 |               0 |               0 |               0 |     6596170 |  10556789714240 |           48125 |         1600060 |     35806416030 |            0 |                0 |                0 |                0 |                0 |            0 |                0 |                0 |                0 |                0 |            0 |                0 |                0 |                0 |                0 |
| TABLE       | isucon2       | order_request | NULL           |         94 |  2256572540145 |       24644620 |    24006090570 |  1355498746525 |          0 |              0 |              0 |              0 |              0 |          94 |   2256572540145 |        24644620 |     24006090570 |   1355498746525 |           0 |               0 |               0 |               0 |               0 |           94 |    2256572540145 |         24644620 |      24006090570 |    1355498746525 |            0 |                0 |                0 |                0 |                0 |            0 |                0 |                0 |                0 |                0 |
+-------------+---------------+---------------+----------------+------------+----------------+----------------+----------------+----------------+------------+----------------+----------------+----------------+----------------+-------------+-----------------+-----------------+-----------------+-----------------+-------------+-----------------+-----------------+-----------------+-----------------+--------------+------------------+------------------+------------------+------------------+--------------+------------------+------------------+------------------+------------------+--------------+------------------+------------------+------------------+------------------+
3 rows in set (0.00 sec)

mysql> SELECT * FROM table_io_waits_summary_by_index_usage WHERE count_star <> 0 ORDER BY sum_timer_wait DESC LIMIT 1\G
*************************** 1. row ***************************
     OBJECT_TYPE: TABLE
   OBJECT_SCHEMA: isucon2
     OBJECT_NAME: stock
      INDEX_NAME: NULL
      COUNT_STAR: 23155059
  SUM_TIMER_WAIT: 15405691875035
  MIN_TIMER_WAIT: 51590
  AVG_TIMER_WAIT: 665280
  MAX_TIMER_WAIT: 60737987310
      COUNT_READ: 23073139
  SUM_TIMER_READ: 14505802679445
  MIN_TIMER_READ: 51590
  AVG_TIMER_READ: 628320
  MAX_TIMER_READ: 29693793745
     COUNT_WRITE: 81920
 SUM_TIMER_WRITE: 899889195590
 MIN_TIMER_WRITE: 3240930
 AVG_TIMER_WRITE: 10984820
 MAX_TIMER_WRITE: 60737987310
     COUNT_FETCH: 23073139
 SUM_TIMER_FETCH: 14505802679445
 MIN_TIMER_FETCH: 51590
 AVG_TIMER_FETCH: 628320
 MAX_TIMER_FETCH: 29693793745
    COUNT_INSERT: 81920
SUM_TIMER_INSERT: 899889195590
MIN_TIMER_INSERT: 3240930
AVG_TIMER_INSERT: 10984820
MAX_TIMER_INSERT: 60737987310
    COUNT_UPDATE: 0
SUM_TIMER_UPDATE: 0
MIN_TIMER_UPDATE: 0
AVG_TIMER_UPDATE: 0
MAX_TIMER_UPDATE: 0
    COUNT_DELETE: 0
SUM_TIMER_DELETE: 0
MIN_TIMER_DELETE: 0
AVG_TIMER_DELETE: 0
MAX_TIMER_DELETE: 0
1 row in set (0.01 sec)

更に細かく、インデックス単位でのWAIT, READ, WRITE, FETCH, INSERT, UPDATE, DELETE(table_io_waits_summary_by_tableの方はテーブル単位)
INDEX_NAME = 'NULL'ってWITH ROLLUP的な感じで合算なのかと思ったけどどうもそうではなさげ。。なんだろう。
使われてないインデックス(writeばっかりでfetchが少ないとかになるのかな)とか算出するsysスキーマがあったような気がする。これ使ってるのかな。


* table_lock_waits_summary_by_table

mysql> SELECT * FROM table_lock_waits_summary_by_table WHERE count_star <> 0 ORDER BY sum_timer_wait DESC LIMIT 3;
+-------------+---------------+-------------+------------+----------------+----------------+----------------+----------------+------------+----------------+----------------+----------------+----------------+-------------+-----------------+-----------------+-----------------+-----------------+-------------------+-----------------------+-----------------------+-----------------------+-----------------------+------------------------------+----------------------------------+----------------------------------+----------------------------------+----------------------------------+--------------------------+------------------------------+------------------------------+------------------------------+------------------------------+----------------------+--------------------------+--------------------------+--------------------------+--------------------------+---------------------+-------------------------+-------------------------+-------------------------+-------------------------+-------------------------+-----------------------------+-----------------------------+-----------------------------+-----------------------------+-------------------------------+-----------------------------------+-----------------------------------+-----------------------------------+-----------------------------------+---------------------+-------------------------+-------------------------+-------------------------+-------------------------+--------------------------+------------------------------+------------------------------+------------------------------+------------------------------+--------------------+------------------------+------------------------+------------------------+------------------------+----------------------+--------------------------+--------------------------+--------------------------+--------------------------+
| OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT | COUNT_READ | SUM_TIMER_READ | MIN_TIMER_READ | AVG_TIMER_READ | MAX_TIMER_READ | COUNT_WRITE | SUM_TIMER_WRITE | MIN_TIMER_WRITE | AVG_TIMER_WRITE | MAX_TIMER_WRITE | COUNT_READ_NORMAL | SUM_TIMER_READ_NORMAL | MIN_TIMER_READ_NORMAL | AVG_TIMER_READ_NORMAL | MAX_TIMER_READ_NORMAL | COUNT_READ_WITH_SHARED_LOCKS | SUM_TIMER_READ_WITH_SHARED_LOCKS | MIN_TIMER_READ_WITH_SHARED_LOCKS | AVG_TIMER_READ_WITH_SHARED_LOCKS | MAX_TIMER_READ_WITH_SHARED_LOCKS | COUNT_READ_HIGH_PRIORITY | SUM_TIMER_READ_HIGH_PRIORITY | MIN_TIMER_READ_HIGH_PRIORITY | AVG_TIMER_READ_HIGH_PRIORITY | MAX_TIMER_READ_HIGH_PRIORITY | COUNT_READ_NO_INSERT | SUM_TIMER_READ_NO_INSERT | MIN_TIMER_READ_NO_INSERT | AVG_TIMER_READ_NO_INSERT | MAX_TIMER_READ_NO_INSERT | COUNT_READ_EXTERNAL | SUM_TIMER_READ_EXTERNAL | MIN_TIMER_READ_EXTERNAL | AVG_TIMER_READ_EXTERNAL | MAX_TIMER_READ_EXTERNAL | COUNT_WRITE_ALLOW_WRITE | SUM_TIMER_WRITE_ALLOW_WRITE | MIN_TIMER_WRITE_ALLOW_WRITE | AVG_TIMER_WRITE_ALLOW_WRITE | MAX_TIMER_WRITE_ALLOW_WRITE | COUNT_WRITE_CONCURRENT_INSERT | SUM_TIMER_WRITE_CONCURRENT_INSERT | MIN_TIMER_WRITE_CONCURRENT_INSERT | AVG_TIMER_WRITE_CONCURRENT_INSERT | MAX_TIMER_WRITE_CONCURRENT_INSERT | COUNT_WRITE_DELAYED | SUM_TIMER_WRITE_DELAYED | MIN_TIMER_WRITE_DELAYED | AVG_TIMER_WRITE_DELAYED | MAX_TIMER_WRITE_DELAYED | COUNT_WRITE_LOW_PRIORITY | SUM_TIMER_WRITE_LOW_PRIORITY | MIN_TIMER_WRITE_LOW_PRIORITY | AVG_TIMER_WRITE_LOW_PRIORITY | MAX_TIMER_WRITE_LOW_PRIORITY | COUNT_WRITE_NORMAL | SUM_TIMER_WRITE_NORMAL | MIN_TIMER_WRITE_NORMAL | AVG_TIMER_WRITE_NORMAL | MAX_TIMER_WRITE_NORMAL | COUNT_WRITE_EXTERNAL | SUM_TIMER_WRITE_EXTERNAL | MIN_TIMER_WRITE_EXTERNAL | AVG_TIMER_WRITE_EXTERNAL | MAX_TIMER_WRITE_EXTERNAL |
+-------------+---------------+-------------+------------+----------------+----------------+----------------+----------------+------------+----------------+----------------+----------------+----------------+-------------+-----------------+-----------------+-----------------+-----------------+-------------------+-----------------------+-----------------------+-----------------------+-----------------------+------------------------------+----------------------------------+----------------------------------+----------------------------------+----------------------------------+--------------------------+------------------------------+------------------------------+------------------------------+------------------------------+----------------------+--------------------------+--------------------------+--------------------------+--------------------------+---------------------+-------------------------+-------------------------+-------------------------+-------------------------+-------------------------+-----------------------------+-----------------------------+-----------------------------+-----------------------------+-------------------------------+-----------------------------------+-----------------------------------+-----------------------------------+-----------------------------------+---------------------+-------------------------+-------------------------+-------------------------+-------------------------+--------------------------+------------------------------+------------------------------+------------------------------+------------------------------+--------------------+------------------------+------------------------+------------------------+------------------------+----------------------+--------------------------+--------------------------+--------------------------+--------------------------+
| TABLE       | isucon2       | stock       |       3844 |     1580755330 |          38885 |         411180 |       84922530 |       3612 |     1451608235 |          38885 |         401555 |       84922530 |         232 |       129147095 |          192885 |          556325 |         9873325 |              1806 |             503861820 |                 48125 |                278740 |              84922530 |                            0 |                                0 |                                0 |                                0 |                                0 |                        0 |                            0 |                            0 |                            0 |                            0 |                    0 |                        0 |                        0 |                        0 |                        0 |                1806 |               947746415 |                   38885 |                  524755 |                13140050 |                     114 |                    40675635 |                      192885 |                      356510 |                     1143450 |                             0 |                                 0 |                                 0 |                                 0 |                                 0 |                   0 |                       0 |                       0 |                       0 |                       0 |                        0 |                            0 |                            0 |                            0 |                            0 |                  2 |                1497265 |                 525525 |                 748440 |                 971740 |                  116 |                 86974195 |                   418110 |                   749595 |                  9873325 |
| TABLE       | isucon2       | variation   |       2260 |      722340080 |          58905 |         319550 |        9551850 |       2216 |      705739265 |          58905 |         318395 |        9551850 |          44 |        16600815 |          180180 |          376915 |          656040 |              1108 |             360249120 |                114345 |                324940 |               9551850 |                            0 |                                0 |                                0 |                                0 |                                0 |                        0 |                            0 |                            0 |                            0 |                            0 |                    0 |                        0 |                        0 |                        0 |                        0 |                1108 |               345490145 |                   58905 |                  311465 |                 1170785 |                      20 |                     5014625 |                      180180 |                      250635 |                      358050 |                             0 |                                 0 |                                 0 |                                 0 |                                 0 |                   0 |                       0 |                       0 |                       0 |                       0 |                        0 |                            0 |                            0 |                            0 |                            0 |                  2 |                 860860 |                 338030 |                 430430 |                 522830 |                   22 |                 10725330 |                   423885 |                   487410 |                   656040 |
| TABLE       | isucon2       | artist      |       2236 |      466900280 |          25795 |         208670 |        3642485 |       2224 |      455622090 |          25795 |         204820 |        3642485 |          12 |        11278190 |          210595 |          939785 |         2962960 |              1112 |             224735280 |                 44660 |                201740 |               1176560 |                            0 |                                0 |                                0 |                                0 |                                0 |                        0 |                            0 |                            0 |                            0 |                            0 |                    0 |                        0 |                        0 |                        0 |                        0 |                1112 |               230886810 |                   25795 |                  207515 |                 3642485 |                       4 |                     2527140 |                      210595 |                      631785 |                     1158850 |                             0 |                                 0 |                                 0 |                                 0 |                                 0 |                   0 |                       0 |                       0 |                       0 |                       0 |                        0 |                            0 |                            0 |                            0 |                            0 |                  2 |                1629705 |                 699545 |                 814660 |                 930160 |                    6 |                  7121345 |                   438130 |                  1186570 |                  2962960 |
+-------------+---------------+-------------+------------+----------------+----------------+----------------+----------------+------------+----------------+----------------+----------------+----------------+-------------+-----------------+-----------------+-----------------+-----------------+-------------------+-----------------------+-----------------------+-----------------------+-----------------------+------------------------------+----------------------------------+----------------------------------+----------------------------------+----------------------------------+--------------------------+------------------------------+------------------------------+------------------------------+------------------------------+----------------------+--------------------------+--------------------------+--------------------------+--------------------------+---------------------+-------------------------+-------------------------+-------------------------+-------------------------+-------------------------+-----------------------------+-----------------------------+-----------------------------+-----------------------------+-------------------------------+-----------------------------------+-----------------------------------+-----------------------------------+-----------------------------------+---------------------+-------------------------+-------------------------+-------------------------+-------------------------+--------------------------+------------------------------+------------------------------+------------------------------+------------------------------+--------------------+------------------------+------------------------+------------------------+------------------------+----------------------+--------------------------+--------------------------+--------------------------+--------------------------+
3 rows in set (0.00 sec)

mysql> SELECT * FROM table_lock_waits_summary_by_table WHERE count_star <> 0 ORDER BY sum_timer_wait DESC LIMIT 1\G
*************************** 1. row ***************************
                      OBJECT_TYPE: TABLE
                    OBJECT_SCHEMA: isucon2
                      OBJECT_NAME: stock
                       COUNT_STAR: 3844
                   SUM_TIMER_WAIT: 1580755330
                   MIN_TIMER_WAIT: 38885
                   AVG_TIMER_WAIT: 411180
                   MAX_TIMER_WAIT: 84922530
                       COUNT_READ: 3612
                   SUM_TIMER_READ: 1451608235
                   MIN_TIMER_READ: 38885
                   AVG_TIMER_READ: 401555
                   MAX_TIMER_READ: 84922530
                      COUNT_WRITE: 232
                  SUM_TIMER_WRITE: 129147095
                  MIN_TIMER_WRITE: 192885
                  AVG_TIMER_WRITE: 556325
                  MAX_TIMER_WRITE: 9873325
                COUNT_READ_NORMAL: 1806
            SUM_TIMER_READ_NORMAL: 503861820
            MIN_TIMER_READ_NORMAL: 48125
            AVG_TIMER_READ_NORMAL: 278740
            MAX_TIMER_READ_NORMAL: 84922530
     COUNT_READ_WITH_SHARED_LOCKS: 0
 SUM_TIMER_READ_WITH_SHARED_LOCKS: 0
 MIN_TIMER_READ_WITH_SHARED_LOCKS: 0
 AVG_TIMER_READ_WITH_SHARED_LOCKS: 0
 MAX_TIMER_READ_WITH_SHARED_LOCKS: 0
         COUNT_READ_HIGH_PRIORITY: 0
     SUM_TIMER_READ_HIGH_PRIORITY: 0
     MIN_TIMER_READ_HIGH_PRIORITY: 0
     AVG_TIMER_READ_HIGH_PRIORITY: 0
     MAX_TIMER_READ_HIGH_PRIORITY: 0
             COUNT_READ_NO_INSERT: 0
         SUM_TIMER_READ_NO_INSERT: 0
         MIN_TIMER_READ_NO_INSERT: 0
         AVG_TIMER_READ_NO_INSERT: 0
         MAX_TIMER_READ_NO_INSERT: 0
              COUNT_READ_EXTERNAL: 1806
          SUM_TIMER_READ_EXTERNAL: 947746415
          MIN_TIMER_READ_EXTERNAL: 38885
          AVG_TIMER_READ_EXTERNAL: 524755
          MAX_TIMER_READ_EXTERNAL: 13140050
          COUNT_WRITE_ALLOW_WRITE: 114
      SUM_TIMER_WRITE_ALLOW_WRITE: 40675635
      MIN_TIMER_WRITE_ALLOW_WRITE: 192885
      AVG_TIMER_WRITE_ALLOW_WRITE: 356510
      MAX_TIMER_WRITE_ALLOW_WRITE: 1143450
    COUNT_WRITE_CONCURRENT_INSERT: 0
SUM_TIMER_WRITE_CONCURRENT_INSERT: 0
MIN_TIMER_WRITE_CONCURRENT_INSERT: 0
AVG_TIMER_WRITE_CONCURRENT_INSERT: 0
MAX_TIMER_WRITE_CONCURRENT_INSERT: 0
              COUNT_WRITE_DELAYED: 0
          SUM_TIMER_WRITE_DELAYED: 0
          MIN_TIMER_WRITE_DELAYED: 0
          AVG_TIMER_WRITE_DELAYED: 0
          MAX_TIMER_WRITE_DELAYED: 0
         COUNT_WRITE_LOW_PRIORITY: 0
     SUM_TIMER_WRITE_LOW_PRIORITY: 0
     MIN_TIMER_WRITE_LOW_PRIORITY: 0
     AVG_TIMER_WRITE_LOW_PRIORITY: 0
     MAX_TIMER_WRITE_LOW_PRIORITY: 0
               COUNT_WRITE_NORMAL: 2
           SUM_TIMER_WRITE_NORMAL: 1497265
           MIN_TIMER_WRITE_NORMAL: 525525
           AVG_TIMER_WRITE_NORMAL: 748440
           MAX_TIMER_WRITE_NORMAL: 971740
             COUNT_WRITE_EXTERNAL: 116
         SUM_TIMER_WRITE_EXTERNAL: 86974195
         MIN_TIMER_WRITE_EXTERNAL: 418110
         AVG_TIMER_WRITE_EXTERNAL: 749595
         MAX_TIMER_WRITE_EXTERNAL: 9873325
1 row in set (0.00 sec)

テーブルごとのロック待ちの統計…なんだけど、i_sで確認するステータスとは違う変数名がならんでてどこがどう対応してるんだろう。
ブロックしてるクエリーとかも見られるi_sの方が優秀かなここは。


もういちど。

events_statements_summary_by_digest マジ優秀。

【2015/03/31 17:28】
フルパワーにしたらこんな感じだった。
日々の覚書: MySQLのperformance_schemaをフルパワーにするとどんな情報が見られるのか

2015年3月27日金曜日

MySQL 5.7でやっと(?)1テーブル複数トリガーが仕掛けられるようになった

As of MySQL 5.7.2, it is possible to define multiple triggers for a given table that have the same trigger event and action time. For example, you cannot have two BEFORE UPDATE triggers for a table. By default, triggers that have the same trigger event and action time activate in the order they were created. To affect trigger order, specify a trigger_order clause that indicates FOLLOWS or PRECEDES and the name of an existing trigger that also has the same trigger event and action time. With FOLLOWS, the new trigger activates after the existing trigger. With PRECEDES, the new trigger activates before the existing trigger.
MySQL :: MySQL 5.7 Reference Manual :: 13.1.16 CREATE TRIGGER Syntax


試してみよう。

5.6のフツーの動作は

mysql56> CREATE TRIGGER before_insert_1 BEFORE INSERT ON t1 FOR EACH ROW INSERT INTO t2 SET num = NEW.num, val = NEW.val;
Query OK, 0 rows affected (0.02 sec)

mysql56> INSERT INTO t1 VALUES (1, 'one');
Query OK, 1 row affected (0.03 sec)

mysql56> SELECT * FROM t1;
+-----+------+
| num | val  |
+-----+------+
|   1 | one  |
+-----+------+
1 row in set (0.00 sec)

mysql56> SELECT * FROM t2;
+-----+------+
| num | val  |
+-----+------+
|   1 | one  |
+-----+------+
1 row in set (0.00 sec)

mysql56> CREATE TRIGGER before_insert_2 BEFORE INSERT ON t1 FOR EACH ROW UPDATE t2 SET val = '残念だったな' WHERE num = NEW.num;
ERROR 1235 (42000): This version of MySQL doesn't yet support 'multiple triggers with the same action time and event for one table'

もちろんこう。


5.7.6だと

mysql57> CREATE TRIGGER before_insert_1 BEFORE INSERT ON t1 FOR EACH ROW INSERT INTO t2 SET num = NEW.num, val = NEW.val;
Query OK, 0 rows affected (0.01 sec)

mysql57> INSERT INTO t1 VALUES (1, 'one');
Query OK, 1 row affected (0.01 sec)

mysql57> SELECT * FROM t1;
+-----+------+
| num | val  |
+-----+------+
|   1 | one  |
+-----+------+
1 row in set (0.00 sec)

mysql57> SELECT * FROM t2;
+-----+------+
| num | val  |
+-----+------+
|   1 | one  |
+-----+------+
1 row in set (0.00 sec)

mysql57> CREATE TRIGGER before_insert_2 BEFORE INSERT ON t1 FOR EACH ROW UPDATE t2 SET val = '残念だったな' WHERE num = NEW.num;
Query OK, 0 rows affected (0.01 sec)

mysql57> INSERT INTO t1 VALUES (2, 'two');
Query OK, 1 row affected (0.04 sec)

mysql57> SELECT * FROM t1;
+-----+------+
| num | val  |
+-----+------+
|   1 | one  |
|   2 | two  |
+-----+------+
2 rows in set (0.00 sec)

mysql57> SELECT * FROM t2;
+-----+--------------------+
| num | val                |
+-----+--------------------+
|   1 | one                |
|   2 | 残念だったな       |
+-----+--------------------+
2 rows in set (0.00 sec)

mysql57> SHOW TRIGGERS\G
*************************** 1. row ***************************
             Trigger: before_insert_1
               Event: INSERT
               Table: t1
           Statement: INSERT INTO t2 SET num = NEW.num, val = NEW.val
              Timing: BEFORE
             Created: 2015-03-27 02:53:23.66
            sql_mode: ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ENGINE_SUBSTITUTION
             Definer: root@localhost
character_set_client: utf8
collation_connection: utf8_general_ci
  Database Collation: utf8_general_ci
*************************** 2. row ***************************
             Trigger: before_insert_2
               Event: INSERT
               Table: t1
           Statement: UPDATE t2 SET val = '残念だったな' WHERE num = NEW.num
              Timing: BEFORE
             Created: 2015-03-27 02:53:47.85
            sql_mode: ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ENGINE_SUBSTITUTION
             Definer: root@localhost
character_set_client: utf8
collation_connection: utf8_general_ci
  Database Collation: utf8_general_ci
2 rows in set (0.00 sec)

当たり前だけど張れた。順番の制御は、FOR EACH ROWのあとにPRECEDESまたはFOLLOWSで既存のトリガーを指定する(省略時は最後のトリガーの更に次に追加されるのかな)


mysql57> DROP TRIGGER before_insert_2;
Query OK, 0 rows affected (0.01 sec)

mysql57> CREATE TRIGGER before_insert_3 BEFORE INSERT ON t1 FOR EACH ROW PRECEDES before_insert_1 UPDATE t2 SET val = '残念だったな' WHERE num = NEW.num;
Query OK, 0 rows affected (0.02 sec)

mysql57> INSERT INTO t1 VALUES (3, 'three');
Query OK, 1 row affected (0.00 sec)

mysql57> SELECT * FROM t1;
+-----+-------+
| num | val   |
+-----+-------+
|   1 | one   |
|   2 | two   |
|   3 | three |
+-----+-------+
3 rows in set (0.00 sec)

mysql57> SELECT * FROM t2;
+-----+--------------------+
| num | val                |
+-----+--------------------+
|   1 | one                |
|   2 | 残念だったな       |
|   3 | three              |
+-----+--------------------+
3 rows in set (0.00 sec)

mysql57> SHOW TRIGGERS\G
*************************** 1. row ***************************
             Trigger: before_insert_3
               Event: INSERT
               Table: t1
           Statement: UPDATE t2 SET val = '残念だったな' WHERE num = NEW.num
              Timing: BEFORE
             Created: 2015-03-27 02:56:45.90
            sql_mode: ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ENGINE_SUBSTITUTION
             Definer: root@localhost
character_set_client: utf8
collation_connection: utf8_general_ci
  Database Collation: utf8_general_ci
*************************** 2. row ***************************
             Trigger: before_insert_1
               Event: INSERT
               Table: t1
           Statement: INSERT INTO t2 SET num = NEW.num, val = NEW.val
              Timing: BEFORE
             Created: 2015-03-27 02:53:23.66
            sql_mode: ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ENGINE_SUBSTITUTION
             Definer: root@localhost
character_set_client: utf8
collation_connection: utf8_general_ci
  Database Collation: utf8_general_ci
2 rows in set (0.00 sec)

UPDATE t2が先に実行されるのでt2にレコードがなくて空ぶって、そのあとINSERT INTO t2でコピーされる。
ちょっと便利になるかも知れない。