diff --git a/src/box/box.cc b/src/box/box.cc
index 80fda4c587925f6b4dd22dac5c1f94c193a6990c..4e921f769179cde3e5c8b3432a3aa8199ef35b7c 100644
--- a/src/box/box.cc
+++ b/src/box/box.cc
@@ -614,6 +614,11 @@ void
box_set_too_long_threshold(void)
{
too_long_threshold = cfg_getd("too_long_threshold");
+
+ struct vinyl_engine *vinyl;
+ vinyl = (struct vinyl_engine *)engine_by_name("vinyl");
+ assert(vinyl != NULL);
+ vinyl_engine_set_too_long_threshold(vinyl, too_long_threshold);
}
void
@@ -1432,10 +1437,10 @@ engine_init()
cfg_geti64("vinyl_cache"),
cfg_geti("vinyl_read_threads"),
cfg_geti("vinyl_write_threads"),
- cfg_getd("vinyl_timeout"),
cfg_geti("force_recovery"));
engine_register((struct engine *)vinyl);
box_set_vinyl_max_tuple_size();
+ box_set_vinyl_timeout();
}
/**
diff --git a/src/box/vinyl.c b/src/box/vinyl.c
index 5fafa4ebc39dd6e1cfee9165fc6e1bdd3b1651e3..f4dc48d532a3722a00007108461e71b2d3123405 100644
--- a/src/box/vinyl.c
+++ b/src/box/vinyl.c
@@ -149,6 +149,11 @@ struct vy_env {
size_t memory;
/** Max time a transaction may wait for memory. */
double timeout;
+ /**
+ * If read of a single statement takes longer than
+ * the given value, warn about it in the log.
+ */
+ double too_long_threshold;
/** Max number of threads used for reading. */
int read_threads;
/** Max number of threads used for writing. */
@@ -1246,8 +1251,8 @@ vy_index_get(struct vy_env *env, struct vy_tx *tx, struct vy_index *index,
}
struct vy_read_iterator itr;
- vy_read_iterator_open(&itr, &env->run_env, index, tx,
- ITER_EQ, vykey, p_read_view);
+ vy_read_iterator_open(&itr, &env->run_env, index, tx, ITER_EQ, vykey,
+ p_read_view, env->too_long_threshold);
int rc = vy_read_iterator_next(&itr, result);
tuple_unref(vykey);
if (*result != NULL)
@@ -2570,8 +2575,8 @@ vy_squash_schedule(struct vy_index *index, struct tuple *stmt,
void /* struct vy_env */ *arg);
static struct vy_env *
-vy_env_new(const char *path, size_t memory, size_t cache, int read_threads,
- int write_threads, double timeout, bool force_recovery)
+vy_env_new(const char *path, size_t memory, size_t cache,
+ int read_threads, int write_threads, bool force_recovery)
{
enum { KB = 1000, MB = 1000 * 1000 };
static int64_t dump_bandwidth_buckets[] = {
@@ -2596,7 +2601,8 @@ vy_env_new(const char *path, size_t memory, size_t cache, int read_threads,
memset(e, 0, sizeof(*e));
e->status = VINYL_OFFLINE;
e->memory = memory;
- e->timeout = timeout;
+ e->timeout = TIMEOUT_INFINITY;
+ e->too_long_threshold = TIMEOUT_INFINITY;
e->read_threads = read_threads;
e->write_threads = write_threads;
e->force_recovery = force_recovery;
@@ -2689,8 +2695,7 @@ vy_env_delete(struct vy_env *e)
struct vinyl_engine *
vinyl_engine_new(const char *dir, size_t memory, size_t cache,
- int read_threads, int write_threads, double timeout,
- bool force_recovery)
+ int read_threads, int write_threads, bool force_recovery)
{
struct vinyl_engine *vinyl = calloc(1, sizeof(*vinyl));
if (vinyl == NULL) {
@@ -2700,7 +2705,7 @@ vinyl_engine_new(const char *dir, size_t memory, size_t cache,
}
vinyl->env = vy_env_new(dir, memory, cache, read_threads,
- write_threads, timeout, force_recovery);
+ write_threads, force_recovery);
if (vinyl->env == NULL) {
free(vinyl);
return NULL;
@@ -2732,6 +2737,13 @@ vinyl_engine_set_timeout(struct vinyl_engine *vinyl, double timeout)
vinyl->env->timeout = timeout;
}
+void
+vinyl_engine_set_too_long_threshold(struct vinyl_engine *vinyl,
+ double too_long_threshold)
+{
+ vinyl->env->too_long_threshold = too_long_threshold;
+}
+
/** }}} Environment */
/* {{{ Checkpoint */
@@ -3521,7 +3533,8 @@ vy_squash_process(struct vy_squash *squash)
* prepared, but not committed statements.
*/
vy_read_iterator_open(&itr, &env->run_env, index, NULL, ITER_EQ,
- squash->stmt, &env->xm->p_committed_read_view);
+ squash->stmt, &env->xm->p_committed_read_view,
+ env->too_long_threshold);
struct tuple *result;
int rc = vy_read_iterator_next(&itr, &result);
if (rc == 0 && result != NULL)
@@ -3908,7 +3921,8 @@ vinyl_index_create_iterator(struct index *base, enum iterator_type type,
vy_read_iterator_open(&it->iterator, &env->run_env,
index, tx, type, it->key,
- (const struct vy_read_view **)&tx->read_view);
+ (const struct vy_read_view **)&tx->read_view,
+ env->too_long_threshold);
return (struct iterator *)it;
}
diff --git a/src/box/vinyl.h b/src/box/vinyl.h
index c8c07dfd99158ca7727bbd670963f150628ed359..63add146b60c8e73d448518b3aebf62b9927e429 100644
--- a/src/box/vinyl.h
+++ b/src/box/vinyl.h
@@ -43,8 +43,7 @@ struct vinyl_engine;
struct vinyl_engine *
vinyl_engine_new(const char *dir, size_t memory, size_t cache,
- int read_threads, int write_threads, double timeout,
- bool force_recovery);
+ int read_threads, int write_threads, bool force_recovery);
/**
* Engine introspection (box.info.vinyl())
@@ -64,6 +63,13 @@ vinyl_engine_set_max_tuple_size(struct vinyl_engine *vinyl, size_t max_size);
void
vinyl_engine_set_timeout(struct vinyl_engine *vinyl, double timeout);
+/**
+ * Update too_long_threshold.
+ */
+void
+vinyl_engine_set_too_long_threshold(struct vinyl_engine *vinyl,
+ double too_long_threshold);
+
#ifdef __cplusplus
} /* extern "C" */
@@ -71,12 +77,11 @@ vinyl_engine_set_timeout(struct vinyl_engine *vinyl, double timeout);
static inline struct vinyl_engine *
vinyl_engine_new_xc(const char *dir, size_t memory, size_t cache,
- int read_threads, int write_threads, double timeout,
- bool force_recovery)
+ int read_threads, int write_threads, bool force_recovery)
{
struct vinyl_engine *vinyl;
vinyl = vinyl_engine_new(dir, memory, cache, read_threads,
- write_threads, timeout, force_recovery);
+ write_threads, force_recovery);
if (vinyl == NULL)
diag_raise();
return vinyl;
diff --git a/src/box/vy_read_iterator.c b/src/box/vy_read_iterator.c
index f9b85802d9ebdafdd4f12eac38d003061ec4a8e8..14ac9f7546e305b89d5c98f81da9bc7e84500dad 100644
--- a/src/box/vy_read_iterator.c
+++ b/src/box/vy_read_iterator.c
@@ -575,7 +575,7 @@ void
vy_read_iterator_open(struct vy_read_iterator *itr, struct vy_run_env *run_env,
struct vy_index *index, struct vy_tx *tx,
enum iterator_type iterator_type, struct tuple *key,
- const struct vy_read_view **rv)
+ const struct vy_read_view **rv, double too_long_threshold)
{
memset(itr, 0, sizeof(*itr));
@@ -585,6 +585,7 @@ vy_read_iterator_open(struct vy_read_iterator *itr, struct vy_run_env *run_env,
itr->iterator_type = iterator_type;
itr->key = key;
itr->read_view = rv;
+ itr->too_long_threshold = too_long_threshold;
if (tuple_field_count(key) == 0) {
/*
@@ -888,8 +889,15 @@ vy_read_iterator_next(struct vy_read_iterator *itr, struct tuple **result)
if (prev_key != NULL)
tuple_unref(prev_key);
- latency_collect(&index->stat.latency,
- ev_monotonic_now(loop()) - start_time);
+ ev_tstamp latency = ev_monotonic_now(loop()) - start_time;
+ latency_collect(&index->stat.latency, latency);
+
+ if (latency > itr->too_long_threshold) {
+ say_warn("%s: select(%s, %s) => %s took too long: %.3f sec",
+ vy_index_name(index), tuple_str(itr->key),
+ iterator_type_strs[itr->iterator_type],
+ vy_stmt_str(itr->last_stmt), latency);
+ }
return rc;
}
diff --git a/src/box/vy_read_iterator.h b/src/box/vy_read_iterator.h
index 51ebc33db0b47aecf8e11a0074db112f4ca5f704..344e457c8b56ae9cbf238f00295585c8cb904809 100644
--- a/src/box/vy_read_iterator.h
+++ b/src/box/vy_read_iterator.h
@@ -59,6 +59,11 @@ struct vy_read_iterator {
struct tuple *key;
/** Read view the iterator lives in. */
const struct vy_read_view **read_view;
+ /**
+ * If a read iteration takes longer than the given value,
+ * warn about it in the log.
+ */
+ double too_long_threshold;
/**
* Set if the resulting statement needs to be
* checked to match the search key.
@@ -128,7 +133,7 @@ void
vy_read_iterator_open(struct vy_read_iterator *itr, struct vy_run_env *run_env,
struct vy_index *index, struct vy_tx *tx,
enum iterator_type iterator_type, struct tuple *key,
- const struct vy_read_view **rv);
+ const struct vy_read_view **rv, double too_long_threshold);
/**
* Get the next statement with another key, or start the iterator,
diff --git a/test/vinyl/errinj.result b/test/vinyl/errinj.result
index 4a5bc14d07c71c81aeff4d8491e3b1900ad15796..9f4c82c178b96e8eee1dfe3d81ea1d39112fcd8d 100644
--- a/test/vinyl/errinj.result
+++ b/test/vinyl/errinj.result
@@ -282,6 +282,40 @@ s:select()
- [9, 'test str9']
- [10, 'test str10']
...
+-- gh-2871: check that long reads are logged
+too_long_threshold = box.cfg.too_long_threshold
+---
+...
+box.cfg{too_long_threshold = 0.01}
+---
+...
+errinj.set("ERRINJ_VY_READ_PAGE_TIMEOUT", true)
+---
+- ok
+...
+#s:select(5, {iterator = 'LE'}) == 5
+---
+- true
+...
+errinj.set("ERRINJ_VY_READ_PAGE_TIMEOUT", false);
+---
+- ok
+...
+test_run:cmd("push filter 'lsn=[0-9]+' to 'lsn=<lsn>'")
+---
+- true
+...
+test_run:grep_log('default', 'select.* took too long')
+---
+- select([5], LE) => REPLACE([5, "test str5"], lsn=<lsn>) took too long
+...
+test_run:cmd("clear filter")
+---
+- true
+...
+box.cfg{too_long_threshold = too_long_threshold}
+---
+...
s:drop()
---
...
diff --git a/test/vinyl/errinj.test.lua b/test/vinyl/errinj.test.lua
index 5def06a0ec96ada67406a3dd835b27af7a937109..98d31182013e8e7c864576eec8a933294b6262b1 100644
--- a/test/vinyl/errinj.test.lua
+++ b/test/vinyl/errinj.test.lua
@@ -95,6 +95,18 @@ fiber.sleep(0.1)
errinj.set("ERRINJ_VY_READ_PAGE_TIMEOUT", false);
errinj.set("ERRINJ_VY_READ_PAGE", false);
s:select()
+
+-- gh-2871: check that long reads are logged
+too_long_threshold = box.cfg.too_long_threshold
+box.cfg{too_long_threshold = 0.01}
+errinj.set("ERRINJ_VY_READ_PAGE_TIMEOUT", true)
+#s:select(5, {iterator = 'LE'}) == 5
+errinj.set("ERRINJ_VY_READ_PAGE_TIMEOUT", false);
+test_run:cmd("push filter 'lsn=[0-9]+' to 'lsn=<lsn>'")
+test_run:grep_log('default', 'select.* took too long')
+test_run:cmd("clear filter")
+box.cfg{too_long_threshold = too_long_threshold}
+
s:drop()
s = box.schema.space.create('test', {engine='vinyl'});