Tarantool development patches archive
 help / color / mirror / Atom feed
* [PATCH] vinyl: improve dump start/stop logging
@ 2019-04-12  9:11 Vladimir Davydov
  2019-04-12  9:53 ` Vladimir Davydov
  2019-04-12 11:20 ` Konstantin Osipov
  0 siblings, 2 replies; 3+ messages in thread
From: Vladimir Davydov @ 2019-04-12  9:11 UTC (permalink / raw)
  To: kostja; +Cc: tarantool-patches

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

^ permalink raw reply	[flat|nested] 3+ messages in thread

end of thread, other threads:[~2019-04-12 11:20 UTC | newest]

Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-04-12  9:11 [PATCH] vinyl: improve dump start/stop logging Vladimir Davydov
2019-04-12  9:53 ` Vladimir Davydov
2019-04-12 11:20 ` Konstantin Osipov

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox