Optimize Seconds_Behind_Source Under MTS Parallel Replication - #748
Open
jiyfhust wants to merge 3 commits into
Open
Optimize Seconds_Behind_Source Under MTS Parallel Replication#748jiyfhust wants to merge 3 commits into
jiyfhust wants to merge 3 commits into
Conversation
…timization
PROBLEM
=======
Under MTS parallel replication, Seconds_Behind_Source (SBM) can be
inaccurate and unstable, spiking well beyond the actual replication
lag. This has severe consequences in proxy-based read/write splitting
deployments.
Root cause analysis:
1. last_master_timestamp == 0 window:
The group's ts field (grp->ts) is only set when the coordinator
processes the ends_group event (XID/Query event). Between
starts_group (GTID event) and ends_group, grp->ts remains 0. If a
checkpoint occurs in this window, last_master_timestamp is
initialized to 0.
2. Fallback to imprecise event time:
When last_master_timestamp == 0, the fallback logic sets it to
ev->common_header->when.tv_sec + (time_t)ev->exec_time. This is
the event header timestamp plus the transaction execution time on
the master — NOT the real commit time. For a transaction that
takes 10 seconds on the master, this value is ~10 seconds earlier
than the actual commit, inflating SBM by the master execution
time.
3. Unconditional overwrite in ends_group:
Even if a precise immediate_commit_timestamp were available from
the GTID event, ends_group unconditionally overwrites grp->ts with
when.tv_sec + exec_time, discarding the precise value.
Impact on proxy-based read/write splitting:
Proxies (ProxySQL, MySQL Router, custom middleware) monitor SBM
to decide whether a replica is safe for reads. An inflated SBM
causes the proxy to evict the replica from the read pool; the
subsequent drop causes re-addition. This repeated flapping of
replica availability causes intermittent read failures, directly
impacting business continuity.
This commit adds the MTR test and two debug points that control MTS
checkpoint timing to verify the fix. The core optimization is in a
follow-up commit. Without the core optimization, both test cases
fail because SBM includes the master execution time and exceeds 9
seconds.
Debug points:
- sbm_block_checkpoint: prevents mta_checkpoint_routine from
executing, keeping a completed group in GAQ.
- sbm_force_checkpoint: forces checkpoint on the next QUERY_EVENT,
triggering the checkpoint path while a new transaction is being
assigned.
Test cases (both under replica_parallel_workers=4):
- Test case 1: A long transaction (INSERT ... SLEEP(10)) is blocked
on the replica by LOCK TABLE. SBM must not exceed 9 seconds.
- Test case 2: Uses the debug points to control checkpoint timing
and verify SBM does not spike.
The test requires --binlog-rows-query-log-events=ON (via .opt file)
so that SHOW PROCESSLIST displays the original SQL text in row-based
binlog mode.
…stamp PROBLEM ======= Under MTS parallel replication, Seconds_Behind_Source (SBM) can be inaccurate and unstable, spiking well beyond the actual replication lag. This has severe consequences in proxy-based read/write splitting deployments. Root cause analysis: 1. last_master_timestamp == 0 window: The group's ts field (grp->ts) is only set when the coordinator processes the ends_group event (XID/Query event). Between starts_group (GTID event) and ends_group, grp->ts remains 0. If a checkpoint occurs in this window, last_master_timestamp is initialized to 0. 2. Fallback to imprecise event time: When last_master_timestamp == 0, the fallback logic sets it to ev->common_header->when.tv_sec + (time_t)ev->exec_time. This is the event header timestamp plus the transaction execution time on the master — NOT the real commit time. For a transaction that takes 10 seconds on the master, this value is ~10 seconds earlier than the actual commit, inflating SBM by the master execution time. 3. Unconditional overwrite in ends_group: Even if a precise immediate_commit_timestamp were available from the GTID event, ends_group unconditionally overwrites grp->ts with when.tv_sec + exec_time, discarding the precise value. Impact on proxy-based read/write splitting: Proxies (ProxySQL, MySQL Router, custom middleware) monitor SBM to decide whether a replica is safe for reads. An inflated SBM causes the proxy to evict the replica from the read pool; the subsequent drop causes re-addition. This repeated flapping of replica availability causes intermittent read failures, directly impacting business continuity. FIX === This commit implements the core optimization. The GTID event already carries immediate_commit_timestamp — the commit time on the immediate master with microsecond precision. This patch uses it instead of when+exec_time in three code paths: 1. starts_group (log_event.cc): Set grp->ts from immediate_commit_timestamp at GTID event time, eliminating the ts=0 window between starts_group and ends_group. 2. ends_group (log_event.cc): Only fall back to when+exec_time when grp->ts == 0 (not set by a GTID event), preserving the precise commit timestamp. 3. exec_relay_log_event (rpl_replica.cc): Prefer immediate_commit_timestamp for last_master_timestamp. Fall back to when+exec_time for non-GTID events or old masters without commit timestamps. The fix is backward compatible: when immediate_commit_timestamp is unavailable (has_commit_timestamps == false), the original when+exec_time logic is used unchanged.
…for immediate_commit_timestamp The dec_event_time_by_1_hour and inc_event_time_by_1_hour debug points exist in log_event.cc (affecting event header when.tv_sec) but were missing from binlog.cc (affecting immediate_commit_timestamp). This caused rpl_seconds_behind_master to fail after the SBM optimization switched to immediate_commit_timestamp, since the debug point no longer shifted the timestamp used for SBM calculation.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
What does this change do?
Problem
Why
last_master_timestampCan Be 0Under MTS parallel replication, each transaction group is assigned a
Slave_job_groupentry in the GAQ (Group Assigned Queue). Thegrp->tsfield — which ultimately feedslast_master_timestamp— isonly set when the coordinator processes the ends_group event
(XID or Query event that terminates the transaction). Between
starts_group (the GTID event) and ends_group,
grp->tsremains 0. If a checkpoint happens to occur in this window, the
checkpoint routine reads
grp->ts == 0and propagates it tolast_master_timestamp, causing SBM to momentarily drop to 0.What Happens When
last_master_timestamp == 0During ReplayWhen
last_master_timestampis 0, the fallback logic inexec_relay_log_eventsets it to:This value is derived from the event header —
when.tv_secisthe timestamp when the event was written to the binary log, and
exec_timeis the time the transaction spent executing on themaster. This is not the real commit time. For a long-running
transaction (e.g.
INSERT ... SLEEP(10)),when.tv_secis set atthe start of the statement, so
when.tv_sec + exec_timeis roughly10 seconds earlier than the actual commit. SBM is therefore
inflated by the master execution time, making it appear that the
replica is 10 seconds behind even when replication lag is near zero.
Furthermore,
ends_groupunconditionally overwritesgrp->tswith
when.tv_sec + exec_time, so even if a preciseimmediate_commit_timestampwere available from the GTID event, itwould be discarded.
Impact on Proxy-Based Read/Write Splitting
In proxy-based read/write splitting deployments (e.g. ProxySQL,
MySQL Router, or custom middleware), the proxy continuously monitors
Seconds_Behind_Sourceto determine whether a replica is safe toserve read traffic. When SBM spikes due to the imprecise
when.tv_sec + exec_timecalculation, the proxy incorrectlyconcludes the replica is stale and evicts it from the read pool.
When SBM subsequently drops back, the replica is re-added. This
repeated flapping of replica availability causes read requests to
fail intermittently, directly impacting business continuity and
user experience. A correct and stable SBM is therefore critical for
proxy-based architectures.
Fix
The GTID event already carries
immediate_commit_timestamp— thecommit time on the immediate master with microsecond precision. This
patch uses it instead of
when.tv_sec + exec_timein three codepaths:
starts_group (
log_event.cc): Setgrp->tsfromimmediate_commit_timestampat GTID event time, eliminating thets=0 window between starts_group and ends_group.
ends_group (
log_event.cc): Only fall back towhen.tv_sec + exec_timewhengrp->ts == 0(not set by a GTIDevent), preserving the precise commit timestamp.
exec_relay_log_event (
rpl_replica.cc): Preferimmediate_commit_timestampforlast_master_timestamp. Fall backto
when.tv_sec + exec_timefor non-GTID events or old masterswithout commit timestamps.
The fix is backward compatible: when
immediate_commit_timestampisunavailable (
has_commit_timestamps == false), the originalwhen.tv_sec + exec_timelogic is used unchanged.Test
Two test cases under MTS (
replica_parallel_workers=4):Test case 1: A long transaction (
INSERT ... SLEEP(10)) isblocked on the replica by
LOCK TABLE. SBM must not exceed 9seconds, proving it does not include the 10-second master
execution time.
Test case 2: Uses two debug points to control MTS checkpoint
timing:
sbm_block_checkpoint: preventsmta_checkpoint_routinefromexecuting, keeping a completed group in GAQ.
sbm_force_checkpoint: forces checkpoint on the nextQUERY_EVENT, triggering the checkpoint path while a newtransaction is being assigned.
This verifies the checkpoint path uses
immediate_commit_timestampand SBM does not spike.
The test requires
--binlog-rows-query-log-events=ON(via.optfile) so that
SHOW PROCESSLISTdisplays the original SQL text inrow-based binlog mode, allowing
wait_show_conditionto detect whenthe replica worker starts replaying the blocked transaction.
Without the core optimization, both test cases fail because SBM
includes the master execution time and exceeds 9 seconds.
Why is it needed?
How was it tested?
mysql-test/scripts/ci/mtr.shpasses locallyContributor checklist
scripts/ci/format.sh)AI assistance
If AI assistance was used, describe the tool(s) and extent of use:
Areas touched