2013年4月30日火曜日

MySQL 5.5.30のmysqldumpに当てるパッチ書いた

前々からパッチは書いてあって(本番環境で使ってる)公開するする詐欺だったんだけれども、
著作権周りのごたごたが社内でやっと落ち着いたので今度こそ公開。

修正している内容の主なものは、
"--master-data=2と--dump-slave=2を同時に指定できるようにする"
です。

何に使うかというと、こんな構成で


・バイナリログのバックアップはlog-slave-updatesでスレーブにとってあるので、
・マスターのDISKが消し飛んでもバイナリログからロールフォワードを保証するためには
 --master-dataと--dump-slaveの両方のポジション情報が必要で、
・でも2回もmysqldumpは取りたくなくて
・あと—dump-slaveにはFLUSH TABLES WITH READ LOCKをかけてくれないバグがあったり
・要らないSTOP SLAVEをかける(--single-transactionと一緒に使うなら不要)バグがあったりする
のでどうしたもんかなー

って思ったときに使います。

需要なさげ。でも折角なので公開。GPLv2です。

https://gist.github.com/yoku0825/5487061



--master-dataと--dump-slaveを(0以外で)両方していした場合、
--master-data=2 --dump-slave=2として解釈されます(両方のバイナリログのポジションがコメントアウトで出力される)

あとはdump-slave使ってる時にFLUSH TABLES WITH READ LOCKが必要なのにやってないバグ(#65035)

dump-slaveでsingle-transactionならSTOP SQL_THREADしなくても良いのにやってるバグ(同じく#65035)
古いSET OPTION構文が残っているバグ(#67507)
を修正しています。

会社の名前で公開できるかどうかモメた挙句、
著作権をワタシ個人に譲渡する && 公開は個人としてやる、ということになりました。

公開するなではなく、便宜を図ってくれた会社に感謝します(*-人-)

2013年4月24日水曜日

MySQL5.6 ALTER TABLE中のtmpdirのファイル

なんかうれし恥ずかし状態になっているので頑張って調べてます。

もともとの話は、MySQL5.6で巨大テーブルのALTER TABLE中に
tmpdirに何かI/Oがあるせいで遅くなってる、という話で、
MySQLでデータ領域をシステムと別diskにするならtmpdirも設定した方がいい - 酒日記 はてな支店

というか、でも、

Σ(゚д゚lll) 結論出てるじゃないですか!?


はい、調べます。

1) ALTER TABLEが走るとALGORITHM = INPLACEかどうか、INPLACEでALTER TABLEできるかどうかの判定が走る(sql/sql_table.cc:mysql_inplace_alter_table)

2) もろもろの関数を経て、InnoDBのOnline ALTER TABLEにたどりつく(storage/innobase/handler/handler0alter.cc:ha_innobase::inplace_alter_table)

3) Online ALTER TABLE用のtemporary merge fileが作られる。DDL中の更新差分をココに閉じ込めて、後からテンポラリテーブルにマージする動き。内部的にはMySQL内共通のテンポラリファイル作る関数を、ファイル名の先頭"ib"で呼んでる。(storage/innobase/row/row0log.cc:row_log_table_open)

4) DDL中の更新差分は、InnoDBのINSERT, UPDATE, DELETE用APIの中でOnline ALTER TABLE中かどうかを判定して、
   フラグが立ってたらさっきのテンポラリファイルにデータを突っ込む関数が呼ばれる(storage/innobase/row/row0ins.ccとか)


if (err == DB_SUCCESS && dict_index_is_online_ddl(index)) {
                        row_log_table_insert(rec, index, offsets);
                }

こんなかんじ。

5) ALTER TABLE中の面倒は(storage/innobase/row/row0log.cc:row_log_online_op)が見ているぽくて、

if (byte_offset + srv_sort_buf_size >= srv_online_max_size) {
                        goto write_failed;
                }

ファイルの末尾+sort_buffer_size(ソートバッファサイズごとに処理してるぽいので、
次の1回分くらいしか残りがない、という感じ?)がinnodb_online_alter_log_max_sizeに達するとエラーで抜けるようになってる。

