[Tarantool-patches] [PATCH v10 2/2] relay: provide information about downstream lag
Cyrill Gorcunov
gorcunov at gmail.com
Tue Jun 22 18:22:46 MSK 2021
We already have `box.replication.upstream.lag` entry for monitoring
sake. Same time in synchronous replication timeouts are key properties
for quorum gathering procedure. Thus we would like to know how long
it took of a transaction to traverse `initiator WAL -> network ->
remote applier -> initiator ACK reception` path.
Typical output is
| tarantool> box.info.replication[2].downstream
| ---
| - status: follow
| idle: 0.61753897101153
| vclock: {1: 147}
| lag: 0
| ...
| tarantool> box.space.sync:insert{69}
| ---
| - [69]
| ...
|
| tarantool> box.info.replication[2].downstream
| ---
| - status: follow
| idle: 0.75324084801832
| vclock: {1: 151}
| lag: 0.0011014938354492
| ...
Closes #5447
Signed-off-by: Cyrill Gorcunov <gorcunov at gmail.com>
@TarantoolBot document
Title: Add `box.info.replication[n].downstream.lag` entry
`replication[n].downstream.lag` represents a lag between the main
node writes a certain transaction to it's own WAL and a moment it
receives an ack for this transaction from a replica.
---
.../unreleased/gh-5447-downstream-lag.md | 6 +
src/box/lua/info.c | 3 +
src/box/relay.cc | 41 ++++++
src/box/relay.h | 6 +
.../replication/gh-5447-downstream-lag.result | 124 ++++++++++++++++++
.../gh-5447-downstream-lag.test.lua | 56 ++++++++
test/replication/suite.ini | 2 +-
7 files changed, 237 insertions(+), 1 deletion(-)
create mode 100644 changelogs/unreleased/gh-5447-downstream-lag.md
create mode 100644 test/replication/gh-5447-downstream-lag.result
create mode 100644 test/replication/gh-5447-downstream-lag.test.lua
diff --git a/changelogs/unreleased/gh-5447-downstream-lag.md b/changelogs/unreleased/gh-5447-downstream-lag.md
new file mode 100644
index 000000000..f937ce35e
--- /dev/null
+++ b/changelogs/unreleased/gh-5447-downstream-lag.md
@@ -0,0 +1,6 @@
+#feature/replication
+
+ * Introduced `box.info.replication[n].downstream.lag` field to monitor
+ state of replication. This member represents a lag between the main
+ node writes a certain transaction to it's own WAL and a moment it
+ receives an ack for this transaction from a replica (gh-5447).
diff --git a/src/box/lua/info.c b/src/box/lua/info.c
index 0eb48b823..f201b25e3 100644
--- a/src/box/lua/info.c
+++ b/src/box/lua/info.c
@@ -143,6 +143,9 @@ lbox_pushrelay(lua_State *L, struct relay *relay)
lua_pushnumber(L, ev_monotonic_now(loop()) -
relay_last_row_time(relay));
lua_settable(L, -3);
+ lua_pushstring(L, "lag");
+ lua_pushnumber(L, relay_txn_lag(relay));
+ lua_settable(L, -3);
break;
case RELAY_STOPPED:
{
diff --git a/src/box/relay.cc b/src/box/relay.cc
index b1571b361..115037fc3 100644
--- a/src/box/relay.cc
+++ b/src/box/relay.cc
@@ -68,6 +68,8 @@ struct relay_status_msg {
struct relay *relay;
/** Replica vclock. */
struct vclock vclock;
+ /** Last replicated transaction timestamp. */
+ double txn_lag;
};
/**
@@ -158,6 +160,14 @@ struct relay {
struct stailq pending_gc;
/** Time when last row was sent to peer. */
double last_row_time;
+ /**
+ * A time difference between the moment when we
+ * wrote a transaction to the local WAL and when
+ * this transaction has been replicated to remote
+ * node (ie written to node's WAL) so that ACK get
+ * received.
+ */
+ double txn_lag;
/** Relay sync state. */
enum relay_state state;
@@ -166,6 +176,11 @@ struct relay {
alignas(CACHELINE_SIZE)
/** Known relay vclock. */
struct vclock vclock;
+ /**
+ * Transaction downstream lag to be accessed
+ * from TX thread only.
+ */
+ double txn_lag;
/**
* True if the relay needs Raft updates. It can live fine
* without sending Raft updates, if it is a relay to an
@@ -217,6 +232,12 @@ relay_last_row_time(const struct relay *relay)
return relay->last_row_time;
}
+double
+relay_txn_lag(const struct relay *relay)
+{
+ return relay->tx.txn_lag;
+}
+
static void
relay_send(struct relay *relay, struct xrow_header *packet);
static void
@@ -336,6 +357,12 @@ relay_stop(struct relay *relay)
* upon cord_create().
*/
relay->cord.id = 0;
+ /*
+ * If relay is stopped then lag statistics should
+ * be updated on next new ACK packets obtained.
+ */
+ relay->txn_lag = 0;
+ relay->tx.txn_lag = 0;
}
void
@@ -483,6 +510,8 @@ tx_status_update(struct cmsg *msg)
{
struct relay_status_msg *status = (struct relay_status_msg *)msg;
vclock_copy(&status->relay->tx.vclock, &status->vclock);
+ status->relay->tx.txn_lag = status->txn_lag;
+
struct replication_ack ack;
ack.source = status->relay->replica->id;
ack.vclock = &status->vclock;
@@ -629,6 +658,17 @@ relay_reader_f(va_list ap)
/* vclock is followed while decoding, zeroing it. */
vclock_create(&relay->recv_vclock);
xrow_decode_vclock_xc(&xrow, &relay->recv_vclock);
+ /*
+ * Replica send us last replicated transaction
+ * timestamp which is needed for relay lag
+ * monitoring. Note that this transaction has
+ * been written to WAL with our current realtime
+ * clock value, thus when it get reported back we
+ * can compute time spent regardless of the clock
+ * value on remote replica.
+ */
+ if (xrow.tm != 0)
+ relay->txn_lag = ev_now(loop()) - xrow.tm;
fiber_cond_signal(&relay->reader_cond);
}
} catch (Exception *e) {
@@ -838,6 +878,7 @@ relay_subscribe_f(va_list ap)
};
cmsg_init(&relay->status_msg.msg, route);
vclock_copy(&relay->status_msg.vclock, send_vclock);
+ relay->status_msg.txn_lag = relay->txn_lag;
relay->status_msg.relay = relay;
cpipe_push(&relay->tx_pipe, &relay->status_msg.msg);
}
diff --git a/src/box/relay.h b/src/box/relay.h
index b32e2ea2a..615ffb75d 100644
--- a/src/box/relay.h
+++ b/src/box/relay.h
@@ -93,6 +93,12 @@ relay_vclock(const struct relay *relay);
double
relay_last_row_time(const struct relay *relay);
+/**
+ * Returns relay's transaction's lag.
+ */
+double
+relay_txn_lag(const struct relay *relay);
+
/**
* Send a Raft update request to the relay channel. It is not
* guaranteed that it will be delivered. The connection may break.
diff --git a/test/replication/gh-5447-downstream-lag.result b/test/replication/gh-5447-downstream-lag.result
new file mode 100644
index 000000000..0d5de2564
--- /dev/null
+++ b/test/replication/gh-5447-downstream-lag.result
@@ -0,0 +1,124 @@
+-- test-run result file version 2
+--
+-- gh-5447: Test for box.info.replication[n].downstream.lag.
+-- We need to be sure that slow ACKs delivery might be
+-- caught by monitoring tools.
+--
+
+fiber = require('fiber')
+ | ---
+ | ...
+test_run = require('test_run').new()
+ | ---
+ | ...
+engine = test_run:get_cfg('engine')
+ | ---
+ | ...
+
+box.schema.user.grant('guest', 'replication')
+ | ---
+ | ...
+
+test_run:cmd('create server replica with rpl_master=default, \
+ script="replication/replica.lua"')
+ | ---
+ | - true
+ | ...
+test_run:cmd('start server replica')
+ | ---
+ | - true
+ | ...
+
+replica_id = test_run:get_server_id('replica')
+ | ---
+ | ...
+
+--
+-- Upon replica startup there is no ACKs to process.
+assert(box.info.replication[replica_id].downstream.lag == 0)
+ | ---
+ | - true
+ | ...
+
+s = box.schema.space.create('test', {engine = engine})
+ | ---
+ | ...
+_ = s:create_index('pk')
+ | ---
+ | ...
+
+--
+-- The replica should wait some time before writing data
+-- to the WAL, otherwise we might not even notice the lag
+-- if media is too fast. Before disabling WAL we need to
+-- wait the space get propagated.
+test_run:switch('replica')
+ | ---
+ | - true
+ | ...
+test_run:wait_lsn('replica', 'default')
+ | ---
+ | ...
+box.error.injection.set("ERRINJ_WAL_DELAY", true)
+ | ---
+ | - ok
+ | ...
+
+--
+-- Insert a record and wakeup replica's WAL to process data.
+test_run:switch('default')
+ | ---
+ | - true
+ | ...
+box.space.test:insert({1})
+ | ---
+ | - [1]
+ | ...
+-- The record is written on the master node.
+test_run:switch('replica')
+ | ---
+ | - true
+ | ...
+box.error.injection.set("ERRINJ_WAL_DELAY", false)
+ | ---
+ | - ok
+ | ...
+
+--
+-- Wait the record to be ACKed, the lag value should be nonzero.
+test_run:switch('default')
+ | ---
+ | - true
+ | ...
+test_run:wait_lsn('replica', 'default')
+ | ---
+ | ...
+assert(box.info.replication[replica_id].downstream.lag > 0)
+ | ---
+ | - true
+ | ...
+
+--
+-- Cleanup everything.
+test_run:switch('default')
+ | ---
+ | - true
+ | ...
+box.space.test:drop()
+ | ---
+ | ...
+box.schema.user.revoke('guest', 'replication')
+ | ---
+ | ...
+test_run:cmd('stop server replica')
+ | ---
+ | - true
+ | ...
+test_run:cmd('cleanup server replica')
+ | ---
+ | - true
+ | ...
+test_run:cmd('delete server replica')
+ | ---
+ | - true
+ | ...
diff --git a/test/replication/gh-5447-downstream-lag.test.lua b/test/replication/gh-5447-downstream-lag.test.lua
new file mode 100644
index 000000000..dd1d2e2c9
--- /dev/null
+++ b/test/replication/gh-5447-downstream-lag.test.lua
@@ -0,0 +1,56 @@
+--
+-- gh-5447: Test for box.info.replication[n].downstream.lag.
+-- We need to be sure that slow ACKs delivery might be
+-- caught by monitoring tools.
+--
+
+fiber = require('fiber')
+test_run = require('test_run').new()
+engine = test_run:get_cfg('engine')
+
+box.schema.user.grant('guest', 'replication')
+
+test_run:cmd('create server replica with rpl_master=default, \
+ script="replication/replica.lua"')
+test_run:cmd('start server replica')
+
+replica_id = test_run:get_server_id('replica')
+
+--
+-- Upon replica startup there is no ACKs to process.
+assert(box.info.replication[replica_id].downstream.lag == 0)
+
+s = box.schema.space.create('test', {engine = engine})
+_ = s:create_index('pk')
+
+--
+-- The replica should wait some time before writing data
+-- to the WAL, otherwise we might not even notice the lag
+-- if media is too fast. Before disabling WAL we need to
+-- wait the space get propagated.
+test_run:switch('replica')
+test_run:wait_lsn('replica', 'default')
+box.error.injection.set("ERRINJ_WAL_DELAY", true)
+
+--
+-- Insert a record and wakeup replica's WAL to process data.
+test_run:switch('default')
+box.space.test:insert({1})
+-- The record is written on the master node.
+test_run:switch('replica')
+box.error.injection.set("ERRINJ_WAL_DELAY", false)
+
+--
+-- Wait the record to be ACKed, the lag value should be nonzero.
+test_run:switch('default')
+test_run:wait_lsn('replica', 'default')
+assert(box.info.replication[replica_id].downstream.lag > 0)
+
+--
+-- Cleanup everything.
+test_run:switch('default')
+box.space.test:drop()
+box.schema.user.revoke('guest', 'replication')
+test_run:cmd('stop server replica')
+test_run:cmd('cleanup server replica')
+test_run:cmd('delete server replica')
diff --git a/test/replication/suite.ini b/test/replication/suite.ini
index 40daa713b..7e478f7d0 100644
--- a/test/replication/suite.ini
+++ b/test/replication/suite.ini
@@ -3,7 +3,7 @@ core = tarantool
script = master.lua
description = tarantool/box, replication
disabled = consistent.test.lua
-release_disabled = catch.test.lua errinj.test.lua gc.test.lua gc_no_space.test.lua before_replace.test.lua qsync_advanced.test.lua qsync_errinj.test.lua quorum.test.lua recover_missing_xlog.test.lua sync.test.lua long_row_timeout.test.lua gh-4739-vclock-assert.test.lua gh-4730-applier-rollback.test.lua gh-5140-qsync-casc-rollback.test.lua gh-5144-qsync-dup-confirm.test.lua gh-5167-qsync-rollback-snap.test.lua gh-5506-election-on-off.test.lua gh-5536-wal-limit.test.lua hang_on_synchro_fail.test.lua anon_register_gap.test.lua gh-5213-qsync-applier-order.test.lua gh-5213-qsync-applier-order-3.test.lua gh-6027-applier-error-show.test.lua gh-6032-promote-wal-write.test.lua gh-6057-qsync-confirm-async-no-wal.test.lua
+release_disabled = catch.test.lua errinj.test.lua gc.test.lua gc_no_space.test.lua before_replace.test.lua qsync_advanced.test.lua qsync_errinj.test.lua quorum.test.lua recover_missing_xlog.test.lua sync.test.lua long_row_timeout.test.lua gh-4739-vclock-assert.test.lua gh-4730-applier-rollback.test.lua gh-5140-qsync-casc-rollback.test.lua gh-5144-qsync-dup-confirm.test.lua gh-5167-qsync-rollback-snap.test.lua gh-5506-election-on-off.test.lua gh-5536-wal-limit.test.lua hang_on_synchro_fail.test.lua anon_register_gap.test.lua gh-5213-qsync-applier-order.test.lua gh-5213-qsync-applier-order-3.test.lua gh-6027-applier-error-show.test.lua gh-6032-promote-wal-write.test.lua gh-6057-qsync-confirm-async-no-wal.test.lua gh-5447-downstream-lag.test.lua
config = suite.cfg
lua_libs = lua/fast_replica.lua lua/rlimit.lua
use_unix_sockets = True
--
2.31.1
More information about the Tarantool-patches
mailing list