2019年1月29日火曜日

innodb_autoinc_lock_mode <> 0 でINSERT .. SELECT .. をかけた時にauto_incrementなカラムが歯抜けになる理由を調べてみる

TL;DR

  • innodb_autoinc_lock_mode が0の場合、ステートメントが始まってから終わるまでまるまるAUTOINC_LOCKで保護する -> 歯抜けが起きない
  • non 0 の場合、ステートメントが始まった時点でAUTOINC_LOCK -> (2^0 + 2^1 + 2^2 + ..) 個autoinc払い出し -> AUTOINC_LOCK解除 するので歯抜けが起きる

InnoDBのパラレルリードマスター @atsuizo さんがふと、







↓この現象が気になるっぽい
mysql57 2> DROP TABLE t1;
Query OK, 0 rows affected (0.01 sec)

mysql57 2> CREATE TABLE t1 (num int unsigned NOT NULL auto_increment PRIMARY KEY);
Query OK, 0 rows affected (0.01 sec)

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

mysql57 2> INSERT INTO t1 VALUES (0); -- 1が入るので次は2
Query OK, 1 row affected (0.01 sec)

mysql57 2> SHOW CREATE TABLE t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` int(10) unsigned NOT NULL AUTO_INCREMENT,
  PRIMARY KEY (`num`)
) ENGINE=InnoDB AUTO_INCREMENT=2 DEFAULT CHARSET=utf8mb4
1 row in set (0.00 sec)

mysql57 2> INSERT INTO t1 SELECT 0 FROM t1; -- 2が入るので次は3
Query OK, 1 row affected (0.00 sec)
Records: 1  Duplicates: 0  Warnings: 0

mysql57 2> SHOW CREATE TABLE t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` int(10) unsigned NOT NULL AUTO_INCREMENT,
  PRIMARY KEY (`num`)
) ENGINE=InnoDB AUTO_INCREMENT=3 DEFAULT CHARSET=utf8mb4
1 row in set (0.00 sec)

mysql57 2> INSERT INTO t1 SELECT 0 FROM t1; -- 3, 4が入るので次は5になってほしいんだけど
Query OK, 2 rows affected (0.00 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql57 2> SHOW CREATE TABLE t1\G -- 5を飛ばして6になっちゃう
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` int(10) unsigned NOT NULL AUTO_INCREMENT,
  PRIMARY KEY (`num`)
) ENGINE=InnoDB AUTO_INCREMENT=6 DEFAULT CHARSET=utf8mb4
1 row in set (0.00 sec)

mysql57 2> INSERT INTO t1 SELECT 0 FROM t1; -- 6, 7, 8, 9が入るので次は10になってほしいんだけど
Query OK, 4 rows affected (0.00 sec)
Records: 4  Duplicates: 0  Warnings: 0

mysql57 2> SHOW CREATE TABLE t1\G -- 13まで飛んじゃう
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` int(10) unsigned NOT NULL AUTO_INCREMENT,
  PRIMARY KEY (`num`)
) ENGINE=InnoDB AUTO_INCREMENT=13 DEFAULT CHARSET=utf8mb4
1 row in set (0.00 sec)

mysql57 2> SELECT * FROM t1;
+-----+
| num |
+-----+
|   1 |
|   2 |
|   3 |
|   4 | -- 5がない
|   6 |
|   7 |
|   8 |
|   9 | -- 次は13から始まる
+-----+
8 rows in set (0.00 sec)
という訳で調べてみた。
というかここのコメントに答えがあった。
(gdb) b ha_innobase::get_auto_increment
+b ha_innobase::get_auto_increment
Breakpoint 2 at 0xeff860: file /home/yoku0825/mysql-5.7.25/storage/innobase/handler/ha_innodb.cc, line 16700.
(gdb) c
+c
Continuing.

