[PATCH] vinyl: improve latency stat

[Vladimir Davydov]

To facilitate performance analysis, let us
 - Report not only 99th percentile, but also 50th, 75th, 90th, and 95th.
 - Add microsecond-granular buckets to the latency histogram.
 - Use clock_monotonic() instead of ev_monotonic_now() for measuring
   latency as it is more precise and allows to catch CPU-bound stalls.
   On Linux the syscall is implemented using VDSO so it shouldn't
   introduce any noticable performance penalty.

Closes #3207
---
https://github.com/tarantool/tarantool/issues/3207
https://github.com/tarantool/tarantool/tree/gh-3207-vy-improve-latency-stat

 src/box/vinyl.c            |  9 ++++++++-
 src/box/vy_point_lookup.c  |  5 +++--
 src/box/vy_read_iterator.c |  9 ++++++---
 src/latency.c              | 13 ++++++-------
 src/latency.h              |  3 ++-
 5 files changed, 25 insertions(+), 14 deletions(-)

diff --git a/src/box/vinyl.c b/src/box/vinyl.c
index 03a54670..f8e4dabd 100644
--- a/src/box/vinyl.c
+++ b/src/box/vinyl.c
@@ -415,7 +415,14 @@ vinyl_index_info(struct index *base, struct info_handler *h)
 	info_append_int(h, "lookup", stat->lookup);
 	vy_info_append_stmt_counter(h, "get", &stat->get);
 	vy_info_append_stmt_counter(h, "put", &stat->put);
-	info_append_double(h, "latency", latency_get(&stat->latency));
+
+	info_table_begin(h, "latency");
+	info_append_double(h, "p50", latency_get(&stat->latency, 50));
+	info_append_double(h, "p75", latency_get(&stat->latency, 75));
+	info_append_double(h, "p90", latency_get(&stat->latency, 90));
+	info_append_double(h, "p95", latency_get(&stat->latency, 95));
+	info_append_double(h, "p99", latency_get(&stat->latency, 99));
+	info_table_end(h);
 
 	info_table_begin(h, "upsert");
 	info_append_int(h, "squashed", stat->upsert.squashed);
diff --git a/src/box/vy_point_lookup.c b/src/box/vy_point_lookup.c
index 4076d231..b2380986 100644
--- a/src/box/vy_point_lookup.c
+++ b/src/box/vy_point_lookup.c
@@ -38,6 +38,7 @@
 #include <small/rlist.h>
 
 #include "fiber.h"
+#include "clock.h"
 
 #include "vy_index.h"
 #include "vy_stmt.h"
@@ -396,7 +397,7 @@ vy_point_lookup(struct vy_index *index, struct vy_tx *tx,
 
 	*ret = NULL;
 	size_t region_svp = region_used(&fiber()->gc);
-	double start_time = ev_monotonic_now(loop());
+	double start_time = clock_monotonic();
 	int rc = 0;
 
 	index->stat.lookup++;
@@ -465,7 +466,7 @@ done:
 	if (rc != 0)
 		return -1;
 
-	double latency = ev_monotonic_now(loop()) - start_time;
+	double latency = clock_monotonic() - start_time;
 	latency_collect(&index->stat.latency, latency);
 
 	if (latency > index->env->too_long_threshold) {
diff --git a/src/box/vy_read_iterator.c b/src/box/vy_read_iterator.c
index d08be9a0..58019ae3 100644
--- a/src/box/vy_read_iterator.c
+++ b/src/box/vy_read_iterator.c
@@ -29,11 +29,14 @@
  * SUCH DAMAGE.
  */
 #include "vy_read_iterator.h"
+
+#include "fiber.h"
+#include "clock.h"
+
 #include "vy_run.h"
 #include "vy_mem.h"
 #include "vy_cache.h"
 #include "vy_tx.h"
-#include "fiber.h"
 #include "vy_upsert.h"
 #include "vy_index.h"
 #include "vy_stat.h"
@@ -936,7 +939,7 @@ vy_read_iterator_track_read(struct vy_read_iterator *itr, struct tuple *stmt)
 NODISCARD int
 vy_read_iterator_next(struct vy_read_iterator *itr, struct tuple **result)
 {
-	ev_tstamp start_time = ev_monotonic_now(loop());
+	double start_time = clock_monotonic();
 
 	/* The key might be set to NULL during previous call, that means
 	 * that there's no more data */
@@ -1049,7 +1052,7 @@ clear:
 	if (prev_key != NULL)
 		tuple_unref(prev_key);
 
-	ev_tstamp latency = ev_monotonic_now(loop()) - start_time;
+	double latency = clock_monotonic() - start_time;
 	latency_collect(&index->stat.latency, latency);
 
 	if (latency > index->env->too_long_threshold) {
diff --git a/src/latency.c b/src/latency.c
index 406bc4f6..80f00642 100644
--- a/src/latency.c
+++ b/src/latency.c
@@ -40,15 +40,15 @@ enum {
 	USEC_PER_SEC		= 1000000,
 };
 
-enum {
-	LATENCY_PERCENTILE	= 99,
-};
-
 int
 latency_create(struct latency *latency)
 {
 	enum { US = 1, MS = USEC_PER_MSEC, S = USEC_PER_SEC };
 	static int64_t buckets[] = {
+		  1 * US,   2 * US,   3 * US,   4 * US,   5 * US,   6 * US,
+		  7 * US,   8 * US,   9 * US,
+		 10 * US,  20 * US,  30 * US,  40 * US,  50 * US,  60 * US,
+		 70 * US,  80 * US,  90 * US,
 		100 * US, 200 * US, 300 * US, 400 * US, 500 * US, 600 * US,
 		700 * US, 800 * US, 900 * US,
 		  1 * MS,   2 * MS,   3 * MS,   4 * MS,   5 * MS,   6 * MS,
@@ -83,9 +83,8 @@ latency_collect(struct latency *latency, double value)
 }
 
 double
-latency_get(struct latency *latency)
+latency_get(struct latency *latency, int pct)
 {
-	int64_t value_usec = histogram_percentile(latency->histogram,
-						  LATENCY_PERCENTILE);
+	int64_t value_usec = histogram_percentile(latency->histogram, pct);
 	return (double)value_usec / USEC_PER_SEC;
 }
diff --git a/src/latency.h b/src/latency.h
index cb53cea9..608e8f69 100644
--- a/src/latency.h
+++ b/src/latency.h
@@ -66,8 +66,9 @@ latency_collect(struct latency *latency, double value);
 
 /**
  * Get accumulated latency value, in seconds.
+ * Returns @pct-th percentile of all observations.
  */
 double
-latency_get(struct latency *latency);
+latency_get(struct latency *latency, int pct);
 
 #endif /* TARANTOOL_LATENCY_H_INCLUDED */
-- 
2.11.0