GA

2019/05/21

エラーログに 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.
日々の覚書: 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” ください…
​
投稿者 時刻: 0 件のコメント :
ラベル: ,

2019/05/16

MySQL 8.0のSHOW TABLE STATUSが全然更新されない件

TL;DR

空っぽのテーブルを用意する。
mysql80 111566> SHOW TABLE STATUS\G
*************************** 1. row ***************************
           Name: t1
         Engine: InnoDB
        Version: 10
     Row_format: Dynamic
           Rows: 0
 Avg_row_length: 0
    Data_length: 16384
Max_data_length: 0
   Index_length: 0
      Data_free: 0
 Auto_increment: NULL
    Create_time: 2019-05-16 15:41:52
    Update_time: NULL
     Check_time: NULL
      Collation: utf8mb4_0900_ai_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.00 sec)
データを1万行くらい入れる。
$ for n in $(seq 1 10000) ; do mysql80 -e "INSERT INTO t1 VALUES ($n, '')" d1; done

mysql80 111566> SELECT COUNT(*) FROM t1;
+----------+
| COUNT(*) |
+----------+
|    10000 |
+----------+
1 row in set (0.00 sec)
でも SHOW TABLE STATUS の結果は変わらない。。
mysql80 111566> SHOW TABLE STATUS\G
*************************** 1. row ***************************
           Name: t1
         Engine: InnoDB
        Version: 10
     Row_format: Dynamic
           Rows: 0
 Avg_row_length: 0
    Data_length: 16384
Max_data_length: 0
   Index_length: 0
      Data_free: 0
 Auto_increment: NULL
    Create_time: 2019-05-16 15:41:52
    Update_time: NULL
     Check_time: NULL
      Collation: utf8mb4_0900_ai_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.00 sec)
ちなみに SHOW CREATE TABLE の方の AUTO_INCREMENT の値はちゃんと増えてる。
mysql80 111566> SHOW CREATE TABLE t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `val` varchar(32) DEFAULT NULL,
  UNIQUE KEY `num` (`num`)
) ENGINE=InnoDB AUTO_INCREMENT=10001 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
1 row in set (0.00 sec)
これはMySQL 8.0.3から information_schema_stats_expiry なるオプションが増えてからの挙動で、どうも information_schema.tables に含まれるほとんどの情報は mysql.table_stats テーブルにキャッシュされ、そのキャッシュがexpireされるまではずっとその値を使う様子（ mysql.table_stats は隠れシステムテーブルなので、フツーにSQLを使っているだけだとそのテーブルは見えない）
mysql80 111566> SELECT * FROM mysql.table_stats;
ERROR 3554 (HY000): Access to data dictionary table 'mysql.table_stats' is rejected.
オプションにも書いてある通り、単位は秒でデフォルトは86400秒(= 24時間)
つまりどれだけテーブルを更新しようと、 information_schema.tables や SHOW TABLE STATUS の値は「最後に mysql.table_stats が更新されてから24時間」は全く変更されない（ように見える）
コード的には このへん でキャッシュがexpireされてるかとかそのへんを判定してて、元をたどって進んでいくと ここらへん でキャッシュを更新する処理に突入している。
(現在時刻 - キャッシュの更新時刻) > information_schema_stats_expiryになった場合はキャッシュを更新してその結果を、 information_schema_stats_expiry = 0 の場合はそもそも mysql.table_stats テーブルをキャッシュとして 使わない みたいな動作になるようだ。
mysql80 111566> SET SESSION information_schema_stats_expiry= 1;
Query OK, 0 rows affected (0.01 sec)

mysql80 111566> SHOW TABLE STATUS\G
*************************** 1. row ***************************
           Name: t1
         Engine: InnoDB
        Version: 10
     Row_format: Dynamic
           Rows: 10000
 Avg_row_length: 32
    Data_length: 327680
Max_data_length: 0
   Index_length: 0
      Data_free: 0
 Auto_increment: 10001
    Create_time: 2019-05-16 15:41:52
    Update_time: 2019-05-16 16:02:34
     Check_time: NULL
      Collation: utf8mb4_0900_ai_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.00 sec)
セッションスコープ, グローバルスコープが両方あるタイプの変数なので、監視用のセッションにだけ押し込んでおけばいいかと。
しかし SET_VAR 構文は使えないらしいので残念。
​
投稿者 時刻: 0 件のコメント :
ラベル: ,
登録: 投稿 ( Atom )