GA

2019/01/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_mode は innodb_read_only がセットされた時のフラグなので読み飛ばすとして、 group->scanned_lsn != checkpoint_lsn なのが気に入らないらしい。
4168行目で srv_force_recovery ( innodb_force_recovery が SRV_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 = xxx32753 と group->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で吸い上げるって感じになるだろうか。
​
投稿者 時刻:
ラベル:

0 件のコメント :

コメントを投稿

登録: コメントの投稿 ( Atom )