こんばんは。


yoku0825さん、ご指摘ありがとうございます。

再度整理してみたのですが、 yoku0825さんの想定通りになっているようです。

−−−−−−−−−−−−−−−−−−−−−−−−−−
【マスターエラーログ】
2020-12-14T12:32:59.742804+09:00 71325 [Warning] [MY-011153] [Server] Timeout waiting for reply of binlog (file: binlog.000685, pos: 696205307), semi-sync up to file binlog.000685, position 696204814.


【マスターのレプリケーションステータスは1分おきにZabbixにて採取】

「tx_wait_time]
12:31:15〜12:32:15の間に884,978マイクロ秒,
12:32:15〜12:33:15の間に  2,640マイクロ秒,
12:33:15〜12:34:15の間に274,577マイクロ秒計上された。

「yes_tx」
12:31:19〜12:32:19の間に363回,
12:32:19〜12:33:19の間に1回,
12:33:19〜12:34:19の間に113回計上された。

「no_tx」
12:31:12〜12:32:12の間に0回、
12:32:12〜12:33:12の間に115回
12:33:12〜12:34:12の間に0回計上された。

「tx_waits」
12:31:16〜12:32:16の間に363回,
12:32:16〜12:33:16の間に1回,
12:32:16〜12:34:16の間に113回計上された


【参考：マニュアルより抜粋】
Rpl_semi_sync_master_tx_wait_time 
マスターがトランザクションを待機する合計時間 (マイクロ秒)。 
The total time in microseconds the source waited for transactions. 


Rpl_semi_sync_master_yes_tx 
スレーブによって正しく認証されたコミットの数。 
The number of commits that were acknowledged successfully by a replica. 


Rpl_semi_sync_master_no_tx 
スレーブによって正しく認証されなかったコミット数。 
The number of commits that were not acknowledged successfullyby a replica. 


Rpl_semi_sync_master_tx_waits
マスターがトランザクションを待機した合計回数。
The total number of times the source waited for transactions. 

−−−−−−−−−−−−−−−−−−−−−−−−−−

あるトランザクションがタイムアウトし、準同期が非同期に切り替わった後、
「no_tx」がカウントアップしたのは間違いなさそうです。
その後準同期モードに戻ってます。


マスターエラーログのメッセージは気づいていたのですが、
10秒待って非同期になったのであれば、12:31:15〜12:32:15の間の「tx_wait_time」が
10秒以上計上されるはずと考えてしまったのが、誤りでした。

「tx_wait_time」は準同期のトランザクションのみの時間がカウントアップされるなら納得いきます。


今回の私のミッションは準同期でレプリケーション(AFTER_SYNC)し、タイムアウトを10秒にしたので、
「実際どれくらいのトランザクションの時間なのかを明らかにする」でした。


「tx_wait_time」と「tx_waits」でおおよその1分間の移動平均時間を求めることはできますが、
(集計期間の最大1分平均は0.23秒でした)
非同期分のトランザクションの時間は分からないでしょうから、答えが出せないですね。

非同期になった「no_tx」回数分のトランザクションの時間は不明というしきりにしようと思います。



今回、原因を調査するためにはソースをチェックするだというのが、私的にはすごく衝撃的でした。

今までパッケージの仕様はパッケージベンダーに聞くしかないと思っていた節がありましたが、
オープンソースではベンダーに聞かずとも自分でも調べる手法があるんだというのが新しいなと思った次第でした。

yoku0825さん色々とありがとうございました。


内村


On Tue, 22 Dec 2020 18:27:43 +0900
yoku0825 <yoku0825@xxxxxxxxxx> wrote:

> こんばんは。

> 

> タイムアウトの設定は実際には10秒だったのですね。ありがとうございます。

> 

> 少し調べてみましたが、 Rpl_semi_sync_master_no_tx

> は「マスターからレプリカに準同期モードで渡さなかった(渡せなかった)トランザクション」があった時にカウントアップされました。

> これは「準同期モードでタイムアウトした当のトランザクション」もカウントアップされますし、非同期モードにフォールバック中にコミットされたトランザクションの時もカウントアップされました。

> （レプリカ側からエラーが返っているわけではなく、マスター側から見た時に「準同期モードでないコミットをした」という視点です）

