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

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

[Vladimir Davydov]

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.

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

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

[Konstantin Osipov]

* 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

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

[Vladimir Davydov]

On Thu, Apr 11, 2019 at 11:04:34PM +0300, Konstantin Osipov wrote:
> * 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 :)

It doesn't. I just moves latency accounting to the upper level to take
into account the time spent on skipping deferred DELETEs. It still uses
ev_monotonic_now for latency accounting.

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

[Vladimir Davydov]

Pushed to master, 2.1, 1.10.