日々の覚書: 3月 2013

2013/03/27

pt-duplicate-key-checkerが快適

Percona Toolkitのひとつpt-duplicate-key-checker。
名前の通り、重複したインデックスをチェックしてくれる。

$ pt-duplicate-key-checker S=/usr/mysql/5.5.30/data/mysql.sock,u=tpcc,p=xxxx --database=tpcc

# ########################################################################
# tpcc.stock
# ########################################################################

# s_w_id is a left-prefix of PRIMARY
# Key definitions:
# KEY `s_w_id` (`s_w_id`),
# PRIMARY KEY (`s_w_id`,`s_i_id`),
# Column types:
# `s_w_id` smallint(6) not null
# `s_i_id` int(11) not null
# To remove this duplicate index, execute:
ALTER TABLE `tpcc`.`stock` DROP INDEX `s_w_id`;

# ########################################################################
# Summary of indexes
# ########################################################################

# Size Duplicate Indexes 2
# Total Duplicate Indexes 1
# Total Indexes 25

　⇒わざと作った重複インデックスを検出させてみる。
　　複合キーの左側に含まれてる不要なインデックスをリストして
　　イラナイキーをDROPするためのALTER TABLEステートメントも一緒に出してくれる。

DSNの指定の部分は、
S=ソケットファイル,
h=ホスト名,
u=ユーザー名,
p=パスワード,
P=ポート
各パラメータはコンマ区切り。

--databases 対象DB1,対象DB2
これも複数指定するときはコンマ区切り。
対象を指定しない場合は全DBが対象。

その他諸々は本家のドキュメントを…って、ドキュメントはまだ2.2になってないのね。
http://www.percona.com/doc/percona-toolkit/2.1/pt-duplicate-key-checker.html

これで重複インデックスを一網打尽にしたい。

2013/03/25

tail -fしながらファイルをリネームすると追いかけてくれなくなる理由

tail -Fの存在は知っているんですが、
なんで追いかけてくれないのかが気になって途中まで調べた。

$ ls -l error.log*
-rw-rw---- 1 mysql mysql 5954 3月 25 14:44 2013 error.log

$ tail -f error.log
..

2013-03-25 14:44:50 11326 [Note] /usr/mysql/5.6.10/bin/mysqld: ready for connections.
Version: '5.6.10-log' socket: '/usr/mysql/5.6.10/data/mysql.sock' port: 64056 Source distribution

$ mv -i error.log error.log.1

$ ls -l error.log*

-rw-rw---- 1 mysql mysql 5954 3月 25 14:44 2013 error.log.1

$ mysqladmin debug

　⇒mysqladmin debugで(情報として有益かどうかはともかく)mysqldの標準エラー出力にごにょごにょ吐く。

$ ls -l error.log*

-rw-rw---- 1 mysql mysql 8756 3月 25 14:46 2013 error.log.1

　⇒ちゃんとリネーム後のファイルに出力される。

　　tail -f の方はよく知られている様に出力されない。

$ mysql -e "FLUSH ERROR LOGS"

$ ls -l error.log*

-rw-rw---- 1 mysql mysql 0 3月 25 14:50 2013 error.log

-rw-rw---- 1 mysql mysql 8756 3月 25 14:46 2013 error.log.1

$ mysqladmin debug

$ ls -l error.log*

-rw-rw---- 1 mysql mysql 2803 3月 25 14:50 2013 error.log

-rw-rw---- 1 mysql mysql 8756 3月 25 14:46 2013 error.log.1

　⇒もちろん新しい方に出力される。

なーんか、tail -f が追いかけない話が有名なので、この動作は直感的じゃないけど、

fdはiノード向いてるわけで、どちらかというとtail -f がフツウじゃない気がする。

# lsof -p `pidof mysqld` | grep error.log

mysqld 11326 mysql 1w REG 253,0 2803 1186510 /usr/mysql/5.6.10/data/error.log

mysqld 11326 mysql 2w REG 253,0 2803 1186510 /usr/mysql/5.6.10/data/error.log

# lsof -p `pidof tail` | grep error.log

