[PATCH] vinyl: take into account primary key lookup in latency accounting
Konstantin Osipov
kostja at tarantool.org
Thu Apr 11 23:04:34 MSK 2019
* Vladimir Davydov <vdavydov.dev at 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
More information about the Tarantool-patches
mailing list