Breakpoint 2, ha_innobase::get_auto_increment (this=0x7fb570022740, offset=1, increment=1, nb_desired_values=1,
    first_value=0x7fb59812e230, nb_reserved_values=0x7fb59812e240)
    at /home/yoku0825/mysql-5.7.25/storage/innobase/handler/ha_innodb.cc:16700
16700   {
(gdb) c
+c
Continuing.

Breakpoint 2, ha_innobase::get_auto_increment (this=0x7fb570022740, offset=1, increment=1, nb_desired_values=2,
    first_value=0x7fb59812e230, nb_reserved_values=0x7fb59812e240)
    at /home/yoku0825/mysql-5.7.25/storage/innobase/handler/ha_innodb.cc:16700
16700   {
(gdb) c
+c
Continuing.

Breakpoint 2, ha_innobase::get_auto_increment (this=0x7fb570022740, offset=1, increment=1, nb_desired_values=4,
    first_value=0x7fb59812e230, nb_reserved_values=0x7fb59812e240)
    at /home/yoku0825/mysql-5.7.25/storage/innobase/handler/ha_innodb.cc:16700
16700   {
(gdb) c
+c
Continuing.

Breakpoint 2, ha_innobase::get_auto_increment (this=0x7fb570022740, offset=1, increment=1, nb_desired_values=8,
    first_value=0x7fb59812e230, nb_reserved_values=0x7fb59812e240)
    at /home/yoku0825/mysql-5.7.25/storage/innobase/handler/ha_innodb.cc:16700
16700   {
(gdb) c
+c
Continuing.
これがさっきの結果にもう一度 INSERT INTO t1 SELECT 0 FROM t1 で8行足した時のステップ実行。
最初のautoinc = 13から見て、
13 + (1) .. 1行 < 8行なのでもう一度
13 + (1 + 2) .. 3行 < 8行なので略
13 + (1 + 2 + 4) .. 7行 < 8行略
13 + (1 + 2 + 4 + 8) .. 15行 > 8行なので、ここまで払い出して終了
mysql57 3> SELECT * FROM t1;
+-----+
| num |
+-----+
|   1 |
|   2 |
|   3 |
|   4 |
|   6 |
|   7 |
|   8 |
|   9 |
|  13 |
|  14 |
|  15 |
|  16 |
|  17 |
|  18 |
|  19 |
|  20 |
+-----+
16 rows in set (0.00 sec)

mysql57 3> SHOW CREATE TABLE t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` int(10) unsigned NOT NULL AUTO_INCREMENT,
  PRIMARY KEY (`num`)
) ENGINE=InnoDB AUTO_INCREMENT=28 DEFAULT CHARSET=utf8mb4
1 row in set (0.01 sec)
という訳で、autoincを一気に払い出すのが (2^0 + 2^1 + 2^2 + ..) だから、歯抜けになるようでしたん。
じゃあなんで (2^0 + 2^1 + 2^2 + ..) で払い出すのかまではわからんですが。気になる人は、3に変えてみて性能検証とかしてみるといいんじゃないですかね…。。

2019年1月15日火曜日

とあるコアラのエラー考察(未完)

日々の覚書: とある豆腐のエラー考察(未完) の時のように、エラーログをもらう機会があったのでちょっと考察。




免責事項(?)ですが、俺はこのエラーの再現環境があるわけではないので、かなりの部分を推測に基づいて考察します。

もらったログの全文

2019-01-14T14:41:17.424422Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)
2019-01-14T14:41:17.424513Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)
2019-01-14T14:41:17.576511Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2019-01-14T14:41:17.578354Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.23-0ubuntu0.16.04.1-log) starting as process 6416 ...
2019-01-14T14:41:17.584305Z 0 [Note] InnoDB: PUNCH HOLE support available
2019-01-14T14:41:17.584354Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-01-14T14:41:17.584363Z 0 [Note] InnoDB: Uses event mutexes
2019-01-14T14:41:17.584369Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2019-01-14T14:41:17.584376Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
2019-01-14T14:41:17.584383Z 0 [Note] InnoDB: Using Linux native AIO
2019-01-14T14:41:17.584677Z 0 [Note] InnoDB: Number of pools: 1
2019-01-14T14:41:17.584824Z 0 [Note] InnoDB: Using CPU crc32 instructions
2019-01-14T14:41:17.586336Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2019-01-14T14:41:17.598369Z 0 [Note] InnoDB: Completed initialization of buffer pool
2019-01-14T14:41:17.600460Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-01-14T14:41:17.612757Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2019-01-14T14:41:17.613697Z 0 [ERROR] InnoDB: Ignoring the redo log due to missing MLOG_CHECKPOINT between the checkpoint 18543632753 and the end 18543632384.
2019-01-14T14:41:17.613721Z 0 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
2019-01-14T14:41:18.251987Z 0 [ERROR] Plugin 'InnoDB' init function returned error.
2019-01-14T14:41:18.252044Z 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2019-01-14T14:41:18.252071Z 0 [ERROR] Failed to initialize builtin plugins.
2019-01-14T14:41:18.252077Z 0 [ERROR] Aborting

2019-01-14T14:41:18.252096Z 0 [Note] Binlog end
2019-01-14T14:41:18.252166Z 0 [Note] Shutting down plugin 'MyISAM'
2019-01-14T14:41:18.252186Z 0 [Note] Shutting down plugin 'CSV'
2019-01-14T14:41:18.252691Z 0 [Note] /usr/sbin/mysqld: Shutdown complete
取り敢えず、スタートアップシーケンスの中のInnoDBサブシステムの起動で転けてるところまではわかる。
その手前が [ERROR] InnoDB: Ignoring the redo log due to missing MLOG_CHECKPOINT between the checkpoint 18543632753 and the end 18543632384. なので、これを吐きそうなところを探すと…あった。
4162                 if (!srv_read_only_mode
4163                     && group->scanned_lsn != checkpoint_lsn) {
4164                         ib::error() << "Ignoring the redo log due to missing"
4165                                 " MLOG_CHECKPOINT between the checkpoint "
4166                                 << checkpoint_lsn << " and the end "
4167                                 << group->scanned_lsn << ".";
4168                         if (srv_force_recovery < SRV_FORCE_NO_LOG_REDO) {
4169                                 log_mutex_exit();
4170                                 return(DB_ERROR);
4171                         }
4172                 }
recv_recovery_from_checkpoint_start の中で呼ばれていた。
どうやらというか、クラッシュリカバリーの中でログファイルをスキャンするあたりらしい。
srv_read_only_modeinnodb_read_only がセットされた時のフラグなので読み飛ばすとして、 group->scanned_lsn != checkpoint_lsn なのが気に入らないらしい。
4168行目で srv_force_recovery ( innodb_force_recoverySRV_FORCE_NO_LOG_REDO = 6 より小さければ return(DB_ERROR) でクラッシュリカバリーに失敗することもわかる。
scanned_lsn はクラッシュリカバリーの最中にログファイルを先頭から舐めた中で、validなログが書かれたところのバイト数っぽい。
実際は、ログブロックのヘッダーとに書かれたブロック番号の検査、ログブロックのチェックサム検査あたりをすり抜けたものだけが scanned_lsn に加算されるっぽい、詳しくは recv_scan_log_recs
それに対して checkpoint_lsn はというと、 recv_recovery_from_checkpoint_start のもうちょっと手前のあたりで
4076         buf = log_sys->checkpoint_buf;
4077
4078         checkpoint_lsn = mach_read_from_8(buf + LOG_CHECKPOINT_LSN);
4079         checkpoint_no = mach_read_from_8(buf + LOG_CHECKPOINT_NO);
この checkpoint_lsn はInnoDBログのヘッダに書かれた「次にクラッシュリカバリーを開始すべき位置」らしく、InnoDBが稼働中に(ファジーにしろシャープにしろ)チェックポイントを走らせた際に、チェックポイントが終わった時のLSN + αで上書きするっぽい。
とすると、 checkpoint_lsn = xxx32753group->scanned_lsn= xxx32384 で「ib_logfile0のヘッダーにはxxx32753までチェックポイント済って書いてあるのに、ib_logfile* を全部さらってもxxx32384までしか出てこない!」としてクラッシュリカバリーに失敗しているということか。
ということは、
  • (たぶんファジーな)チェックポイントが走る
  • ib_logfile0 のヘッダーを書き換えて、 ib_logfile* のどこかにREDOログを追記
  • MBPがハング()
  • ヘッダーの方はちゃんと書き込まれていたけれど、REDOログの部分は書き込まれていなかった
    • ログファイルに書いた時にアトミック性が保証されない innodb_flush_log_at_trx_commit <> 1 だったか、それともハングアップの最中にREDOログの一部がセクタごと持っていかれたか
    • あるいはストレージにfsyncを欺かれたか…
個人的にはセクタごと持っていかれた説を推したい(俺もかつてハングアップはしてないけれど、バイナリーログの一部セクターを打ちぬかれてスレーブが一斉にチェックサム違反でレプリケーションが止まったという経験ががが)
取り敢えず、(バックアップからのリストアをしないのであれば)ログファイルの最後の369バイトぶんの更新を失うことを念頭に、innodb_force_recovery= 6 で起動してmysqldumpで吸い上げるって感じになるだろうか。

2019年1月11日金曜日

PHPerKaigi2019 のCfPに5本のMySQLトークを出しました!

TL;DR


それぞれ完全新作なので「本当に大丈夫?」感が否み切れないアレとなっておりますが、自分用のメモを兼ねて概要を書いておきます。
  • 障害対応の勘所
    • まずはアプリケーションのエラーログを見ましょう
    • エラーログと /var/log/messages を見ましょう
    • スローログと /var/log/sa あたりを見ましょう
    • 初動を加速できるような情報を残しておきましょう
    • パラメーターは安全弁(なこともある)
  • 夢見る冗長構成
    • MySQL InnoDB Cluster と他のHAソリューションの違い
    • キモはMySQL Routerを通してInnoDB Cluster側の状態をアプリケーションが気にしなくていいこと(それ、 mikasafabric for MySQL でもできるよ)
    • 逆にMySQL Routerに隠蔽されるから面倒なこと(それ mikasafa略)
    • PXCとかNDBCLUSTERとの違いはしゃらっと
    • 吊るしのMySQLの方がマッチするケース、マルチマスターで幸せになれるケース
  • ログDB
    • 「定期的にダンプしてS3にでも放り込むのが一番幸せになるんじゃ?」って話
    • トランザクションで保護されるメリットはある
    • SQLが使えるメリットはS3 SELECTの登場で多少変わってきている
      • これを活かせば、メモリーにもストレージにもお財布にも優しくなる
      • S3 SELECTが使えなくても、都度展開とか何ならgrepとかさ…
    • ログなので、エンドユーザートラフィックで参照されることはない、っていうケースを想定
      • この前提が無い場合はRDBMSもまあまあ悪くない選択なのでは?
  • 大量レコード vs ORM
    • 100万行のフェッチ、DBMSとしては大したことないけど、アプリケーションは100万要素の行オブジェクトを全生成するのつらくない?
      • というかつらくて爆死していた
    • GROUP BY, Window関数, サブクエリーあたりを使って、DBMS内部で何とかできるものは何とかすればいいのでは?
    • やりすぎるとSQLおじさんになるので見極めがきっと大事
  • ユニットテスト
    • CIが薄いplackをキック, コンテナ起動してportを返す, テストデータ挿入, ユニットテスト, 薄いplackでコンテナを破棄させる, 終了
    • DBのMock代わり(?)にdockerコンテナを使ってみた話です
    • ひねったのは薄いplackがPOSTでスキーマを作成するSQLを受け取って、それを流してからポート番号を返すところ(えっ)
それでは、(採択されれば) PHPerKaigi2019 でお待ちしております!