6) ALTER TABLEの終了後に、テンポラリファイルからINSERT, UPDATE, DELETEの差分をマージする(storage/innobase/row/row0log.cc:row_log_table_apply_*)

こんな感じでしょうか。5) はちょっと自信無い…。


ざっくりですが楽しませていただきました。

ネタをくれた@fujiwaraさん、
鬼振りしてくれた@kamipoさん、@kenjiskywalkerさん、@sh2ndさん、@oranieさん、
美味しゅうございました。ありがとうございます。

2013年4月23日火曜日

InnoDBのロックは行ロックじゃなくてインデックス行ロックだからね、という例

また使う気がするのでメモ。

mysql1> CREATE DATABASE d1;
mysql1> USE d1;
mysql1> CREATE TABLE t1 (num SERIAL, val VARCHAR(32), KEY (val(1))) ENGINE = InnoDB;
mysql1> INSERT INTO t1 VALUES (1, 'one'), (2, 'two'), (3, 'three');
mysql1> START TRANSACTION;
mysql1> SELECT * FROM t1 WHERE val = 'two' FOR UPDATE;

mysql2> SELECT * FROM t1 WHERE num = 3 LOCK IN SHARE MODE;

valの先頭1文字でインデックスになっているので、"[t]wo"のロックは"[t]hree"も一緒にロックする。
よってnum = 3のロックは不可能。

2013年4月17日水曜日

information_schema.INNODB_BUFFER_PAGEのACCESS_TIMEが何か変な件

取り敢えずBugsにも上げたんですけど、エスパーさんでないと伝わらない気がしています。

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


MySQL 5.6.2, 5.5.28, 5.1.66に搭載された新しいinformation_schema、INNODB_BUFFER_PAGEとINNODB_BUFFER_PAGE_LRU。
⇒ http://yoku0825.blogspot.jp/2013/02/informationschemainnodbbufferpage.html

これの中身をちょこちょこ確認していたところ、どうにも`ACCESS_TIME`が納得のいく値にならないことに気付いた。


mysql56> DESC INNODB_BUFFER_PAGE;
+---------------------+---------------------+------+-----+---------+-------+
| Field               | Type                | Null | Key | Default | Extra |
+---------------------+---------------------+------+-----+---------+-------+
| POOL_ID             | bigint(21) unsigned | NO   |     | 0       |       |
| BLOCK_ID            | bigint(21) unsigned | NO   |     | 0       |       |
| SPACE               | bigint(21) unsigned | NO   |     | 0       |       |
| PAGE_NUMBER         | bigint(21) unsigned | NO   |     | 0       |       |
| PAGE_TYPE           | varchar(64)         | YES  |     | NULL    |       |
| FLUSH_TYPE          | bigint(21) unsigned | NO   |     | 0       |       |
| FIX_COUNT           | bigint(21) unsigned | NO   |     | 0       |       |
| IS_HASHED           | varchar(3)          | YES  |     | NULL    |       |
| NEWEST_MODIFICATION | bigint(21) unsigned | NO   |     | 0       |       |
| OLDEST_MODIFICATION | bigint(21) unsigned | NO   |     | 0       |       |
| ACCESS_TIME         | bigint(21) unsigned | NO   |     | 0       |       |
| TABLE_NAME          | varchar(1024)       | YES  |     | NULL    |       |
| INDEX_NAME          | varchar(1024)       | YES  |     | NULL    |       |
| NUMBER_RECORDS      | bigint(21) unsigned | NO   |     | 0       |       |
| DATA_SIZE           | bigint(21) unsigned | NO   |     | 0       |       |
| COMPRESSED_SIZE     | bigint(21) unsigned | NO   |     | 0       |       |
| PAGE_STATE          | varchar(64)         | YES  |     | NULL    |       |
| IO_FIX              | varchar(64)         | YES  |     | NULL    |       |
| IS_OLD              | varchar(3)          | YES  |     | NULL    |       |
| FREE_PAGE_CLOCK     | bigint(21) unsigned | NO   |     | 0       |       |
+---------------------+---------------------+------+-----+---------+-------+
20 rows in set (0.00 sec)



