From: Cyrill Gorcunov via Tarantool-patches <tarantool-patches@dev.tarantool.org> To: tml <tarantool-patches@dev.tarantool.org> Cc: Vladislav Shpilevoy <v.shpilevoy@tarantool.org> Subject: [Tarantool-patches] [PATCH v4 2/2] relay: provide information about downstream lag Date: Fri, 7 May 2021 00:41:32 +0300 [thread overview] Message-ID: <20210506214132.533913-3-gorcunov@gmail.com> (raw) In-Reply-To: <20210506214132.533913-1-gorcunov@gmail.com> 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@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
next prev parent reply other threads:[~2021-05-06 21:42 UTC|newest] Thread overview: 5+ messages / expand[flat|nested] mbox.gz Atom feed top 2021-05-06 21:41 [Tarantool-patches] [PATCH v4 0/2] relay: provide downstream lag information Cyrill Gorcunov via Tarantool-patches 2021-05-06 21:41 ` [Tarantool-patches] [PATCH v4 1/2] applier: send transaction's first row WAL time in the applier_writer_f Cyrill Gorcunov via Tarantool-patches 2021-05-12 19:59 ` Vladislav Shpilevoy via Tarantool-patches 2021-05-06 21:41 ` Cyrill Gorcunov via Tarantool-patches [this message] 2021-05-12 20:10 ` [Tarantool-patches] [PATCH v4 2/2] relay: provide information about downstream lag Vladislav Shpilevoy via Tarantool-patches
Reply instructions: You may reply publicly to this message via plain-text email using any one of the following methods: * Save the following mbox file, import it into your mail client, and reply-to-all from there: mbox Avoid top-posting and favor interleaved quoting: https://en.wikipedia.org/wiki/Posting_style#Interleaved_style * Reply using the --to, --cc, and --in-reply-to switches of git-send-email(1): git send-email \ --in-reply-to=20210506214132.533913-3-gorcunov@gmail.com \ --to=tarantool-patches@dev.tarantool.org \ --cc=gorcunov@gmail.com \ --cc=v.shpilevoy@tarantool.org \ --subject='Re: [Tarantool-patches] [PATCH v4 2/2] relay: provide information about downstream lag' \ /path/to/YOUR_REPLY https://kernel.org/pub/software/scm/git/docs/git-send-email.html * If your mail client supports setting the In-Reply-To header via mailto: links, try the mailto: link
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox