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

[Vladimir Davydov <vdavydov.dev@gmail.com>]

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