> 

> 逆に、準同期モードで渡せたトランザクションは Rpl_semi_sync_master_yes_txがカウントアップされます。

> 

> というわけで、「1つのACKが何らかの理由でタイムアウトした」ならば準同期モードに復帰するまでの間に来た新たなトランザクションは全て非同期モードで処理されるので、

> Rpl_semi_sync_master_no_tx がカウントアップされるのは観測され得ます。

> ただしこのカウントアップとRpl_semi_sync_master_statusのOFFに直接の因果関係は無く、どちらも「準同期レプリケーションが失敗した」結果として「Rpl_semi_sync_master_no_txがカウントアップされ、Rpl_semi_sync_master_statusはOFFになった」という形ではないでしょうか。

> 

> おそらく、準同期レプリケーションが失敗した理由そのものはエラーログに出ていると思います。

> 

> 2020-12-22T08:40:21.644649Z 14 [Warning] [MY-011153] [Server] Timeout

> waiting for reply of binlog (file: mysql-bin.000001, pos: 4952),

> semi-sync up to file , position 0.

> 

> 

> yoku0825,

> 

> 

> 

> 

> 

> 2020年12月21日(月) 14:45 内村健司 <uchimura.kenji@xxxxxxxxxx>:

> >

> > yoku0825さん、はじめまして。

> >

> >

> > ご連絡ありがとうございます。

> >

> >

> > > > ・rpl_semi_sync_master_timeout=1000(10秒)

> > >

> > > rpl_semi_sync_master_timeout=1000 は1秒です。

> > > メールの書き間違いか、10秒(デフォルトはこちら)と1秒を取り間違えているかが気になります。

> > > なお、semisyncプラグインは「一度タイムアウトするとAsyncにフォールバックする」ので、

> > > 最初の1秒または10秒待たされた以降はタイムアウトを待たずにAsyncレプリケーションでレプリカに流れます。

> >

> >

> > 「rpl_semi_sync_master_timeout」については「10000」(10秒)でした。ゼロを一つ少なかったです。すいません。

> >

> >

> > > > Rpl_semi_sync_master_no_tx

> > >

> > > これがカウントアップされそうなあたりをちょっと見てみましたが、binlog_order_commitとかslave_preserve_commit_orderとか関係あるのかないのかなコードが出てきます。

> > > 心当たりはありますか？

> > >

> > > https://github.com/mysql/mysql-server/blob/mysql-8.0.19/plugin/semisync/semisync_master.cc#L701-L718

> >

> >

> > これについては心当たりはありません。

> > 設定したパラメータにもなかったような気がします。。。

> >

> >

> > > > スレーブからエラーを返した来た際も非同期への切り替えが行われるように見えます。

> > >

> > > どんなエラーでしょうか…？ (リレーログの書き込みに失敗したとしても、明確なエラー応答はせずに黙ってACKを返さないものだと思っていました)

> >

> >

> > エラーは「Rpl_semi_sync_master_no_tx」がカウントアップされたことを言っておりました。

> >

> >

> > 「Rpl_semi_sync_master_status」がOFFになった原因を調べていたら、

> > 「Rpl_semi_sync_master_no_tx」の値が増加した時間帯に「Rpl_semi_sync_master_status」が「OFF」になっていた為、

> > 相関があるのかなと思った次第です。

> >

> > 「Rpl_semi_sync_master_status」が「OFF」になった時間帯はアプリケーションが1秒当たり100件以上のインサート文発行している時間帯でしたので、

> > そいつが原因で「Rpl_semi_sync_master_no_tx」がカウントアップされ、「Rpl_semi_sync_master_status」がOFFになったのでは？？と想定しております。

> >

> >

> > 以上です。

> >

> >

> >

> >

> > On Mon, 21 Dec 2020 13:29:11 +0900

> > yoku0825 <yoku0825@xxxxxxxxxx> wrote:

> >

> > > こんにちは、yoku0825といいます。

> > >

> > > 先に伺っておきたいのですが、

> > >

> > > > ・rpl_semi_sync_master_timeout=1000(10秒)

> > >

> > > rpl_semi_sync_master_timeout=1000 は1秒です。

