Re: [PATCH] vinyl: take into account primary key lookup in latency accounting

[Konstantin Osipov <kostja@tarantool.org>]

* Vladimir Davydov <vdavydov.dev@gmail.com> [19/04/11 20:29]:
> Currently, latency accounting and warning lives in vy_point_lookup and
> vy_read_iterator_next. As a result, we don't take into account full by
> partial tuple lookup in it while it can take quite a while, especially
> if there are lots of deferred DELETE statements we have to skip. So this
> patch moves latency accounting to the upper level, namely to vy_get and
> vinyl_iterator_{primary,secondary}_next.

I believe this si a temporary patch as long as it uses
clock_monotonic :)

please push with a comment that it's a tmp commit.
> 
> Note, as a side effect, now we always print full tuples to the log on
> "too long" warning. Besides, we strip LSN and statement type as those
> don't make much sense anymore.
> ---
> https://github.com/tarantool/tarantool/commits/dv/vy-fix-latency-accounting
> 
>  src/box/vinyl.c            | 47 +++++++++++++++++++++++++++++++++++++++++++---
>  src/box/vy_point_lookup.c  | 10 ----------
>  src/box/vy_read_iterator.c | 13 -------------
>  test/vinyl/errinj.result   | 12 ++----------
>  test/vinyl/errinj.test.lua |  2 --
>  5 files changed, 46 insertions(+), 38 deletions(-)
> 
> diff --git a/src/box/vinyl.c b/src/box/vinyl.c
> index e3286229..82116a57 100644
> --- a/src/box/vinyl.c
> +++ b/src/box/vinyl.c
> @@ -1421,6 +1421,7 @@ vy_get(struct vy_lsm *lsm, struct vy_tx *tx,
>         const struct vy_read_view **rv,
>         struct tuple *key_stmt, struct tuple **result)
>  {
> +	double start_time = ev_monotonic_now(loop());
>  	/*
>  	 * tx can be NULL, for example, if an user calls
>  	 * space.index.get({key}).
> @@ -1455,8 +1456,7 @@ vy_get(struct vy_lsm *lsm, struct vy_tx *tx,
>  			vy_cache_add(&lsm->cache, entry,
>  				     vy_entry_none(), key, ITER_EQ);
>  		}
> -		*result = entry.stmt;
> -		return 0;
> +		goto out;
>  	}
>  
>  	struct vy_read_iterator itr;
> @@ -1475,8 +1475,21 @@ vy_get(struct vy_lsm *lsm, struct vy_tx *tx,
>  	if (rc == 0)
>  		vy_read_iterator_cache_add(&itr, entry);
>  	vy_read_iterator_close(&itr);
> +	if (rc != 0)
> +		return -1;
> +out:
>  	*result = entry.stmt;
> -	return rc;
> +
> +	double latency = ev_monotonic_now(loop()) - start_time;
> +	latency_collect(&lsm->stat.latency, latency);
> +
> +	if (latency > lsm->env->too_long_threshold) {
> +		say_warn_ratelimited("%s: get(%s) => %s "
> +				     "took too long: %.3f sec",
> +				     vy_lsm_name(lsm), tuple_str(key.stmt),
> +				     tuple_str(*result), latency);
> +	}
> +	return 0;
>  }
>  
>  /**
> @@ -3766,9 +3779,32 @@ vinyl_iterator_check_tx(struct vinyl_iterator *it)
>  	return 0;
>  }
>  
> +static void
> +vinyl_iterator_account_latency(struct vinyl_iterator *it, double start_time,
> +			       struct tuple *result)
> +{
> +	struct vy_lsm *lsm = it->iterator.lsm;
> +	struct tuple *key = it->iterator.key.stmt;
> +	enum iterator_type type = it->iterator.iterator_type;
> +
> +	double latency = ev_monotonic_now(loop()) - start_time;
> +	latency_collect(&lsm->stat.latency, latency);
> +
> +	if (latency > lsm->env->too_long_threshold) {
> +		say_warn_ratelimited("%s: select(%s, %s) => %s "
> +				     "took too long: %.3f sec",
> +				     vy_lsm_name(lsm), tuple_str(key),
> +				     iterator_type_strs[type],
> +				     tuple_str(result), latency);
> +	}
> +
> +}
> +
>  static int
>  vinyl_iterator_primary_next(struct iterator *base, struct tuple **ret)
>  {
> +	double start_time = ev_monotonic_now(loop());
> +
>  	assert(base->next = vinyl_iterator_primary_next);
>  	struct vinyl_iterator *it = (struct vinyl_iterator *)base;
>  	assert(it->lsm->index_id == 0);
> @@ -3779,6 +3815,7 @@ vinyl_iterator_primary_next(struct iterator *base, struct tuple **ret)
>  	if (vy_read_iterator_next(&it->iterator, &entry) != 0)
>  		goto fail;
>  	vy_read_iterator_cache_add(&it->iterator, entry);
> +	vinyl_iterator_account_latency(it, start_time, entry.stmt);
>  	if (entry.stmt == NULL) {
>  		/* EOF. Close the iterator immediately. */
>  		vinyl_iterator_close(it);
> @@ -3795,6 +3832,8 @@ fail:
>  static int
>  vinyl_iterator_secondary_next(struct iterator *base, struct tuple **ret)
>  {
> +	double start_time = ev_monotonic_now(loop());
> +
>  	assert(base->next = vinyl_iterator_secondary_next);
>  	struct vinyl_iterator *it = (struct vinyl_iterator *)base;
>  	assert(it->lsm->index_id > 0);
> @@ -3810,6 +3849,7 @@ next:
>  	if (partial.stmt == NULL) {
>  		/* EOF. Close the iterator immediately. */
>  		vy_read_iterator_cache_add(&it->iterator, vy_entry_none());
> +		vinyl_iterator_account_latency(it, start_time, NULL);
>  		vinyl_iterator_close(it);
>  		*ret = NULL;
>  		return 0;
> @@ -3830,6 +3870,7 @@ next:
>  	if (entry.stmt == NULL)
>  		goto next;
>  	vy_read_iterator_cache_add(&it->iterator, entry);
> +	vinyl_iterator_account_latency(it, start_time, entry.stmt);
>  	*ret = entry.stmt;
>  	tuple_bless(*ret);
>  	tuple_unref(*ret);
> diff --git a/src/box/vy_point_lookup.c b/src/box/vy_point_lookup.c
> index 39aad41f..becc0486 100644
> --- a/src/box/vy_point_lookup.c
> +++ b/src/box/vy_point_lookup.c
> @@ -201,7 +201,6 @@ vy_point_lookup(struct vy_lsm *lsm, struct vy_tx *tx,
>  	assert(tx == NULL || tx->state == VINYL_TX_READY);
>  
>  	*ret = vy_entry_none();
> -	double start_time = ev_monotonic_now(loop());
>  	int rc = 0;
>  
>  	lsm->stat.lookup++;
> @@ -298,15 +297,6 @@ done:
>  	if (ret->stmt != NULL)
>  		vy_stmt_counter_acct_tuple(&lsm->stat.get, ret->stmt);
>  
> -	double latency = ev_monotonic_now(loop()) - start_time;
> -	latency_collect(&lsm->stat.latency, latency);
> -
> -	if (latency > lsm->env->too_long_threshold) {
> -		say_warn_ratelimited("%s: get(%s) => %s "
> -				     "took too long: %.3f sec",
> -				     vy_lsm_name(lsm), tuple_str(key.stmt),
> -				     vy_stmt_str(ret->stmt), latency);
> -	}
>  	return 0;
>  }
>  
> diff --git a/src/box/vy_read_iterator.c b/src/box/vy_read_iterator.c
> index d6a5c65d..b26750e9 100644
> --- a/src/box/vy_read_iterator.c
> +++ b/src/box/vy_read_iterator.c
> @@ -857,8 +857,6 @@ vy_read_iterator_next(struct vy_read_iterator *itr, struct vy_entry *result)
>  {
>  	assert(itr->tx == NULL || itr->tx->state == VINYL_TX_READY);
>  
> -	ev_tstamp start_time = ev_monotonic_now(loop());
> -
>  	struct vy_lsm *lsm = itr->lsm;
>  	struct vy_entry entry;
>  
> @@ -898,17 +896,6 @@ next_key:
>  	if (entry.stmt != NULL)
>  		vy_stmt_counter_acct_tuple(&lsm->stat.get, entry.stmt);
>  
> -	ev_tstamp latency = ev_monotonic_now(loop()) - start_time;
> -	latency_collect(&lsm->stat.latency, latency);
> -
> -	if (latency > lsm->env->too_long_threshold) {
> -		say_warn_ratelimited("%s: select(%s, %s) => %s "
> -				     "took too long: %.3f sec",
> -				     vy_lsm_name(lsm), tuple_str(itr->key.stmt),
> -				     iterator_type_strs[itr->iterator_type],
> -				     vy_stmt_str(entry.stmt), latency);
> -	}
> -
>  	*result = entry;
>  	return 0;
>  }
> diff --git a/test/vinyl/errinj.result b/test/vinyl/errinj.result
> index f4300333..f6d37769 100644
> --- a/test/vinyl/errinj.result
> +++ b/test/vinyl/errinj.result
> @@ -314,21 +314,13 @@ errinj.set("ERRINJ_VY_READ_PAGE_TIMEOUT", 0);
>  ---
>  - ok
>  ...
> -test_run:cmd("push filter 'lsn=[0-9]+' to 'lsn=<lsn>'")
> ----
> -- true
> -...
>  test_run:grep_log('default', 'get.* took too long')
>  ---
> -- get([10]) => INSERT([10, 20], lsn=<lsn>) took too long
> +- get([10]) => [10, 20] took too long
>  ...
>  test_run:grep_log('default', 'select.* took too long')
>  ---
> -- select([5], LE) => INSERT([5, 10], lsn=<lsn>) took too long
> -...
> -test_run:cmd("clear filter")
> ----
> -- true
> +- select([5], LE) => [5, 10] took too long
>  ...
>  box.cfg{too_long_threshold = too_long_threshold}
>  ---
> diff --git a/test/vinyl/errinj.test.lua b/test/vinyl/errinj.test.lua
> index bb61a9a5..4820ef97 100644
> --- a/test/vinyl/errinj.test.lua
> +++ b/test/vinyl/errinj.test.lua
> @@ -110,10 +110,8 @@ errinj.set("ERRINJ_VY_READ_PAGE_TIMEOUT", 0.05)
>  s:get(10) ~= nil
>  #s:select(5, {iterator = 'LE'}) == 5
>  errinj.set("ERRINJ_VY_READ_PAGE_TIMEOUT", 0);
> -test_run:cmd("push filter 'lsn=[0-9]+' to 'lsn=<lsn>'")
>  test_run:grep_log('default', 'get.* took too long')
>  test_run:grep_log('default', 'select.* took too long')
> -test_run:cmd("clear filter")
>  box.cfg{too_long_threshold = too_long_threshold}
>  
>  s:drop()
> -- 
> 2.11.0
> 

-- 
Konstantin Osipov, Moscow, Russia, +7 903 626 22 32
http://tarantool.io - www.twitter.com/kostja_osipov