tail 11455 root 3r REG 253,0 2803 1186510 /usr/mysql/5.6.10/data/error.log

当然同じiノード(1186519)向いてる。

# mv -i /usr/mysql/5.6.10/data/error.log /usr/mysql/5.6.10/data/error.log.2

# lsof -p `pidof mysqld` | grep error.log

mysqld 11326 mysql 1w REG 253,0 2803 1186510 /usr/mysql/5.6.10/data/error.log.2

mysqld 11326 mysql 2w REG 253,0 2803 1186510 /usr/mysql/5.6.10/data/error.log.2

# lsof -p `pidof tail` | grep error.log

tail 11455 root 3r REG 253,0 2803 1186510 /usr/mysql/5.6.10/data/error.log.2

　⇒Σ(ﾟдﾟlll) あれtailの方はfd閉じちゃうかと思った。

src/tail.cにもぐってみる。

main関数の先頭近くにsleep_intervalとかいうのを発見。こんなのあるんだ。

そのまま下に行くと、 #if HAVE_INOTIFYの中でtail_forever_inotify関数を、

外でtail_forever関数を呼び出しているのを発見。

この辺の違いな気がするのでHAVE_INOTIFYの内側をめっきり消してコンパイルしようかと思ったけど、

#if HAVE_INOTIFYの中でif (!disable_inotify && ..) となってるので、どこかで何か出来そうな予感も。

で、disable_inotifyを探したらDISABLE_INOTIFY_OPTIONに出会って、

最終的に

static struct option const long_options[] ={.. {"-disable-inotify", no_argument, NULL, DISABLE_INOTIFY_OPTION}, /* do not document */..}

こんなところに出会った。

ドキュメントに書くなって書いてある。書いてない、じゃなくて書くな、なの。。

$ tail -f ---disable-inotify error.log

　⇒ハイフン3つ。

$ mv -i error.log error.log.3

$ mysqladmin debug

これでtail -f も途切れず出力された。

あとは、inotify側がファイル名の変更でfdを解放するのを調べればQ.E.D.

…たぶん調べない。

【2013/03/25 16:37】

@yoku0825 途中で、inotifyがionotifyになってるけど、これ全部inotifyが正しい？　面倒くさがらずにtailのソース読めと言われそうな気もするがw
— ISHII Hidenoriさん (@h141gm) 2013年3月25日

ありがとうございまーすorz

Chiba.pm #2に行って誰得XtraDB Clusterの話をしてきた

行ってきました。
前回はちゃんと千葉県民だったんですが、今回は東京都民としての出場です（？）

http://atnd.org/events/36981

Introduction to XtraDB Cluster from yoku0825

Perl Mongersにも関わらずDBの話してきました。

なんか今回はDBネタが多かったですね。

前回がLTデビューだったので、なんかChiba.pmが実家みたいな感じです。
なにしゃべろうかなー、まあ取り敢えずMySQLでいっかー、みたいな（Perlしゃべれ）

懇親会でMySQLのエラーログ見せてもらって肥大化の原因見つけたり、
やっぱりChiba.pmはゆるふわでした。
なんとかカジュアルの罠もないのでみんな安心して参加できますよ！

Chiba.pm #2 ハッシュタグまとめ

2013/03/19

MyNA 2013/03 行ってきました

MySQL Nippon Associate、日本MySQLユーザー会こと`まいな'に行ってきました。
ひらがなで書くとなんか人の名前みたいな感じがしますね。
教育テレビに出てそう。お料理かぐるぐるどっかーん的な何か。

http://atnd.org/events/37387

MySQL clients from yoku0825

前を平塚さん、後ろを奥野さんに固められた恐怖の布陣、
「こりゃあ変なこと話したらマサカリが㌧でくる…ッ！」と思って飛び道具的なネタになりました。
あの二人に挟まれて5.6サーバーの新機能とか話せませんのでmysql_install_dbとか、mysql_config_editor、mysqlbinlogの新機能とか変更になった動作を紹介してます。

なお、当日は色々ありすぎて（雲の上～な人たちに会って舞い上がっていたのが大半）
あんまり憶えてないんですが、

今日のショッキング。第三位、木下さんが全然寡黙じゃなかった。第二位、奥野さんでも上手くいかないことはあった。第一位、木村明治さんにおっさん言われたw
— ts. yokuさん (@yoku0825) 2013年3月15日

でした。

取り敢えず一番の目的だった「平塚さんにお目にかかる！」は果たせました。
「MyNAで話さない？」と声をかけて下さった RKajiyamaさんありがとうございました！
ブログ書いたりツイートしてみるもんですね。正直びっくり。

次は Chiba.pm #2 でXtraDB Clusterについて(誰得で)話してきます。

2013/03/15

バイナリログやスローログを見やすくするワンライナー

バイナリログやスローログを遡って更新履歴をチェックしたりする時に(個人的に)面倒なのが、
`こいつらはSQLステートメントの改行を反映するし、インデントもしっかり記録してくれる'こと。

grep -v "INSERT INTO t1"とかやっても、"VALUES"の手前で改行してインデントするような
小綺麗に書かれたコードだと上手く引っ掛けにくい。
個人的にはインデントあった方が好きだけど、大量のログを見る時には不向き。

なので1分で考えたワンライナー。

perl -e '$/="#"; while(<>) { s/[ \n\r\t]{2,}/ /g; print $_;}' | egrep -iv '^SET (TIMESTAMP|.+session\.|INSERT_ID)|^/\*|^BEGIN|^COMMIT|^DELIMITER' | grep '^[^#]' -B1

これで連続する改行なり空白なりを全部まとめて単独のスペース文字に変換できる。
grepでもawkでも自由自在。

ついでに、いつものSET TIMESTAMPやBEGIN, COMMITを弾いた上で、
コメント行以外の行とその直前のコメント行を引っこ抜いてくる。
スローログだったら-B2にすると良いかと。

…小汚いですが、1分で思い付いたのはこれくらいでした。

2013/03/13

ついに#mysql50#lost+foundデータベースとさよならするのだ

$ ls -l lost+found/

合計 108

-rw-rw---- 1 mysql mysql 8554 3月 13 20:06 2013 t1.frm

-rw-rw---- 1 mysql mysql 98304 3月 13 20:06 2013 t1.ibd

それどころか、消せる。

mysql> DROP DATABASE `#mysql50#lost+found`;

Query OK, 1 row affected (0.07 sec)

$ ls -l lost+found/

ls: cannot access lost+found/: そのようなファイルやディレクトリはありません

ちなみに複数のディレクトリをIgnoreする時には、1行に1個ずつ書く必要があります。

$ vi /etc/my.cnf

[mysqld]

ignore-db-dir = lost+found

ignore-db-dir = .ssh

消せるのはちょっと面白かった。

2013/03/08

MySQL5.6が勝手にsql_modeを書き換えてくれる話

MySQL5.6のmysql_install_dbは大幅に変更が加えられていて、
権限データベースを作るついでに、basedirにすごく役に立たないmy.cnfを作ってくれる。
　⇒ MySQL5.6.8でrpmインストール時に変更になったこと

5.6.10だとscripts/mysql_install_dbの427～450行あたり。

このbasedir/my.cnf、ほとんどコメントアウトされていてホント何の役にも立たない上に、
sql_modeだけ指定されている。

sql_mode=NO_ENGINE_SUBSTITUTION,STRICT_TRANS_TABLES

