疑問
1分間隔でMySQLのレプリケーションラグを監視しているとして突如300秒とかが出るケースがあった。根本的な原因はよくわからなかったが起きていそうな問題について考えてみる。ざっくり以下のような事象である。
- 20:00 レプリカラグ0秒
- 20:01 レプリカラグ300秒
- 20:02 レプリカラグ0秒
考察
プライマリーとレプリカでネットワークで遅延が起きると発生するはず。レプリカラグを見るのはSeconds_Behind_Masterでこの値は「現在 SQL_THREAD が実行しているクエリの実行時刻」と「レプリカが保持しているリレーログの時刻」の差となる。IO_THREADがリレーログに書き込むまでに時間がかかってしまうとその分だけ遅延が発生する。MySQLのレプリケーションの仕組みはざっくり以下のようになっている。
- クライアントがプリマリーへWriteしてコミット
- IO_THREADがプライマリのバイナリログをリレーログとしてレプリカに転送
- IO_THREADがリレーログへsync
- SQL_THREADリレーログを読み取りレプリカへクエリを適用
仮にスロークエリがプライマリーで実行されたとするとレプリカでも同様の時間が処理にかかる。30秒のクエリだったらレプリカ遅延も30秒となる。300秒だったら300秒の遅延となる。一番多いレプリカラグ問題はこれだと思う(経験的に)。一方でこの場合はレプリカラグは線形に伸びていく。冒頭の疑問にもあるように300秒が突如として現れるケースではないのでスロークエリであるとは言えなそうである。(スロークエリログを出していてもデフォルトではログに出ないので注意)。
じゃあ何が怪しいかというと2と3あたりとなる。IO_THREADが仮に処理遅延などが起きていたとしよう。そうするとSQL_THREADは全てのクエリを適用し終えているのでレプリカラグは0秒となる。IO_THREADが300秒前に実行されたクエリをリレーログに書き込んだ瞬間にレプリカラグは300秒となる。おそらくはこれが正体ではないだろうか。
ネットワーク遅延かリレーログの書き込み(syncを同期的にするかは設定次第)あたりで何かが起きていた可能性がありそうということがわかる。Network or Diskあたりで遅延が怪しいかなという感想。
緩和策
ネットワークの場合はネットワーク周りの見直しになるがディスクであればsync_relay_logあたりの設定を見直すことでdisk IOを減らすことができるので効果的。
