From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: From: Vladimir Davydov Subject: [PATCH 15/18] vinyl: improve dump start/stop logging Date: Thu, 16 Aug 2018 19:12:09 +0300 Message-Id: <8637c94dd4a9e8550b0357e22c0fa3b1f33494cb.1534432819.git.vdavydov.dev@gmail.com> In-Reply-To: References: In-Reply-To: References: 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 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