From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: From: Vladimir Davydov Subject: [PATCH] vinyl: take into account primary key lookup in latency accounting Date: Thu, 11 Apr 2019 20:24:29 +0300 Message-Id: To: kostja@tarantool.org Cc: tarantool-patches@freelists.org List-ID: 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='") ---- -- 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