Re: [Tarantool-patches] [PATCH v2 2/3] box/info: report replication.X.downstream.lag value

[Serge Petrenko via Tarantool-patches <tarantool-patches@dev.tarantool.org>]

01.02.2021 13:00, Cyrill Gorcunov пишет:
> This is basically a reflection of replication.X.upstream.lag value.
> The upstream lag can be considered as transaction RTT in direction
> from master to replica, in turn downstream lag is the reverse and
> represents RTT from replica to master.
>
> An example of output is (on replica node)
>
>   | 2:
>   |   id: 2
>   |   uuid: 8bb22366-cd21-492e-98df-693884be11bd
>   |   lsn: 0
>   |   downstream:
>   |     status: follow
>   |     idle: 0.55381065199617
>   |     vclock: {1: 119}
>   |     lag: 0.00019168853759766
>
> In case if there some old replicas which are not sending
> timestamp in vclock encoding we simply don't show lag
> field for backward compatibility sake.
>
> Closes #5447
>
> @TarantoolBot document
> Title: Document box.info.replication[n].downstream.lag
>
> replication[n].downstream.lag is time difference between
> local time of the replica `n` sending current vector clock
> state and the time this message was received by a master
> node.
>
> Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
> ---

Hi! Thanks for the patch! Generally looks good, however, I have a comment.

Actually, what you're counting here is not related to upstream lag.
Upstream lag is the difference between master's WAL write time and
replica's time at the moment of receiving the entry. So it may indicate
how much the replica has fallen behind master. This is a meaningful value,
which may be quite high when the replica is syncing with master.

Downstream lag, as you count it, is simply the time it took a network 
packet to
travel from replica to master. It doesn't show anything about replica's 
status
as compared to master. So there's not much value in it.

Sorry for noticing this so late. I had some magic representation of how 
it should
work in my head and didn't look into the patch thoroughly enough.

This is not what the ticket was about. I see two options here:
1) you may simply send applier lag in row->tm, and save it in relay->lag.
    This way downstream.lag on master will be the same as upstream.lag 
on replica,
    so it'll be just a helper, but still better than what we have now.
2) We need to measure difference between transaction WAL write time and the
    time we received an ACK for this transaction. This may be too 
complicated for
    async transactions, since you need to remember times for a bunch of 
already
    committed transactions. So this will make sense only for synchronous 
transactions
    and qsync statistics.

I personally prefer option 1 now, as a counterpart of upstream.lag on 
master, and
option 2 as a part of qsync statistics ticket. But maybe we don't need 
(2) at all.

>   src/box/lua/info.c |  8 ++++++++
>   src/box/relay.cc   | 16 ++++++++++++++++
>   src/box/relay.h    |  8 ++++++++
>   3 files changed, 32 insertions(+)
>
> diff --git a/src/box/lua/info.c b/src/box/lua/info.c
> index c4c9fa0a0..1e533fe8d 100644
> --- a/src/box/lua/info.c
> +++ b/src/box/lua/info.c
> @@ -133,16 +133,24 @@ lbox_pushrelay(lua_State *L, struct relay *relay)
>   
>   	switch(relay_get_state(relay)) {
>   	case RELAY_FOLLOW:
> +	{
> +		double lag = relay_lag(relay);
>   		lua_pushstring(L, "follow");
>   		lua_settable(L, -3);
>   		lua_pushstring(L, "vclock");
>   		lbox_pushvclock(L, relay_vclock(relay));
>   		lua_settable(L, -3);
> +		if (lag != 0) {
> +			lua_pushstring(L, "lag");
> +			lua_pushnumber(L, relay_lag(relay));
> +			lua_settable(L, -3);
> +		}
>   		lua_pushstring(L, "idle");
>   		lua_pushnumber(L, ev_monotonic_now(loop()) -
>   			       relay_last_row_time(relay));
>   		lua_settable(L, -3);
>   		break;
> +	}
>   	case RELAY_STOPPED:
>   	{
>   		lua_pushstring(L, "stopped");
> diff --git a/src/box/relay.cc b/src/box/relay.cc
> index df04f8198..f23e43b30 100644
> --- a/src/box/relay.cc
> +++ b/src/box/relay.cc
> @@ -138,6 +138,8 @@ struct relay {
>   	struct stailq pending_gc;
>   	/** Time when last row was sent to peer. */
>   	double last_row_time;
> +	/** Number of seconds this master is prior the remote replica. */
> +	double lag;
>   	/** Relay sync state. */
>   	enum relay_state state;
>   
> @@ -179,6 +181,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
> @@ -219,6 +227,7 @@ relay_start(struct relay *relay, int fd, uint64_t sync,
>   	relay->sync = sync;
>   	relay->state = RELAY_FOLLOW;
>   	relay->last_row_time = ev_monotonic_now(loop());
> +	relay->lag = 0;
>   }
>   
>   void
> @@ -558,6 +567,13 @@ 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);
> +			/*
> +			 * Old versions may send not a timestamp but
> +			 * zeroified memory field. We can use +0 as
> +			 * a sign that there is nothing encoded.
> +			 */
> +			if (xrow.tm != 0)
> +				relay->lag = ev_now(loop()) - xrow.tm;
>   			fiber_cond_signal(&relay->reader_cond);
>   		}
>   	} catch (Exception *e) {
> diff --git a/src/box/relay.h b/src/box/relay.h
> index b32e2ea2a..ec9d16925 100644
> --- a/src/box/relay.h
> +++ b/src/box/relay.h
> @@ -93,6 +93,14 @@ relay_vclock(const struct relay *relay);
>   double
>   relay_last_row_time(const struct relay *relay);
>   
> +/**
> + * Returns relay's lag
> + * @param 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.

-- 
Serge Petrenko