[PATCH 15/18] vinyl: improve dump start/stop logging

[Vladimir Davydov]

When initiating memory dump, print how much memory is going to be
dumped, expected dump rate, ETA, and the recent write rate. Upon dump
completion, print observed dump rate in addition to dump size and
duration.

Example:

  2018-08-16 14:11:40.802 [19044] main/2096/main I> dumping 134217746 bytes, expected rate 4.0 MB/s, ETA 32.0 s, recent write rate 16.6 MB/s
  2018-08-16 14:11:40.843 [19044] main/103/vinyl.scheduler I> 513/0: dump started
  2018-08-16 14:11:40.844 [19044] vinyl.writer.0/102/task I> writing `./513/0/00000000000000000002.run'
  2018-08-16 14:12:01.394 [19044] vinyl.writer.0/102/task I> writing `./513/0/00000000000000000002.index'
  2018-08-16 14:12:01.467 [19044] main/103/vinyl.scheduler I> 513/0: dump completed
  2018-08-16 14:12:01.467 [19044] main/103/vinyl.scheduler I> dumped 134214971 bytes in 20.7 s, rate 6.2 MB/s
---
 src/box/vinyl.c    |  2 --
 src/box/vy_quota.c | 14 ++++++++++++--
 2 files changed, 12 insertions(+), 4 deletions(-)

diff --git a/src/box/vinyl.c b/src/box/vinyl.c
index 25a937bc..ec7045b5 100644
--- a/src/box/vinyl.c
+++ b/src/box/vinyl.c
@@ -2414,8 +2414,6 @@ vy_env_dump_complete_cb(struct vy_scheduler *scheduler,
 	assert(mem_used_after <= mem_used_before);
 	size_t mem_dumped = mem_used_before - mem_used_after;
 	vy_quota_dump(quota, mem_dumped, dump_duration);
-
-	say_info("dumped %zu bytes in %.1f sec", mem_dumped, dump_duration);
 }
 
 static struct vy_squash_queue *
diff --git a/src/box/vy_quota.c b/src/box/vy_quota.c
index 0250b3ab..c22a8519 100644
--- a/src/box/vy_quota.c
+++ b/src/box/vy_quota.c
@@ -86,8 +86,15 @@ vy_quota_signal(struct vy_quota *q)
 static inline void
 vy_quota_check_watermark(struct vy_quota *q)
 {
-	if (!q->dump_in_progress && q->used >= q->watermark)
-		q->dump_in_progress = q->quota_exceeded_cb(q);
+	if (!q->dump_in_progress &&
+	    q->used >= q->watermark && q->quota_exceeded_cb(q)) {
+		q->dump_in_progress = true;
+		say_info("dumping %zu bytes, expected rate %.1f MB/s, "
+			 "ETA %.1f s, recent write rate %.1f MB/s", q->used,
+			 (double)q->dump_bw / 1024 / 1024,
+			 (double)q->used / (q->dump_bw + 1),
+			 (double)q->use_rate / 1024 / 1024);
+	}
 }
 
 static void
@@ -214,6 +221,9 @@ vy_quota_dump(struct vy_quota *q, size_t size, double duration)
 		q->dump_bw = histogram_percentile_lower(q->dump_bw_hist,
 							VY_DUMP_BANDWIDTH_PCT);
 	}
+
+	say_info("dumped %zu bytes in %.1f s, rate %.1f MB/s",
+		 size, duration, size / duration / 1024 / 1024);
 }
 
 int
-- 
2.11.0