From b5734069de3eea25d1f557c86a99c2dbf0b98ffb Mon Sep 17 00:00:00 2001
From: Vladimir Davydov <vdavydov.dev@gmail.com>
Date: Thu, 11 Apr 2019 20:13:36 +0300
Subject: [PATCH] vinyl: take into account primary key lookup in latency
accounting
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.
---
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 e3286229c9..b9bf721ae5 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_read(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_read(it, start_time, entry.stmt);
if (entry.stmt == NULL) {
/* EOF. Close the iterator immediately. */
vinyl_iterator_close(it);
@@ -3795,6 +3832,8 @@ vinyl_iterator_primary_next(struct iterator *base, struct tuple **ret)
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 @@ vinyl_iterator_secondary_next(struct iterator *base, struct tuple **ret)
if (partial.stmt == NULL) {
/* EOF. Close the iterator immediately. */
vy_read_iterator_cache_add(&it->iterator, vy_entry_none());
+ vinyl_iterator_account_read(it, start_time, NULL);
vinyl_iterator_close(it);
*ret = NULL;
return 0;
@@ -3830,6 +3870,7 @@ vinyl_iterator_secondary_next(struct iterator *base, struct tuple **ret)
if (entry.stmt == NULL)
goto next;
vy_read_iterator_cache_add(&it->iterator, entry);
+ vinyl_iterator_account_read(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 39aad41f96..becc048689 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 @@ vy_point_lookup(struct vy_lsm *lsm, struct vy_tx *tx,
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 d6a5c65da1..b26750e902 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 @@ vy_read_iterator_next(struct vy_read_iterator *itr, struct vy_entry *result)
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 f4300333ef..f6d37769bc 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 bb61a9a58f..4820ef97c3 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()
--
GitLab