From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Date: Thu, 11 Apr 2019 23:04:34 +0300 From: Konstantin Osipov Subject: Re: [PATCH] vinyl: take into account primary key lookup in latency accounting Message-ID: <20190411200434.GB25603@chai> References: MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: To: Vladimir Davydov Cc: tarantool-patches@freelists.org List-ID: * Vladimir Davydov [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='") > ---- > -- true > -... > test_run:grep_log('default', 'get.* took too long') > --- > -- get([10]) => INSERT([10, 20], 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=) 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='") > 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