From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from [87.239.111.99] (localhost [127.0.0.1]) by dev.tarantool.org (Postfix) with ESMTP id AE79B6EC58; Tue, 22 Jun 2021 18:23:52 +0300 (MSK) DKIM-Filter: OpenDKIM Filter v2.11.0 dev.tarantool.org AE79B6EC58 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=tarantool.org; s=dev; t=1624375432; bh=TtLgshneyQWEmqsoOhRbgsqevVtpMXImgDGLDhf7+UQ=; h=To:Date:In-Reply-To:References:Subject:List-Id:List-Unsubscribe: List-Archive:List-Post:List-Help:List-Subscribe:From:Reply-To:Cc: From; b=N8QtQo0Y0oVxUZ7E5RnAbzSQTdj+PeRRWZVLcywy/kLRtwpQL355Yef0N5S2KUBy9 bqw6fMe/kjMcKQkdEA4K2Djov1mWhXwxqFqpRy9Lubr/Vb4lwWvbYZ4VpJWI8MBypf 06gTOQaiVdHk5w2PGC6yWfRwc1f4hMoNZzZk5dEk= Received: from mail-lj1-f172.google.com (mail-lj1-f172.google.com [209.85.208.172]) (using TLSv1.3 with cipher TLS_AES_128_GCM_SHA256 (128/128 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256) (No client certificate requested) by dev.tarantool.org (Postfix) with ESMTPS id A24BD6EC5F for ; Tue, 22 Jun 2021 18:23:14 +0300 (MSK) DKIM-Filter: OpenDKIM Filter v2.11.0 dev.tarantool.org A24BD6EC5F Received: by mail-lj1-f172.google.com with SMTP id d25so2614875lji.7 for ; Tue, 22 Jun 2021 08:23:14 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=Y6T8Ylxg/smIuwHHdQQY5Iug/W4UZ+lhMMgjHVBMlGk=; b=Z5a1SSbErcfeHiIx3QiaOA26Yr2WRksqLz6LDUmn/PPTVg8iwWv/hd3lygYGTiWfiM zXsqUxNYq63IuTvXqr/8DJsyRbN4J89doKY2s/I2LTOWfzr/skuN73ZN+ZB3HPUzsGxA gpr9PeTq80YP/cCwynbL5a26nymysLDiLg1RvNmXWrynWizMHugIxIXiOFaUq55BFT+W sANPrwKbHsYQ5BdjSPJ9923Oz0UafH1QDtbNhcFwHEIWq2t8NGWS13tUCMpuMZkY7Hj8 EkE152/fs+j3HXPzyscJi3v+3hHoF4TnKSkFQgRtAz/PocQg0CN3nzK8IJHEkQsfhgH4 B50g== X-Gm-Message-State: AOAM530ucAbfV2E8iu40OuAvy2KCHlaoXlRI4yTb8ATLZwEC9L2AFYce eJKaA/0eVEGxxVt76kJiOfh8RnB0c3Y= X-Google-Smtp-Source: ABdhPJzlydhiJtb4mSLsOceH4Pf0O7OuBFVhfHFg8e8ncMQp1VK/QYoO8YPCVqjaub/lLaAbtaY1zg== X-Received: by 2002:a2e:a4a4:: with SMTP id g4mr3706781ljm.376.1624375393703; Tue, 22 Jun 2021 08:23:13 -0700 (PDT) Received: from grain.localdomain ([5.18.199.94]) by smtp.gmail.com with ESMTPSA id o2sm198115ljj.24.2021.06.22.08.23.12 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Tue, 22 Jun 2021 08:23:12 -0700 (PDT) Received: by grain.localdomain (Postfix, from userid 1000) id 1C7665A0022; Tue, 22 Jun 2021 18:22:48 +0300 (MSK) To: tml Date: Tue, 22 Jun 2021 18:22:46 +0300 Message-Id: <20210622152246.497955-3-gorcunov@gmail.com> X-Mailer: git-send-email 2.31.1 In-Reply-To: <20210622152246.497955-1-gorcunov@gmail.com> References: <20210622152246.497955-1-gorcunov@gmail.com> MIME-Version: 1.0 Content-Transfer-Encoding: 8bit Subject: [Tarantool-patches] [PATCH v10 2/2] relay: provide information about downstream lag X-BeenThere: tarantool-patches@dev.tarantool.org X-Mailman-Version: 2.1.34 Precedence: list List-Id: Tarantool development patches List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , From: Cyrill Gorcunov via Tarantool-patches Reply-To: Cyrill Gorcunov Cc: Vladislav Shpilevoy Errors-To: tarantool-patches-bounces@dev.tarantool.org Sender: "Tarantool-patches" 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 @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