[Tarantool-patches] [PATCH v4 2/2] relay: provide information about downstream lag
Cyrill Gorcunov
gorcunov at gmail.com
Fri May 7 00:41:32 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 -> ACK` path.
Typical ouput 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` is the time difference between
last transactions been written to the WAL journal of the transaction
initiator and the transaction written to WAL on the `n` replica.
In other words this is a lag in seconds between the main node writes
data to own WAL and replica `n` get this data replicated to the own
WAL journal.
This value is not a constant and if there is no data to replicate
(ie when nodes are sitting in idle cycle, or new heartbeat message
obtained) then it get set back to zero.
---
.../unreleased/gh-5447-downstream-lag.md | 6 ++
src/box/lua/info.c | 3 +
src/box/relay.cc | 18 ++++
src/box/relay.h | 6 ++
.../replication/gh-5447-downstream-lag.result | 93 +++++++++++++++++++
.../gh-5447-downstream-lag.test.lua | 41 ++++++++
6 files changed, 167 insertions(+)
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..3b11c50ee
--- /dev/null
+++ b/changelogs/unreleased/gh-5447-downstream-lag.md
@@ -0,0 +1,6 @@
+#feature/replication
+
+ * Introduce `box.info.replication[n].downstream.lag` to monitor state
+ of replication which is especially important for synchronous spaces
+ where malfunctioning replicas may prevent quorum from gathering votes
+ to commit a transaction.
diff --git a/src/box/lua/info.c b/src/box/lua/info.c
index 0eb48b823..5b7c25f28 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_lag(relay));
+ lua_settable(L, -3);
break;
case RELAY_STOPPED:
{
diff --git a/src/box/relay.cc b/src/box/relay.cc
index ff43c2fc7..1501e53c7 100644
--- a/src/box/relay.cc
+++ b/src/box/relay.cc
@@ -158,6 +158,12 @@ struct relay {
struct stailq pending_gc;
/** Time when last row was sent to peer. */
double last_row_time;
+ /**
+ * A time difference between moment when we
+ * wrote a row in the local WAL and received
+ * an ACK that peer has it replicated.
+ */
+ double lag;
/** Relay sync state. */
enum relay_state state;
@@ -217,6 +223,12 @@ relay_last_row_time(const struct relay *relay)
return relay->last_row_time;
}
+double
+relay_lag(const struct relay *relay)
+{
+ return relay->lag;
+}
+
static void
relay_send(struct relay *relay, struct xrow_header *packet);
static void
@@ -621,6 +633,12 @@ 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);
+ if (xrow.tm != 0) {
+ double delta = ev_now(loop()) - xrow.tm;
+ relay->lag = delta;
+ } else {
+ relay->lag = 0;
+ }
fiber_cond_signal(&relay->reader_cond);
}
} catch (Exception *e) {
diff --git a/src/box/relay.h b/src/box/relay.h
index b32e2ea2a..0f7d8d1bc 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 lag.
+ */
+double
+relay_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..8586d0ed3
--- /dev/null
+++ b/test/replication/gh-5447-downstream-lag.result
@@ -0,0 +1,93 @@
+-- test-run result file version 2
+--
+-- gh-5447: Test for box.info.replication[n].downstream.lag.
+-- We need to be sure that if replica start been back of
+-- master node reports own lagging and cluster admin would
+-- be able to detect such situation.
+--
+
+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
+ | ...
+
+s = box.schema.space.create('test', {engine = engine})
+ | ---
+ | ...
+_ = s:create_index('pk')
+ | ---
+ | ...
+
+--
+-- The replica should wait some time (wal delay is 1 second
+-- by default) so we would be able to detect the lag, since
+-- on local instances the lag is minimal and usually transactions
+-- are handled instantly.
+test_run:switch('replica')
+ | ---
+ | - true
+ | ...
+box.error.injection.set("ERRINJ_WAL_DELAY", true)
+ | ---
+ | - ok
+ | ...
+
+test_run:switch('default')
+ | ---
+ | - true
+ | ...
+box.space.test:insert({1})
+ | ---
+ | - [1]
+ | ...
+test_run:wait_cond(function() return box.info.replication[2].downstream.lag ~= 0 end, 10)
+ | ---
+ | - true
+ | ...
+
+test_run:switch('replica')
+ | ---
+ | - true
+ | ...
+box.error.injection.set("ERRINJ_WAL_DELAY", false)
+ | ---
+ | - ok
+ | ...
+--
+-- Cleanup everything.
+test_run:switch('default')
+ | ---
+ | - true
+ | ...
+
+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..650e8e215
--- /dev/null
+++ b/test/replication/gh-5447-downstream-lag.test.lua
@@ -0,0 +1,41 @@
+--
+-- gh-5447: Test for box.info.replication[n].downstream.lag.
+-- We need to be sure that if replica start been back of
+-- master node reports own lagging and cluster admin would
+-- be able to detect such situation.
+--
+
+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')
+
+s = box.schema.space.create('test', {engine = engine})
+_ = s:create_index('pk')
+
+--
+-- The replica should wait some time (wal delay is 1 second
+-- by default) so we would be able to detect the lag, since
+-- on local instances the lag is minimal and usually transactions
+-- are handled instantly.
+test_run:switch('replica')
+box.error.injection.set("ERRINJ_WAL_DELAY", true)
+
+test_run:switch('default')
+box.space.test:insert({1})
+test_run:wait_cond(function() return box.info.replication[2].downstream.lag ~= 0 end, 10)
+
+test_run:switch('replica')
+box.error.injection.set("ERRINJ_WAL_DELAY", false)
+--
+-- Cleanup everything.
+test_run:switch('default')
+
+test_run:cmd('stop server replica')
+test_run:cmd('cleanup server replica')
+test_run:cmd('delete server replica')
--
2.30.2
More information about the Tarantool-patches
mailing list