From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: From: Vladimir Davydov Subject: [PATCH] vinyl: improve dump start/stop logging Date: Fri, 12 Apr 2019 12:11:19 +0300 Message-Id: <39d8a43c078bf2a57b1549652a2328fcb4882fdf.1555060180.git.vdavydov.dev@gmail.com> To: kostja@tarantool.org Cc: tarantool-patches@freelists.org List-ID: 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