[PATCH] vinyl: improve dump start/stop logging

[PATCH] 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 recent write rate. Upon dump
completion, print observed dump rate in addition to dump size and
duration. This should help debugging stalls on memory quota.

Example:

 | 2019-04-12 12:03:25.092 [30948] main/115/lua I> dumping 39659424 bytes, expected rate 6.0 MB/s, ETA 6.3 s, recent write rate 4.2 MB/s
 | 2019-04-12 12:03:25.101 [30948] main/106/vinyl.scheduler I> 512/1: dump started
 | 2019-04-12 12:03:25.102 [30948] vinyl.dump.0/104/task I> writing `./512/1/00000000000000000008.run'
 | 2019-04-12 12:03:26.487 [30948] vinyl.dump.0/104/task I> writing `./512/1/00000000000000000008.index'
 | 2019-04-12 12:03:26.547 [30948] main/106/vinyl.scheduler I> 512/1: dump completed
 | 2019-04-12 12:03:26.551 [30948] main/106/vinyl.scheduler I> 512/0: dump started
 | 2019-04-12 12:03:26.553 [30948] vinyl.dump.0/105/task I> writing `./512/0/00000000000000000010.run'
 | 2019-04-12 12:03:28.026 [30948] vinyl.dump.0/105/task I> writing `./512/0/00000000000000000010.index'
 | 2019-04-12 12:03:28.100 [30948] main/106/vinyl.scheduler I> 512/0: dump completed
 | 2019-04-12 12:03:28.100 [30948] main/106/vinyl.scheduler I> dumped 33554332 bytes in 3.0 s, rate 10.6 MB/s
---
https://github.com/tarantool/tarantool/tree/dv/vy-improve-dump-logging

 src/box/vinyl.c        |  1 -
 src/box/vy_regulator.c | 10 ++++++++++
 2 files changed, 10 insertions(+), 1 deletion(-)

diff --git a/src/box/vinyl.c b/src/box/vinyl.c
index b9bf721a..a4959aad 100644
--- a/src/box/vinyl.c
+++ b/src/box/vinyl.c
@@ -2548,7 +2548,6 @@ vy_env_dump_complete_cb(struct vy_scheduler *scheduler,
 	size_t mem_used_after = lsregion_used(allocator);
 	assert(mem_used_after <= mem_used_before);
 	size_t mem_dumped = mem_used_before - mem_used_after;
-	say_info("dumped %zu bytes in %.1f sec", mem_dumped, dump_duration);
 	/*
 	 * In certain corner cases, vy_quota_release() may need
 	 * to trigger a new dump. Notify the regulator about dump
diff --git a/src/box/vy_regulator.c b/src/box/vy_regulator.c
index eebfe805..589d3fd9 100644
--- a/src/box/vy_regulator.c
+++ b/src/box/vy_regulator.c
@@ -113,6 +113,12 @@ vy_regulator_trigger_dump(struct vy_regulator *regulator)
 	max_write_rate = MIN(max_write_rate, regulator->dump_bandwidth);
 	vy_quota_set_rate_limit(quota, VY_QUOTA_RESOURCE_MEMORY,
 				max_write_rate);
+
+	say_info("dumping %zu bytes, expected rate %.1f MB/s, "
+		 "ETA %.1f s, recent write rate %.1f MB/s",
+		 quota->used, (double)regulator->dump_bandwidth / 1024 / 1024,
+		 (double)quota->used / (regulator->dump_bandwidth + 1),
+		 (double)regulator->write_rate / 1024 / 1024);
 }
 
 static void
@@ -265,6 +271,10 @@ vy_regulator_dump_complete(struct vy_regulator *regulator,
 	 */
 	vy_quota_set_rate_limit(regulator->quota, VY_QUOTA_RESOURCE_MEMORY,
 				regulator->dump_bandwidth);
+
+	say_info("dumped %zu bytes in %.1f s, rate %.1f MB/s",
+		 mem_dumped, dump_duration,
+		 mem_dumped / dump_duration / 1024 / 1024);
 }
 
 void
-- 
2.11.0

Re: [PATCH] vinyl: improve dump start/stop logging

[Vladimir Davydov]

Pushed to master, 2.1, 1.10.

Re: [PATCH] vinyl: improve dump start/stop logging

[Konstantin Osipov]

* Vladimir Davydov <vdavydov.dev@gmail.com> [19/04/12 14:20]:
> When initiating memory dump, print how much memory is going to be
> dumped, expected dump rate, ETA, and recent write rate. Upon dump
> completion, print observed dump rate in addition to dump size and
> duration. This should help debugging stalls on memory quota.

OK to push.


-- 
Konstantin Osipov, Moscow, Russia, +7 903 626 22 32
http://tarantool.io - www.twitter.com/kostja_osipov