mysql56> SELECT TABLE_NAME, INDEX_NAME, ACCESS_TIME FROM INNODB_BUFFER_PAGE WHERE TABLE_NAME = '`d4`.`t1`';
+------------+------------+-------------+
| TABLE_NAME | INDEX_NAME | ACCESS_TIME |
+------------+------------+-------------+
| `d4`.`t1`  | num        |   386123651 |
+------------+------------+-------------+
1 row in set (0.02 sec)
UNIXTIMEとしては桁が1個おかしい。
NEWEST_MODIFICATION, OLDEST_MODIFICATIONはLSNが記載されるんだけど、それでもない。
EPOCH(1970/01/01 00:00:00)からの経過秒数じゃなくて起動してからの秒数かなとか思っても、
やっぱり計算が全然合わない。

取り敢えず、storage/innobase/handler/i_s.ccなんてあつらえ向きのものがあるので探してみる。
そこからコソコソたどっていくと、storage/innobase/include/buf0buf.icの中で
bpage->access_time = ut_time_ms(); とやっているのを発見。

ut_time_ms()は現在時刻をミリ秒単位でunsigned longで返す関数らしい(storage/innobase/ut/ut0ut.cc)ので、
ページを読み込んだタイミングのUNIXTIME * 1000くらいの値になりそうなもんだが、
ただでさえ桁がおかしいのに更に計算が合わなくなる。