さて問題です。
/etc/my.cnfにsql_modeを指定していて(たとえばPIPES_AS_CONCAT）、
このbasedir/my.cnfを削除しなかった場合。。。

　上　書　き　さ　れ　ま　す　。

　⇒ my.cnfのパラメータ優先順位

ええ。
昨日まで通っていた INSERT INTO (..) VALUES ('hoge' || 'fuga', ..)が蹴られるんですよ。

勝手に作った設定ファイルで自分でやった設定をオーバーライドしないで欲しいんだホントに。

【2013/03/11 13:31】
勝手に作らないで--random-password的にオプションにして欲しい、と
Feature Requestにしようと思ったら既にあった。

http://bugs.mysql.com/bug.php?id=68416

【2013/03/12 10:50】
よく読んだら全然違ったのでふぃーちゃーりくえすとを上げた。。

2013/03/06

InnoDB Monitorの仲間たち（InnoDBエンジン本体のアレ）

InnoDBストレージエンジンには InnoDB Monitor という機能があって、
だいたい`SHOW ENGINE INNODB STATUSの結果をエラーログファイルに定期的に吐き出してくれる'というイメージがある。

mysql> CREATE TABLE innodb_monitor ( hoge int );
$ tail -f error.log
=====================================
130306 10:09:30 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
..

----------------------------
END OF INNODB MONITOR OUTPUT
============================

そのまんまですね。

これなら正直、mysql -e "SHOW ENGINE INNODB STATUS\\G"を定期的に取れば良いかくらいなんですが、
InnoDB Monitorには他の種類もあって、

・InnoDBテーブルスペースモニター
mysql> CREATE TABLE innodb_tablespace_monitor ( hoge int );
$ tail -f error.log

================================================
130306 10:12:46 INNODB TABLESPACE MONITOR OUTPUT
================================================
FILE SPACE INFO: id 0
size 16000, free limit 15424, free extents 214
not full frag extents 9: used pages 256, full frag extents 2
first seg id not used 3546
SEGMENT id 1 space 0; page 2; res 928 used 778; full ext 11
fragm pages 32; free extents 0; not full extents 3: pages 42
SEGMENT id 2 space 0; page 2; res 1 used 1; full ext 0
fragm pages 1; free extents 0; not full extents 0: pages 0
SEGMENT id 3 space 0; page 2; res 1 used 1; full ext 0
fragm pages 1; free extents 0; not full extents 0: pages 0
..

SEGMENT id 3531 space 0; page 12105; res 1 used 1; full ext 0
fragm pages 1; free extents 0; not full extents 0: pages 0
NUMBER of file segments: 323
Validating tablespace
Validation ok
---------------------------------------
END OF INNODB TABLESPACE MONITOR OUTPUT
=======================================

Σ(ﾟдﾟlll) すげえいっぱい！
ibdata1がどんな風に使われているのかをなんとなく見られそう。
（使い道は思い浮かばない）

・InnoDBテーブルモニター
mysql> CREATE TABLE innodb_table_monitor ( hoge int );
$ tail -f error.log

===========================================
130306 10:09:50 INNODB TABLE MONITOR OUTPUT
===========================================
..

--------------------------------------
TABLE: name tpcc/warehouse, id 27, flags 1, columns 12, indexes 1, appr.rows 0
COLUMNS: w_id: DATA_INT DATA_BINARY_TYPE DATA_NOT_NULL len 2; w_name: DATA_VARMYSQL len 30; w_street_1: DATA_VARMYSQL len 60
; w_street_2: DATA_VARMYSQL len 60; w_city: DATA_VARMYSQL len 60; w_state: DATA_MYSQL len 6; w_zip: DATA_MYSQL len 27; w_tax:
DATA_FIXBINARY DATA_BINARY_TYPE len 2; w_ytd: DATA_FIXBINARY DATA_BINARY_TYPE len 6; DB_ROW_ID: DATA_SYS prtype 256 len 6; DB_
TRX_ID: DATA_SYS prtype 257 len 6; DB_ROLL_PTR: DATA_SYS prtype 258 len 7;
INDEX: name PRIMARY, id 41, fields 1/11, uniq 1, type 3
root page 3, appr.key vals 0, leaf pages 1, size pages 1
FIELDS: w_id DB_TRX_ID DB_ROLL_PTR w_name w_street_1 w_street_2 w_city w_state w_zip w_tax w_ytd
FOREIGN KEY CONSTRAINT tpcc/fkey_district_1: tpcc/district ( d_w_id )
REFERENCES tpcc/warehouse ( w_id )
FOREIGN KEY CONSTRAINT tpcc/fkey_stock_1: tpcc/stock ( s_w_id )
REFERENCES tpcc/warehouse ( w_id )
-----------------------------------
END OF INNODB TABLE MONITOR OUTPUT
==================================

Σ(ﾟдﾟlll) 何に使おうかイマイチ思いつかないけどすげえいっぱい。
トランザクションをかけてあれば、トランザクションIDに対応するロールバックポインターの情報も見られるのかしら。

・InnoDBロックモニター
mysql> CREATE TABLE innodb_lock_monitor ( hoge int );
$ tail -f error.log

=====================================
2013-03-06 10:46:14 7f22fa2b1700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 221 srv_active, 0 srv_shutdown, 564473 srv_idle
srv_master_thread log flush and writes: 564694
..

----------------------------
END OF INNODB MONITOR OUTPUT
============================

(　ﾟдﾟ) ・・・
　
(つд⊂)ｺﾞｼｺﾞｼ

(；ﾟдﾟ) ・・・
　
(つд⊂)ｺﾞｼｺﾞｼｺﾞｼ
　　_, ._
（；ﾟ Дﾟ） …innodb_monitorと違わなくね？

と思ったら、ちゃんと違いました。

..

------------
TRANSACTIONS
------------
Trx id counter 13943
Purge done for trx's n:o < 13939 undo n:o < 0 state: running but idle
History list length 559
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 13941, ACTIVE 158 sec
2 lock struct(s), heap size 376, 13 row lock(s)
MySQL thread id 825, OS thread handle 0x7f22fcb12700, query id 3809 localhost root cleaning up
TABLE LOCK table `d1`.`t12` trx id 13941 lock mode IX
RECORD LOCKS space id 41 page no 3 n bits 80 index `GEN_CLUST_INDEX` of table `d1`.`t12` trx id 13941 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;

Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 6; hex 00000000030c; asc ;;
1: len 6; hex 000000003655; asc 6U;;
2: len 7; hex ac000006310110; asc 1 ;;
3: len 3; hex 814000; asc @ ;;

Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 6; hex 00000000030d; asc ;;
1: len 6; hex 000000003655; asc 6U;;
2: len 7; hex ac00000631011e; asc 1 ;;
3: len 3; hex 814040; asc @@;;

Record lock, heap no 4 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 6; hex 00000000030e; asc ;;
1: len 6; hex 000000003655; asc 6U;;
2: len 7; hex ac00000631012c; asc 1 ,;;
3: len 3; hex 814080; asc @ ;;
..

TRANSACTIONSに出力されるレコードロックの情報がすごく多い。
LATEST DEADLOCKセクションに出てくるのと同じレベルで出力してる気がする。
これ頑張って解析したら色々捗りそうだけど、時間対効果はきっとすごく低いよなぁ。。

しかし出力が紛らわしい。innodb_monitorの出力と混じってるからログがごりごり流れるし。
ソースコード(storage/innobase/row/row0mysql.cc)読んでも、

} else if (STR_EQ(table_name, table_name_len,
S_innodb_lock_monitor)) {
srv_print_innodb_monitor = TRUE;
srv_print_innodb_lock_monitor = TRUE;
os_event_set(lock_sys->timeout_event);

両方出力させてるっぽいことは判るんだけど、それが正しいのかどうかよく判らなかった。。
5.5.8までさかのぼってコンパイルしてこの動作で良いのか調べてみたり。

ところでマニュアルのいわく。

The InnoDB Lock Monitor is like the standard Monitor but also provides extensive lock information.

http://dev.mysql.com/doc/refman/5.6/en/innodb-monitors.html

orz

ちなみにこれ、5.0の時代からある古い機能なんですね。
http://dev.mysql.com/doc/refman/5.0/en/innodb-monitors.html
innodb_monitor以外は知らなかった。

【2013/03/27 12:00】
ごめんなさい、これ、作ったinnodb*_monitorテーブルをドロップするまで、
数十秒ごとにエラーログにこの出力結果を吐き出し続けます。

止めるには
mysql> DROP TABLE <作ったテーブル>;
です。
すっかり書くの忘れてた。。