エラーログに MY-010956 と MY-010957 が出まくるはなし

TL;DR

• MySQL 8.0同士でレプリケーションを組んでいると、スレーブから以下のような MY-010956 と MY-010957 がぼこぼこエラーログに吐かれることがある

2019-05-20T14:25:17.121864+09:00 5 [Warning] [MY-010956] [Server] Invalid replication timestamps: original commit timestamp is more recent than the immediate commit timestamp. This may be an issue if delayed replication is active. Make sure that servers have their clocks set to the correct time. No further message will be emitted until after timestamps become valid again.
2019-05-20T14:25:17.177804+09:00 5 [Warning] [MY-010957] [Server] The replication timestamps have returned to normal values.

• 実害はほぼないはずだけど、エラーログの肥大化に注意
• もうちょっと出力を穏やかにできないかね？ ってFeature Requestを出した
  • MySQL Bugs: #95422: MY-010956 and MY-010957 are possible too noisy in error-log

---

日々の覚書: MySQL 8.0.1でバイナリーログに original_commit_timestamp と immediate_commit_timestamp が追加された という記事で書いたように、MySQL 8.0からはバイナリーログのイベントに（正確には、トランザクションがコミットされた時にイベントに先行して記録されるGtid_log_eventに）マイクロ秒単位でタイムスタンプが記録される。

このタイムスタンプが、 original_commit_timestamp > immediate_commit_timestamp （スレーブで実行されたタイムスタンプよりマスターで実行されたタイムスタンプが未来）になってしまった時にエラーログに記録されるワーニングが MY-010956 、 MY-010956 が記録された後に original_commit_timestamp <= immediate_commit_timestamp に戻った時に記録されるワーニングが MY-010957 。

ところで、運用しているMySQLの載っているマシンが「マイクロ秒単位で」正しいシステムクロックに設定されていることに自信のある方はいらっしゃるだろうか？
俺には自信はない、というか、いいとこ1桁ミリ秒単位ならズレるだろうとも思っている。ホストとクロックを定期的に同期するVMならまだしも（試してない）、NTPではこのくらいの精度は限界なんではなかろうか。

というわけで、だ。

$ date "+%s.%N" ### at master
1558337325.766668654

$ date "+%s.%N" ### at slave
1558337325.767114036

こんな状況は起こりえる。500usマスターが進んでいる。

この状態でマスターに更新を叩き込んで、 “500us以内にそのバイナリーログの適用が終わった場合” に MY-010956 が発火する（適用に500us以上かかれば、再びスレーブのタイムスタンプがマスターのそれを追い越すので何も起こらない。これが出まくったってことはそれくらいのレイテンシーで更新できてるってことで望ましいことではある）

そして MY-010956 が発火して以降（ MY-010956 は一度発火すると、次にタイムスタンプの順序が戻る= MY-010957 が出るまでは連続で発火しない）、 “適用に500us以上かかったバイナリーログのイベント” が来ると MY-010957 が着火し、次に500us未満で適用が終わったイベントが…と、延々発火し得る。

きっちり一致させられないにしろ、マスターのシステムクロックを 進めれば 遅らせればいいのでは？ と思ったりしたけど、いつNTPでじりじりと補正されるかわからないし、マスターを切り替えちゃったらまた出ることには変わりはないし、だいたいmysqldを起動したまま手で時刻を修正するとか嫌な予感しかしない。

ワーニングだし「これはどう考えても出る時は出る」って感じなので無視するのがいいんだろうけれど、 log_error_verbosity を1（エラーのみロギング、ワーニング以下を無視する）にするのはちょっと大雑把かなと思うし、かといってエラーログはでっかくなるし。

閾値を設定できるようにしませんか？ というFeature Requestがこれ。
いいな（？）と思ったら “Affects me” ください…

MySQL Bugs: #95422: MY-010956 and MY-010957 are possible too noisy in error-log

​