> > > メールの書き間違いか、10秒(デフォルトはこちら)と1秒を取り間違えているかが気になります。

> > > なお、semisyncプラグインは「一度タイムアウトするとAsyncにフォールバックする」ので、

> > > 最初の1秒または10秒待たされた以降はタイムアウトを待たずにAsyncレプリケーションでレプリカに流れます。

> > >

> > >

> > > > Rpl_semi_sync_master_no_tx

> > >

> > > これがカウントアップされそうなあたりをちょっと見てみましたが、binlog_order_commitとかslave_preserve_commit_orderとか関係あるのかないのかなコードが出てきます。

> > > 心当たりはありますか？

> > >

> > > https://github.com/mysql/mysql-server/blob/mysql-8.0.19/plugin/semisync/semisync_master.cc#L701-L718

> > >

> > >

> > > > スレーブからエラーを返した来た際も非同期への切り替えが行われるように見えます。

> > >

> > > どんなエラーでしょうか…？ (リレーログの書き込みに失敗したとしても、明確なエラー応答はせずに黙ってACKを返さないものだと思っていました)

> > > エラーを返すとしたらマスターのエラーログとかに残るのですかね（SQLスレッドは準同期レプリケーションに関わっていないので、SQLスレッドのエラーは関係ありません）

> > >

> > >

> > > yoku0825,

> > >

> > > 2020年12月21日(月) 11:45 内村健司 <uchimura.kenji@xxxxxxxxxx>:

> > > >

> > > > 情報書き漏れました。すいません。

> > > >

> > > > mysql のバージョンは8.0.19の無償版です。

> > > > OSはrhel7.7です。

> > > >

> > > > 以上、よろしくお願いします。

> > > >

> > > > 2020/12/21 11:28、内村健司 <uchimura.kenji@xxxxxxxxxx>のメール:

> > > >

> > > > > こんにちは。内村と申します。

> > > > >

> > > > >

> > > > > 初めて投稿させていただきます。

> > > > > 準同期レプリケーションの非同期切り替えについてご教授ください。

> > > > >

> > > > >

> > > > > 現在、ロスレスの準同期でレプリケーションを構築しており、

> > > > > 「Rpl_semi_sync_master_status」をZabbixで監視(ON以外になったら、警告)する運用にしております。

> > > > >

> > > > >

> > > > > レプリケーションは以下の設定です。

> > > > > ・rpl_semi_sync_master_timeout=1000(10秒)

> > > > > ・rpl_semi_sync_master_wait_point=AFTER_SYNC

> > > > >

> > > > >

> > > > > マスター側のAPLでデータ更新量が少ないコミット処理を多数連続で発行した場合、

> > > > > 「Rpl_semi_sync_master_no_tx」の値が増加し、

> > > > > そのタイミングで「Rpl_semi_sync_master_status」がOFFになっております。

> > > > >

> > > > >

> > > > > 準同期から非同期への切り替えはマスターがスレーブにバイナリデータを転送し、

> > > > > 10秒返答がなかった場合のみ行われると考えていたのですが、

> > > > > スレーブからエラーを返した来た際も非同期への切り替えが行われるように見えます。

> > > > >

> > > > > 「Rpl_semi_sync_master_no_tx」の値が増加したら、「Rpl_semi_sync_master_status」が「OFF」になる。

> > > > > は動作として正しいのでしょうか。

> > > > >

> > > > >

> > > > > 準同期から非同期への切り替え契機は以下のパターンであってますでしょうか。

> > > > > ・スレーブから応答がない場合

> > > > > ・スレーブから応答エラーと返信が返ってきた場合　★

> > > > >

> > > > > また、その他の条件でも非同期切り替えが発生するのでしょうか。

> > > > >

> > > > >

> > > > > ご存じの方がいらっしゃら、コメント・ご教授頂けると幸いです。

> > > > >

> > > > > 以上、よろしくお願いいたします。

> > > > >

> > > > >

> > > > > ∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞

> > > > > 内村健司

> > > > > インタービレッジ株式会社

> > > > >

> > > > > ∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞



∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞
内村健司
インタービレッジ株式会社
090-2969-7209<softbank>
uchimura.kenji@xxxxxxxxxx
∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