mysql:16623
From: yoku0825 <yoku0825 <yoku0825@xxxxxxxxxx>>
Date: Wed, 23 Dec 2020 00:51:25 +0900
Subject: [mysql 16623] Re: [mysql 16622] Re: 準同期レプリケーションの非同期切り替について
こんばんはこんばんは。 なるほど、「準同期レプリカが倒れた時に巻き込まれたクエリの影響調査」だったのですね。 普段気にしたことがなかったので勉強になりますm(＿ ＿)m バイナリログのoriginal_commit_timestampやexec_timeから出せたりしないかなと思いましたがダメでした。 あたかも、タイムアウト待ちが存在しなかったかのようにCOMMITを叩いた時刻をコミット時刻としてバイナリログ上では扱っているようです。 閾値次第ですがスローログなら(平常状態でCOMMITで記録されるのは稀なので)COMMITに時間がかかっているところを探せるかな？ とは思いましたが、 完全さを求めるとこれも閾値に引っ掛からなければアウトなので調べられませんね（そして過去に戻って閾値を設定することもできない） 不明で済むなら済ませたいところですね…！ 褒めていただいたついでに調べてみましたが、Rpl_semi_sync_master_tx_wait_time はご賢察の通り「yes_tx」の時にだけカウントアップされるようです。 準同期モードの受け渡しに成功 (wait_result != 0が偽)し、かつwait_time > 0の時にインクリメントされていました。 - https://github.com/mysql/mysql-server/blob/mysql-8.0.19/plugin/semisync/semisync_master.cc#L789-L814 将来に備えて深追いの準備をするならperformance_schemaかなと思いましたが、どうもイマイチっぽいです(yes_txとno_txが混ざって計上されてしまう…) --- master [localhost] {msandbox} (performance_schema) > SELECT * FROM setup_instruments; | wait/synch/mutex/semisync/LOCK_binlog_ | NO | NO | | 0 | NULL | | wait/synch/mutex/semisync/Ack_receiver::m_mutex | NO | NO | | 0 | NULL | | wait/synch/cond/semisync/COND_binlog_send_ | NO | NO | | 0 | NULL | | wait/synch/cond/semisync/Ack_receiver::m_cond | NO | NO | | 0 | NULL | | stage/semisync/Waiting for semi-sync ACK from slave | NO | NO | | 0 | NULL | | stage/semisync/Waiting for semi-sync slave connection | NO | NO | | 0 | NULL | | stage/semisync/Reading semi-sync ACK from slave | NO | NO | | 0 | NULL | | memory/semisync/TranxNodeAllocator::block | YES | NULL | | 0 | NULL | master [localhost] {msandbox} (performance_schema) > UPDATE setup_instruments SET enabled = 'Yes', timed = 'Yes' WHERE name LIKE 'stage/semisync%'; Query OK, 3 rows affected (0.00 sec) Rows matched: 3 Changed: 3 Warnings: 0 --- ## 1回、semisyncをタイムアウトさせた master [localhost] {msandbox} (performance_schema) > SELECT * FROM events_stages_summary_global_by_event_name WHERE event_name LIKE 'stage/semisync%'; +-------------------------------------------------------+------------+----------------+----------------+----------------+----------------+ | EVENT_NAME | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT | +-------------------------------------------------------+------------+----------------+----------------+----------------+----------------+ | stage/semisync/Waiting for semi-sync ACK from slave | 1 | 10000203558000 | 10000203558000 | 10000203558000 | 10000203558000 | | stage/semisync/Waiting for semi-sync slave connection | 0 | 0 | 0 | 0 | 0 | | stage/semisync/Reading semi-sync ACK from slave | 0 | 0 | 0 | 0 | 0 | +-------------------------------------------------------+------------+----------------+----------------+----------------+----------------+ 3 rows in set (0.00 sec) ## Asyncにフォールバックした状態でもう1クエリー実行 master [localhost] {msandbox} (performance_schema) > SELECT * FROM events_stages_summary_global_by_event_name WHERE event_name LIKE 'stage/semisync%'; +-------------------------------------------------------+------------+----------------+----------------+----------------+----------------+ | EVENT_NAME | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT | +-------------------------------------------------------+------------+----------------+----------------+----------------+----------------+ | stage/semisync/Waiting for semi-sync ACK from slave | 2 | 10000205078000 | 1520000 | 5000102539000 | 10000203558000 | <-- no_txのぶんも計上されてしまっている | stage/semisync/Waiting for semi-sync slave connection | 0 | 0 | 0 | 0 | 0 | | stage/semisync/Reading semi-sync ACK from slave | 0 | 0 | 0 | 0 | 0 | +-------------------------------------------------------+------------+----------------+----------------+----------------+----------------+ 3 rows in set (0.00 sec) --- うーん、いまいちですね…。 > オープンソースではベンダーに聞かずとも自分でも調べる手法があるんだというのが新しいなと思った次第でした。 オープンソース沼にハマる機会があったら是非またいらしてくださいｗ ハマる機会がなくてもいつでもどうぞ！ yoku0825, 2020年12月22日(火) 22:15 内村健司 <uchimura.kenji@xxxxxxxxxx>: > > こんばんは。 > > > 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 > ∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞∞
16617 2020-12-21 11:28 [内村健司 <uchimura.k] 準同期レプリケーションの非同期切り替について 16618 2020-12-21 11:45 ┗[内村健司 <uchimura.k] Re: [mysql 16617] 準同期レプリケーションの非同期切り替について 16619 2020-12-21 13:29 ┗[yoku0825 <yoku0825@x] Re: [mysql 16618] Re: [mysql 16617] 準同期レプリケーションの非同期切り替について 16620 2020-12-21 14:45 ┗[内村健司 <uchimura.k] Re: 準同期レプリケーションの非同期切り替について 16621 2020-12-22 18:27 ┗[yoku0825 <yoku0825@x] Re: [mysql 16620] Re: 準同期レプリケーションの非同期切り替について 16622 2020-12-22 22:15 ┗[内村健司 <uchimura.k] Re: 準同期レプリケーションの非同期切り替について -> 16623 2020-12-23 00:51 ┗[yoku0825 <yoku0825@x] Re: [mysql 16622] Re: 準同期レプリケーションの非同期切り替について 16624 2020-12-23 08:41 ┗[内村健司 <uchimura.k] Re: 準同期レプリケーションの非同期切り替について