[PATCH] vinyl: warn when transaction waits for quota for too long

[Vladimir Davydov]

If a vinyl transaction stalls waiting for quota for more than
box.cfg.too_long_threshold seconds, emit a warning to the log:

  W> waited for 699089 bytes of vinyl memory quota for too long: 0.504 sec

This will help us understand whether our users experience lags
due to absence of throttling in vinyl (see #1862).

Closes #3096
---
https://github.com/tarantool/tarantool/tree/gh-3096-vy-quota-stall-logging

 src/box/vinyl.c                   |  1 +
 src/box/vy_quota.h                | 15 +++++++++++-
 test/vinyl/quota_timeout.result   | 49 ++++++++++++++++++++++++++++++++++++---
 test/vinyl/quota_timeout.test.lua | 25 ++++++++++++++++++--
 4 files changed, 84 insertions(+), 6 deletions(-)

diff --git a/src/box/vinyl.c b/src/box/vinyl.c
index 94d0d038..03ad2bf4 100644
--- a/src/box/vinyl.c
+++ b/src/box/vinyl.c
@@ -2754,6 +2754,7 @@ void
 vinyl_engine_set_too_long_threshold(struct vinyl_engine *vinyl,
 				    double too_long_threshold)
 {
+	vinyl->env->quota.too_long_threshold = too_long_threshold;
 	vinyl->env->index_env.too_long_threshold = too_long_threshold;
 }
 
diff --git a/src/box/vy_quota.h b/src/box/vy_quota.h
index 8fd390e5..89f88bdc 100644
--- a/src/box/vy_quota.h
+++ b/src/box/vy_quota.h
@@ -37,6 +37,7 @@
 
 #include "fiber.h"
 #include "fiber_cond.h"
+#include "say.h"
 
 #if defined(__cplusplus)
 extern "C" {
@@ -66,6 +67,11 @@ struct vy_quota {
 	/** Current memory consumption. */
 	size_t used;
 	/**
+	 * If vy_quota_use() takes longer than the given
+	 * value, warn about it in the log.
+	 */
+	double too_long_threshold;
+	/**
 	 * Condition variable used for throttling consumers when
 	 * there is no quota left.
 	 */
@@ -83,6 +89,7 @@ vy_quota_create(struct vy_quota *q, vy_quota_exceeded_f quota_exceeded_cb)
 	q->limit = SIZE_MAX;
 	q->watermark = SIZE_MAX;
 	q->used = 0;
+	q->too_long_threshold = TIMEOUT_INFINITY;
 	q->quota_exceeded_cb = quota_exceeded_cb;
 	fiber_cond_create(&q->cond);
 }
@@ -148,12 +155,18 @@ vy_quota_release(struct vy_quota *q, size_t size)
 static inline int
 vy_quota_use(struct vy_quota *q, size_t size, double timeout)
 {
-	double deadline = ev_monotonic_now(loop()) + timeout;
+	double start_time = ev_monotonic_now(loop());
+	double deadline = start_time + timeout;
 	while (q->used + size > q->limit && timeout > 0) {
 		q->quota_exceeded_cb(q);
 		if (fiber_cond_wait_deadline(&q->cond, deadline) != 0)
 			break; /* timed out */
 	}
+	double wait_time = ev_monotonic_now(loop()) - start_time;
+	if (wait_time > q->too_long_threshold) {
+		say_warn("waited for %zu bytes of vinyl memory quota "
+			 "for too long: %.3f sec", size, wait_time);
+	}
 	if (q->used + size > q->limit)
 		return -1;
 	q->used += size;
diff --git a/test/vinyl/quota_timeout.result b/test/vinyl/quota_timeout.result
index 66cd6f88..1e66d392 100644
--- a/test/vinyl/quota_timeout.result
+++ b/test/vinyl/quota_timeout.result
@@ -65,9 +65,6 @@ box.info.vinyl().quota.used
 ---
 - 748241
 ...
-s:drop()
----
-...
 box.error.injection.set('ERRINJ_VY_RUN_WRITE', false)
 ---
 - ok
@@ -76,8 +73,54 @@ fiber.sleep(0.01) -- wait for scheduler to unthrottle
 ---
 ...
 --
+-- Check that there's a warning in the log if a transaction
+-- waits for quota for more than too_long_threshold seconds.
+--
+box.error.injection.set('ERRINJ_VY_RUN_WRITE_TIMEOUT', 0.01)
+---
+- ok
+...
+box.cfg{vinyl_timeout=60}
+---
+...
+box.cfg{too_long_threshold=0.01}
+---
+...
+_ = s:auto_increment{pad}
+---
+...
+_ = s:auto_increment{pad}
+---
+...
+test_run:cmd("push filter '[0-9.]+ sec' to '<sec> sec'")
+---
+- true
+...
+test_run:grep_log('test', 'waited for .* quota for too long.*')
+---
+- 'waited for 699089 bytes of vinyl memory quota for too long: <sec> sec'
+...
+test_run:cmd("clear filter")
+---
+- true
+...
+box.error.injection.set('ERRINJ_VY_RUN_WRITE_TIMEOUT', 0)
+---
+- ok
+...
+s:drop()
+---
+...
+box.snapshot()
+---
+- ok
+...
+--
 -- Check that exceeding quota triggers dump of all spaces.
 --
+box.cfg{vinyl_timeout=0.01}
+---
+...
 s1 = box.schema.space.create('test1', {engine = 'vinyl'})
 ---
 ...
diff --git a/test/vinyl/quota_timeout.test.lua b/test/vinyl/quota_timeout.test.lua
index 227ee80c..ed5ba79d 100644
--- a/test/vinyl/quota_timeout.test.lua
+++ b/test/vinyl/quota_timeout.test.lua
@@ -29,14 +29,35 @@ _ = s:auto_increment{pad}
 s:count()
 box.info.vinyl().quota.used
 
-s:drop()
-
 box.error.injection.set('ERRINJ_VY_RUN_WRITE', false)
 fiber.sleep(0.01) -- wait for scheduler to unthrottle
 
 --
+-- Check that there's a warning in the log if a transaction
+-- waits for quota for more than too_long_threshold seconds.
+--
+box.error.injection.set('ERRINJ_VY_RUN_WRITE_TIMEOUT', 0.01)
+
+box.cfg{vinyl_timeout=60}
+box.cfg{too_long_threshold=0.01}
+
+_ = s:auto_increment{pad}
+_ = s:auto_increment{pad}
+
+test_run:cmd("push filter '[0-9.]+ sec' to '<sec> sec'")
+test_run:grep_log('test', 'waited for .* quota for too long.*')
+test_run:cmd("clear filter")
+
+box.error.injection.set('ERRINJ_VY_RUN_WRITE_TIMEOUT', 0)
+
+s:drop()
+box.snapshot()
+
+--
 -- Check that exceeding quota triggers dump of all spaces.
 --
+box.cfg{vinyl_timeout=0.01}
+
 s1 = box.schema.space.create('test1', {engine = 'vinyl'})
 _ = s1:create_index('pk')
 s2 = box.schema.space.create('test2', {engine = 'vinyl'})
-- 
2.11.0