MySQLのCOMMIT時におけるfsyncの実行タイミング

バージョン5.6で"innodb_flush_log_at_trx_commit=1"の挙動が変わった的な話があったので、こっちで軽く調べ、さらに追加調査したので結果を書く。

目的と結論

目的

簡単に書くと、5.6でバイナリログのグループコミットが入ってREDOログとバイナリログの書込みに依存関係っぽいものがでてきたこと、およびfsyncの回数を減らした的なアナウンスや解説がポツポツあるので、具体的にどうなっているのか調べるのが目的。

結論

結論を先に書くと：

innodb_flush_log_at_trx_commit=1での基本的な挙動は変わらない。
- COMMIT毎にREDOログのwrite+fsync、バイナリログのwrite+fsyncがある。
変わったのは
- バイナリログの書込みがグループコミットになった
- REDOログとバイナリログの処理の後にtrx_commit_complate_for_mysql()でさらに実行されていたfsyncは(通常は)スキップ

ということで、これは間違ってんじゃないのという感じ*1。

実行したSQLは"BEGIN; INSERT INTO tbl VALUES(1);COMMIT;"、他のセッションはなし。COMMIT実行後をgdbでトレース。

ということで、他のトランザクションとの競合が一切ない場合の挙動なので、混み合ってくるとまた状況は変わるはず*2。そろそろMySQLプロパーの人がACIDのDについてきっちり解説すべきでないの、と思うけど*3。。。。

バージョン5.5まで

ルーティンのfsync実行

毎秒、あるスレッドがREDOログが書き込まれたがどうか見張っていて、REDOログ書込みがあれば次の流れでfsync()を実行する。

srv_sync_log_buffer_in_background()
	log_buffer_sync_in_backgroud()
		log_write_up_to()
			log_group_write_buf()
				fil_flush()
					os_file_fsync()
						fsync()

COMMIT時

(1)まずはREDOログの書込みとfsync()。

ha_commit_trans()
	trx_prepare_off_kernel()
		log_write_up_to()
			log_group_write_buf()
				fil_flush()
					os_file_fsync
						fsync()

(2)次、バイナリログの書込みとfsync()。

binlog_commit_flush_stmt_cache()
	binlog_commit_flush_trx_cache()
		my_sync()
			fsync()

(3)さらにtrx_commit_complate_for_mysqlでだめ押し

trx_commit_complete_for_mysql()
        trx_commit_complete_for_mysql()
		log_write_up_to()
			log_group_write_buf()
				fil_flush()
					os_file_fsync()
						fsync()

ということで、この場合は計３回fsync()を実行している。

最後のfsyncの意味はよく分からない。これが実行されるのはflush_log_laterフラグが立っているときで、これってREDOログのグループコミット用のはず。今回はサーバでたった一つのトランザクションしか走ってないので、そもそも何故これが実行されるのという素朴な疑問が。チェックしてスキップできそうな気もするのだが、そんなに簡単な話でもないのだろう。

バージョン5.6

バイナリログのグループコミットが入って、諸説入り乱れているので確認。

ルーティンのfsync実行

こちらは変わらず。

COMMIT時

(1)REDOログの書込み。innobase_handlertonのprepareでtrx_prepare_for_mysql()が起動。
とりあえずfsync()は実行している模様。よって「innodb_flush_log_at_trx_commit=1が0のように振る舞う」は間違い。

trx_prepare_for_mysql()
	trx_prepare()
		log_write_low()
			log_write_up_to()
				log_group_write_buf()
					fil_finish()
						os_file_fsync()
							fsync()

関数の起点が5.5と違うが、これは筆者がここにgdbのbreakpointを置いただけで、深い意味はない。

(2)次、バイナリログのグループコミット。BINLOG:ordered_commit()は次の３ステージに分れている。

ステージ1 = 準備
ステージ2 = バイナリログ書き込み
ステージ3 = REDOログ書込み = trx_commit_complete_for_mysql()の実行に相当する部分

ステージ２は次のとおり。

my_sync()
	fsync()

問題のステージ3はこちらの記事を参照。

結論だけいえばステージ3ではfsync()は実行しない。

よって、この場合のfsync()の実行は２回。

5.5の説明の末尾に「チェックすればスキップできそう」と書いたけど、(REDOログ、バイナリログともども)グループコミットが関るとかなり面倒なことになるのはわかる。どういう機構でこれだけ面倒なのかという点はまだ把握できていないが。

いずれにしてもREDOログの書込み+COMMIT時にはfsync()が呼ばれるようでよかった。

5.6で分かり難いのは

バイナリログの書込みがグループコミットBINLOG:ordered_commit()になった。
- trx_commit_complate_for_mysql()の実行がBINLOG:ordered_commit()に取り込まれた。
そのBINLOG:ordered_commit()は最初にHA_IGNORE_DURABILITY=trueとする。
そして、BINLOG:ordered_commit()のステージ3で呼ばれるtrx_commit_complate_for_mysql()の中で、HA_IGNORE_DURABILITY=trueの場合はfsyncをスキップする。
- HA_IGNORE_DURABILITYフラグが立っているとfsyncスキップ
- つまり、確実にfsyncスキップ
- それじゃあ、いままでのtrx_commit_complate_for_mysql()->fsync()の流れはなんだったの的な。。。
しかも(fsync自体は既に実行されてるのだが)、"HA_IGNORE_DURABILITY"なんていう名前の変数があるので、無駄な勘ぐりをしてしまう。