( ´-`).oO(ここで3日くらい悩んだ)

まあステップ実行かな! とgdbを仕掛けて、i_sにアクセスするところでブレーク。

Breakpoint 3, i_s_innodb_buffer_page_get_info (bpage=0x7f04aa1c3000, pool_id=0, pos=0, page_info=0x7f0484076f78)
    at /home/yoku0825/mysql-5.6.10/storage/innobase/handler/i_s.cc:5076
5076    {

 (gdb) p *bpage
$4 = {space = 261, offset = 240, state = 3, flush_type = 0, io_fix = 0, buf_fix_count = 0, buf_pool_index = 0, zip = {
    data = 0x0, m_end = 0, m_nonempty = 0, n_blobs = 0, ssize = 0}, hash = 0x0, list = {prev = 0x7f04aa1c3180,
    next = 0x7f04aa1eaf00}, newest_modification = 0, oldest_modification = 0, LRU = {prev = 0x7f04aa1c3180, next = 0x0},
  old = 1, freed_page_clock = 1507, access_time = 41213048}

 
(gdb) p ut_time_ms()
$2 = 1366183980583
ウェーイ、この時点でaccess_timeは変な値になってるし、ut_time_ms()はちゃんとUNIXTIME * 1000ぽいスケールの戻り値。。

なんでそう思ったのかよく判らないけれど、何故かaccess_timeの型を調べる気になって叩いてみると、

(gdb) whatis bpage->access_time
type = unsigned int
unsigned int…32bit INTかYO!!

mysql56> create table d4.t1 ( num serial ); select unix_timestamp(now(3)), (unix_timestamp(now(3)) * 1000) & ( pow(2, 32) - 1);
Query OK, 0 rows affected (0.04 sec)

 +------------------------+-----------------------------------------------------+
| unix_timestamp(now(3)) | (unix_timestamp(now(3)) * 1000) & ( pow(2, 32) - 1) |
+------------------------+-----------------------------------------------------+
|         1366185723.810 |                                           386123682 |
+------------------------+-----------------------------------------------------+
1 row in set (0.01 sec)

 mysql56> SELECT TABLE_NAME, INDEX_NAME, ACCESS_TIME FROM INNODB_BUFFER_PAGE WHERE TABLE_NAME = '`d4`.`t1`';
+------------+------------+-------------+
| TABLE_NAME | INDEX_NAME | ACCESS_TIME |
+------------+------------+-------------+
| `d4`.`t1`  | num        |   386123651 |
+------------+------------+-------------+
1 row in set (0.02 sec)

現在のUNIXTIME(5.6なのでミリ秒まで取れるのだ) * 1000の下32bitだけ取り出すと、おお、大体合う。
あとからよく見てみると、あっちゃこっちゃで unsigned access_time で定義されているのを見つける。

あー、すっきり。
でも英語下手すぎてだめぽ。。


2013年4月16日火曜日

MySQL 5.5.28とMariaDB 5.5.28aのmysqldumpを読み比べてみる(binlog_snapshot_%変数というのがある)

--master-dataのオプションの説明にこんなことが書いてある。

on servers before MariaDB 5.3 this will still take a global read lock for a short time at the beginning of the dump;

MariaDB 5.3以降だとFLUSH TABLE WITH READ LOCKしないのか?
 ⇒しない。START TRANSACTION WITH CONSISTENT SNAPSHOTの時に
  binlog_snapshot_fileセッション変数とbinlog_snapshot_positionセッション変数に
  値を自動的に格納してくれる。すご。
  https://kb.askmonty.org/en/enhancements-for-start-transaction-with-consistent-snapshot/
  ⇒対応していないバージョンの場合、オプション解析中にFLUSH TABLES WITH READ LOCKが
   必要な分岐に流れる。



527c531,532
< static const char *load_default_groups[]= { "mysqldump","client",0 };
---
> static const char *load_default_groups[]=
> { "mysqldump", "client", "client-server", "client-mariadb", 0 };

オリジナルのmysqldumpが各種my.cnfから読み取るのは[client]セクションと[mysqldump]セクション、
MariaDB版はそれに加えて[client-server]セクションと[client-mariadb]セクションも読む。

opt_no_create_infoがついてない時は、テーブルDROPして作り直してるんだからUNIQUE_CHECKS=0要らないだロって言ってる。

check_consistent_binlog_pos関数の追加。
START TRANSACTION WITH CONSISTENT SNAPSHOTの時に
binlog_snapshot_fileセッション変数とbinlog_snapshot_positionセッション変数格納した値をパースしてるぽい。
中身は"SHOW STATUS LIKE 'binlog_snapshot_%'"でアクセスしてるだけ。

このセッション変数が取れなかったら"SHOW MASTER DATA"する。
セッション変数が取れるかどうかはオプションを解析している間に一度チェックするので、
そこでダメならFLUSH TABLES WITH READ LOCKする分岐に流れる。


他には、
・ちょこちょこリソースの解放やってる
・my_printf_error関数使わずにfprintfでstderrに書いてる
くらいな感じ。

dump-slaveで要らないSTOP SLAVEが入るやつとかはマージされてないのか。。
まさか違うと思わなかったので結構楽しめた。ごちそうさまでした。

2013年4月8日月曜日

REPLACE INTOが実はINSERT + DELETEだったと思ったら、結局DELETE + INSERTだった

REPLACE INTOが実はINSERT + DELETEだった(INSERTが先で後から消す)の続き。

REPLACE INTOは「DELETE + INSERT(その行を消してからもう一度書く)」だと今まで思っていたけれど、
実は「INSERT + DELETE(行を突っ込んでから古い行を消す)」な動きっぽいというはなし。

そっちが先なんだびっくりー、という感じで書いたのですが、
色々手落ちがあったので後から調べたことをメモ。


1) その結果だと時間が一緒だから、「DELETEトリガーがINSERTトリガーより先」というのは断言できない。順番は必ずしも保証されないから。
⇒TRIGGERの中身をSYSDATE(6)に書き換えてみました。

mysql56> delimiter //

 mysql56> CREATE TRIGGER tr1
    -> BEFORE INSERT ON t2
    -> FOR EACH ROW BEGIN
    ->  INSERT INTO t3(dateval, trg, val) VALUES (SYSDATE(6), 'before insert', new.num);
    -> END//
Query OK, 0 rows affected (0.01 sec)

 mysql56> CREATE TRIGGER tr2
    -> BEFORE DELETE ON t2
    -> FOR EACH ROW BEGIN
    ->  INSERT INTO t3(dateval, trg, val) VALUES (SYSDATE(6), 'before delete', old.num);
    -> END//
Query OK, 0 rows affected (0.01 sec)

 mysql56> delimiter ;

 
mysql56> REPLACE INTO t2 VALUES (1);
Query OK, 1 row affected (0.01 sec)

 mysql56> REPLACE INTO t2 VALUES (1);
Query OK, 2 rows affected (0.03 sec)

 mysql56> SELECT * FROM t3;
+----------------------------+---------------+------+
| dateval                    | trg           | val  |
+----------------------------+---------------+------+
| 2013-04-08 10:41:00.414920 | before insert |    1 |
| 2013-04-08 10:41:01.249376 | before insert |    1 |
| 2013-04-08 10:41:01.249701 | before delete |    1 |
+----------------------------+---------------+------+
3 rows in set (0.00 sec)


綺麗に取れた。
DELETEトリガーの方がINSERTトリガーより後に来てる。

木村さんのブログを参考にさせていただきましたm(_"_)m
http://blog.kimuradb.com/?eid=877275

最初はSYSDATE(6)じゃなくてNOW(6)にしていたら、
NOW()の結果はキャッシュされるからマイクロ秒まで同じ値になっちゃって失敗してたりします。。orz



2) INSERTトリガーがDELETEトリガーより先に引かれていることとINSERTがDELETEより先に発生していることは同値ではない。
⇒データファイルを直接叩けるようにMyISAMエンジンにしてステップ実行。。

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

# od -c t2.MYD
0000000 003  \0 016 002  \0 376 001  \0  \0  \0  \0  \0  \0  \0 003   o
0000020   n   e  \0  \0
0000024

# gdb -p `pidof mysqld`

(gdb) b /home/yoku0825/mysql-5.6.10/sql/sql_insert.cc:1787
Breakpoint 1 at 0x6af7bc: file /home/yoku0825/mysql-5.6.10/sql/sql_insert.cc, line 1787.

取り敢えず前回目星をつけたwrite_record関数のDELETEトリガーを引く前のあたりにブレークポイントを入れる。

mysql56> replace into t2 values (1, 'two');

(gdb) c
Continuing.
[Switching to Thread 0x7f6c207d9700 (LWP 21484)]

Breakpoint 1, write_record (thd=0x43ab7c0, table=0x4414280, info=0x7f6c207d76f0, update=0x7f6c207d7670)
    at /home/yoku0825/mysql-5.6.10/sql/sql_insert.cc:1787
1787            if (last_uniq_key(table,key_nr) &&
(gdb) n
1808              if (table->triggers &&
(gdb)
1812              if ((error=table->file->ha_delete_row(table->record[1])))

od -cを叩きながらポチポチやってたら、ここで

# od -c t2.MYD
0000000  \0  \0  \0 024 377 377 377 377 377 377 377 377 377 377 377 377
0000020 377 377 377 377
0000024

Σ(゚д゚lll) 先に消えた!


(gdb)
1618        while ((error=table->file->ha_write_row(table->record[0])))

# od -c t2.MYD
0000000 003  \0 016 002  \0 376 001  \0  \0  \0  \0  \0  \0  \0 003   t
0000020   w   o  \0  \0
0000024

Σ(゚д゚lll) ここで書いた!


orz

whileでエラー(Err:121 Duplicate key on write or update)があったらすっ飛ばして先にha_delete_rowに行ってからha_write_rowに来るんですね。。

あー、もう、なんだかなーorz

REPLACE INTOは行を消してから新しい行を書く。
けど、トリガーはINSERTトリガーが先に引かれてDELETEトリガーが後から引かれる。

でした。
ちなみに、sql/sql_insert.ccの1787では既にINSERTトリガーは引かれてました。
確かに先頭近くで一度ha_write_rowしてるからそこで引いてるんだと思うですよ。


@meijik さん、@sakaik さん、ツッコミありがとうございましたm(_"_)m


【2013/04/08 12:38】
AFTERトリガーは入れ子になるですよ。

mysql56> select * from t3;
+----------------------------+---------------+------+
| dateval                    | trg           | val  |
+----------------------------+---------------+------+
| 2013-04-08 12:37:17.081148 | before insert |    1 |
| 2013-04-08 12:37:17.081350 | before delete |    1 |
| 2013-04-08 12:37:17.081412 | after delete  |    1 |
| 2013-04-08 12:37:17.081452 | after insert  |    1 |
+----------------------------+---------------+------+
4 rows in set (0.00 sec)

2013年4月2日火曜日

REPLACE INTOが実はINSERT + DELETEだった(INSERTが先で後から消す) 間違ってました。。

「INSERT .. ON DUPLICATE KEY UPDATE ..でクエリを投げているけど、99%くらいはUPDATEになっている」
「UPDATEを直接投げた方が速かったりする?」
「極端にパフォーマンス違うんだったら、UPDATEが転けてからINSERTする方式も考える」

とか聞かれたのでINSERT .. ON DUPLICATE KEY UPDATEについて調べてたんですが、
ソース読んでたら豆知識に出会ったのでメモ。

5.6.10のsql/sql_insert.ccの中でゴニョゴニョしている気配があるけど、write_record関数の中で

table->file->ha_write_row(table->record[0]してみる。
⇒何もないINSERTだとエラーになったらエラー。
⇒REPLACE INTO, INSERT .. ON DUPLICATE KEY UPDATEだと
それぞれHA_ERR_FOUND_DUPP_KEYを引っ掛けてハンドルしている。
最終的にはtable->file->ha_update_row(table->record[1], table->record[0])、
これはsql/sql_update.ccのmysql_update関数で呼んでいるのと同じ感じ。
…あれ。

REPLACE INTOの場合、この処理の`後に'DELETEのトリガー呼んでるように見えるぞ。。


mysql56> CREATE TRIGGER tr1 BEFORE INSERT ON t2 FOR EACH ROW BEGIN INSERT INTO t3(trg, val) VALUES ('before insert', new.num); END;//
Query OK, 0 rows affected (0.00 sec)

mysql56> CREATE TRIGGER tr2 BEFORE DELETE ON t2 FOR EACH ROW BEGIN INSERT INTO t3(trg, val) VALUES ('before delete', old.num); END;//
Query OK, 0 rows affected (0.01 sec)


BEFORE INSERTとBEFORE DELETEのトリガーを作ってみて

mysql56> INSERT INTO t2 VALUES (4, now());
Query OK, 1 row affected (0.01 sec)

mysql56> SELECT * FROM t3;
+---------------------+---------------+------+
| dateval             | trg           | val  |
+---------------------+---------------+------+
| 2013-04-02 15:49:25 | before insert | 4    |
+---------------------+---------------+------+
1 row in set (0.00 sec)

mysql56> REPLACE INTO t2 VALUES (4, now());
Query OK, 2 rows affected (0.01 sec)

mysql56> SELECT * FROM t3;
+---------------------+---------------+------+
| dateval             | trg           | val  |
+---------------------+---------------+------+
| 2013-04-02 15:49:25 | before insert | 4    |
| 2013-04-02 15:49:39 | before insert | 4    |
| 2013-04-02 15:49:39 | before delete | 4    |
+---------------------+---------------+------+
3 rows in set (0.00 sec)


大当たりー。
ソースコードにも、「DELETEトリガーがあったら、ユーザーは俺たちのチートに気付くだろうしNE☆」って書いてあった。

えーと、何の話でしたっけ。。


【2013/04/08 12:12】
@sakaik さんにツッコミをいただいたので丁寧に調べてみたら、

REPLACE INTOは行を消してから新しい行を書く。
けど、トリガーはINSERTトリガーが先に引かれてDELETEトリガーが後から引かれる。

でした。。申し訳ない。。orz

http://yoku0825.blogspot.jp/2013/04/replace-intoinsert-deletedelete-insert.html

@meijik さん、@sakaik さん、ツッコミありがとうございましたm(_"_)m