From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: From: Vladimir Davydov Subject: [PATCH 11/12] vinyl: add dump/compaction time to statistics Date: Tue, 15 Jan 2019 17:17:20 +0300 Message-Id: <701de075c765a9cfe0ed2cf1366bf250517935ed.1547558871.git.vdavydov.dev@gmail.com> In-Reply-To: References: In-Reply-To: References: To: tarantool-patches@freelists.org List-ID: This patch adds dump_time and compaction_time to the scheduler section of global vinyl statistics and disk.dump.time and disk.compaction.time to per-index statistics. They report the total time spent doing dump and compaction tasks, respectively and can be useful for estimating average disk write rate, which is required for compaction-aware throttling. --- src/box/vinyl.c | 6 ++ src/box/vy_lsm.c | 6 +- src/box/vy_lsm.h | 4 +- src/box/vy_scheduler.c | 14 ++++- src/box/vy_stat.h | 8 +++ test/vinyl/errinj_stat.result | 136 ++++++++++++++++++++++++++++++++++++++++ test/vinyl/errinj_stat.test.lua | 45 +++++++++++++ test/vinyl/stat.result | 58 ++++++++++------- test/vinyl/stat.test.lua | 10 +++ 9 files changed, 257 insertions(+), 30 deletions(-) diff --git a/src/box/vinyl.c b/src/box/vinyl.c index ea80d0ba..4e5903c2 100644 --- a/src/box/vinyl.c +++ b/src/box/vinyl.c @@ -254,8 +254,10 @@ vy_info_append_scheduler(struct vy_env *env, struct info_handler *h) info_append_int(h, "tasks_completed", stat->tasks_completed); info_append_int(h, "tasks_failed", stat->tasks_failed); info_append_int(h, "dump_count", stat->dump_count); + info_append_double(h, "dump_time", stat->dump_time); info_append_int(h, "dump_input", stat->dump_input); info_append_int(h, "dump_output", stat->dump_output); + info_append_double(h, "compaction_time", stat->compaction_time); info_append_int(h, "compaction_input", stat->compaction_input); info_append_int(h, "compaction_output", stat->compaction_output); info_append_int(h, "compaction_queue", stat->compaction_queue); @@ -418,11 +420,13 @@ vinyl_index_stat(struct index *index, struct info_handler *h) info_table_end(h); /* iterator */ info_table_begin(h, "dump"); info_append_int(h, "count", stat->disk.dump.count); + info_append_double(h, "time", stat->disk.dump.time); vy_info_append_stmt_counter(h, "input", &stat->disk.dump.input); vy_info_append_disk_stmt_counter(h, "output", &stat->disk.dump.output); info_table_end(h); /* dump */ info_table_begin(h, "compaction"); info_append_int(h, "count", stat->disk.compaction.count); + info_append_double(h, "time", stat->disk.compaction.time); vy_info_append_disk_stmt_counter(h, "input", &stat->disk.compaction.input); vy_info_append_disk_stmt_counter(h, "output", &stat->disk.compaction.output); vy_info_append_disk_stmt_counter(h, "queue", &stat->disk.compaction.queue); @@ -480,11 +484,13 @@ vinyl_index_reset_stat(struct index *index) /* Dump */ stat->disk.dump.count = 0; + stat->disk.dump.time = 0; vy_stmt_counter_reset(&stat->disk.dump.input); vy_disk_stmt_counter_reset(&stat->disk.dump.output); /* Compaction */ stat->disk.compaction.count = 0; + stat->disk.compaction.time = 0; vy_disk_stmt_counter_reset(&stat->disk.compaction.input); vy_disk_stmt_counter_reset(&stat->disk.compaction.output); diff --git a/src/box/vy_lsm.c b/src/box/vy_lsm.c index b79c6e0c..07ddc646 100644 --- a/src/box/vy_lsm.c +++ b/src/box/vy_lsm.c @@ -759,21 +759,23 @@ vy_lsm_unacct_range(struct vy_lsm *lsm, struct vy_range *range) } void -vy_lsm_acct_dump(struct vy_lsm *lsm, +vy_lsm_acct_dump(struct vy_lsm *lsm, double time, const struct vy_stmt_counter *input, const struct vy_disk_stmt_counter *output) { lsm->stat.disk.dump.count++; + lsm->stat.disk.dump.time += time; vy_stmt_counter_add(&lsm->stat.disk.dump.input, input); vy_disk_stmt_counter_add(&lsm->stat.disk.dump.output, output); } void -vy_lsm_acct_compaction(struct vy_lsm *lsm, +vy_lsm_acct_compaction(struct vy_lsm *lsm, double time, const struct vy_disk_stmt_counter *input, const struct vy_disk_stmt_counter *output) { lsm->stat.disk.compaction.count++; + lsm->stat.disk.compaction.time += time; vy_disk_stmt_counter_add(&lsm->stat.disk.compaction.input, input); vy_disk_stmt_counter_add(&lsm->stat.disk.compaction.output, output); } diff --git a/src/box/vy_lsm.h b/src/box/vy_lsm.h index b486a662..97b567d4 100644 --- a/src/box/vy_lsm.h +++ b/src/box/vy_lsm.h @@ -468,7 +468,7 @@ vy_lsm_unacct_range(struct vy_lsm *lsm, struct vy_range *range); * Account dump in LSM tree statistics. */ void -vy_lsm_acct_dump(struct vy_lsm *lsm, +vy_lsm_acct_dump(struct vy_lsm *lsm, double time, const struct vy_stmt_counter *input, const struct vy_disk_stmt_counter *output); @@ -476,7 +476,7 @@ vy_lsm_acct_dump(struct vy_lsm *lsm, * Account compaction in LSM tree statistics. */ void -vy_lsm_acct_compaction(struct vy_lsm *lsm, +vy_lsm_acct_compaction(struct vy_lsm *lsm, double time, const struct vy_disk_stmt_counter *input, const struct vy_disk_stmt_counter *output); diff --git a/src/box/vy_scheduler.c b/src/box/vy_scheduler.c index d0344cdd..7a143062 100644 --- a/src/box/vy_scheduler.c +++ b/src/box/vy_scheduler.c @@ -169,6 +169,8 @@ struct vy_task { * a worker thread. */ struct fiber *fiber; + /** Time of the task creation. */ + double start_time; /** Set if the task failed. */ bool is_failed; /** In case of task failure the error is stored here. */ @@ -243,6 +245,7 @@ vy_task_new(struct vy_scheduler *scheduler, struct vy_worker *worker, task->ops = ops; task->scheduler = scheduler; task->worker = worker; + task->start_time = ev_monotonic_now(loop()); task->lsm = lsm; task->cmp_def = key_def_dup(lsm->cmp_def); if (task->cmp_def == NULL) { @@ -507,8 +510,10 @@ vy_scheduler_reset_stat(struct vy_scheduler *scheduler) stat->tasks_completed = 0; stat->tasks_failed = 0; stat->dump_count = 0; + stat->dump_time = 0; stat->dump_input = 0; stat->dump_output = 0; + stat->compaction_time = 0; stat->compaction_input = 0; stat->compaction_output = 0; } @@ -1138,6 +1143,7 @@ vy_task_dump_complete(struct vy_task *task) struct vy_lsm *lsm = task->lsm; struct vy_run *new_run = task->new_run; int64_t dump_lsn = new_run->dump_lsn; + double dump_time = ev_monotonic_now(loop()) - task->start_time; struct vy_disk_stmt_counter dump_output = new_run->count; struct vy_stmt_counter dump_input; struct tuple_format *key_format = lsm->env->key_format; @@ -1270,7 +1276,7 @@ delete_mems: vy_lsm_delete_mem(lsm, mem); } lsm->dump_lsn = MAX(lsm->dump_lsn, dump_lsn); - vy_lsm_acct_dump(lsm, &dump_input, &dump_output); + vy_lsm_acct_dump(lsm, dump_time, &dump_input, &dump_output); /* * Indexes of the same space share a memory level so we * account dump input only when the primary index is dumped. @@ -1278,6 +1284,7 @@ delete_mems: if (lsm->index_id == 0) scheduler->stat.dump_input += dump_input.bytes; scheduler->stat.dump_output += dump_output.bytes; + scheduler->stat.dump_time += dump_time; /* The iterator has been cleaned up in a worker thread. */ task->wi->iface->close(task->wi); @@ -1499,6 +1506,7 @@ vy_task_compaction_complete(struct vy_task *task) struct vy_lsm *lsm = task->lsm; struct vy_range *range = task->range; struct vy_run *new_run = task->new_run; + double compaction_time = ev_monotonic_now(loop()) - task->start_time; struct vy_disk_stmt_counter compaction_output = new_run->count; struct vy_disk_stmt_counter compaction_input; struct vy_slice *first_slice = task->first_slice; @@ -1615,10 +1623,12 @@ vy_task_compaction_complete(struct vy_task *task) range->n_compactions++; vy_range_update_compaction_priority(range, &lsm->opts); vy_lsm_acct_range(lsm, range); - vy_lsm_acct_compaction(lsm, &compaction_input, &compaction_output); + vy_lsm_acct_compaction(lsm, compaction_time, + &compaction_input, &compaction_output); vy_scheduler_acct_lsm(scheduler, lsm); scheduler->stat.compaction_input += compaction_input.bytes; scheduler->stat.compaction_output += compaction_output.bytes; + scheduler->stat.compaction_time += compaction_time; /* * Unaccount unused runs and delete compacted slices. diff --git a/src/box/vy_stat.h b/src/box/vy_stat.h index bd3b811c..6f6db6ac 100644 --- a/src/box/vy_stat.h +++ b/src/box/vy_stat.h @@ -147,6 +147,8 @@ struct vy_lsm_stat { struct { /* Number of completed tasks. */ int32_t count; + /** Time spent on dump tasks, in seconds. */ + double time; /** Number of input statements. */ struct vy_stmt_counter input; /** Number of output statements. */ @@ -156,6 +158,8 @@ struct vy_lsm_stat { struct { /* Number of completed tasks. */ int32_t count; + /** Time spent on compaction tasks, in seconds. */ + double time; /** Number of input statements. */ struct vy_disk_stmt_counter input; /** Number of output statements. */ @@ -220,10 +224,14 @@ struct vy_scheduler_stat { int32_t tasks_inprogress; /** Number of completed memory dumps. */ int32_t dump_count; + /** Time spent on dump tasks, in seconds. */ + double dump_time; /** Number of bytes read by dump tasks. */ int64_t dump_input; /** Number of bytes written by dump tasks. */ int64_t dump_output; + /** Time spent on compaction tasks, in seconds. */ + double compaction_time; /** Number of bytes read by compaction tasks. */ int64_t compaction_input; /** Number of bytes written by compaction tasks. */ diff --git a/test/vinyl/errinj_stat.result b/test/vinyl/errinj_stat.result index 9989f734..08801dbc 100644 --- a/test/vinyl/errinj_stat.result +++ b/test/vinyl/errinj_stat.result @@ -253,6 +253,142 @@ fiber.sleep(0.01) s:drop() --- ... +-- +-- Check dump/compaction time accounting. +-- +box.stat.reset() +--- +... +s = box.schema.space.create('test', {engine = 'vinyl'}) +--- +... +i = s:create_index('pk') +--- +... +i:stat().disk.dump.time == 0 +--- +- true +... +i:stat().disk.compaction.time == 0 +--- +- true +... +box.stat.vinyl().scheduler.dump_time == 0 +--- +- true +... +box.stat.vinyl().scheduler.compaction_time == 0 +--- +- true +... +for i = 1, 100 do s:replace{i} end +--- +... +errinj.set('ERRINJ_VY_RUN_WRITE_DELAY', true) +--- +- ok +... +start_time = fiber.time() +--- +... +c = fiber.channel(1) +--- +... +_ = fiber.create(function() box.snapshot() c:put(true) end) +--- +... +fiber.sleep(0.1) +--- +... +errinj.set('ERRINJ_VY_RUN_WRITE_DELAY', false) +--- +- ok +... +c:get() +--- +- true +... +i:stat().disk.dump.time >= 0.1 +--- +- true +... +i:stat().disk.dump.time <= fiber.time() - start_time +--- +- true +... +i:stat().disk.compaction.time == 0 +--- +- true +... +box.stat.vinyl().scheduler.dump_time == i:stat().disk.dump.time +--- +- true +... +box.stat.vinyl().scheduler.compaction_time == i:stat().disk.compaction.time +--- +- true +... +for i = 1, 100, 10 do s:replace{i} end +--- +... +box.snapshot() +--- +- ok +... +errinj.set('ERRINJ_VY_RUN_WRITE_DELAY', true) +--- +- ok +... +start_time = fiber.time() +--- +... +i:compact() +--- +... +fiber.sleep(0.1) +--- +... +errinj.set('ERRINJ_VY_RUN_WRITE_DELAY', false) +--- +- ok +... +while i:stat().disk.compaction.count == 0 do fiber.sleep(0.01) end +--- +... +i:stat().disk.compaction.time >= 0.1 +--- +- true +... +i:stat().disk.compaction.time <= fiber.time() - start_time +--- +- true +... +box.stat.vinyl().scheduler.compaction_time == i:stat().disk.compaction.time +--- +- true +... +box.stat.reset() +--- +... +i:stat().disk.dump.time == 0 +--- +- true +... +i:stat().disk.compaction.time == 0 +--- +- true +... +box.stat.vinyl().scheduler.dump_time == 0 +--- +- true +... +box.stat.vinyl().scheduler.compaction_time == 0 +--- +- true +... +s:drop() +--- +... test_run:cmd("clear filter") --- - true diff --git a/test/vinyl/errinj_stat.test.lua b/test/vinyl/errinj_stat.test.lua index fd80b382..19f3d119 100644 --- a/test/vinyl/errinj_stat.test.lua +++ b/test/vinyl/errinj_stat.test.lua @@ -78,6 +78,51 @@ errinj.set('ERRINJ_VY_SCHED_TIMEOUT', 0) fiber.sleep(0.01) s:drop() +-- +-- Check dump/compaction time accounting. +-- +box.stat.reset() +s = box.schema.space.create('test', {engine = 'vinyl'}) +i = s:create_index('pk') +i:stat().disk.dump.time == 0 +i:stat().disk.compaction.time == 0 +box.stat.vinyl().scheduler.dump_time == 0 +box.stat.vinyl().scheduler.compaction_time == 0 + +for i = 1, 100 do s:replace{i} end +errinj.set('ERRINJ_VY_RUN_WRITE_DELAY', true) +start_time = fiber.time() +c = fiber.channel(1) +_ = fiber.create(function() box.snapshot() c:put(true) end) +fiber.sleep(0.1) +errinj.set('ERRINJ_VY_RUN_WRITE_DELAY', false) +c:get() +i:stat().disk.dump.time >= 0.1 +i:stat().disk.dump.time <= fiber.time() - start_time +i:stat().disk.compaction.time == 0 +box.stat.vinyl().scheduler.dump_time == i:stat().disk.dump.time +box.stat.vinyl().scheduler.compaction_time == i:stat().disk.compaction.time + +for i = 1, 100, 10 do s:replace{i} end +box.snapshot() +errinj.set('ERRINJ_VY_RUN_WRITE_DELAY', true) +start_time = fiber.time() +i:compact() +fiber.sleep(0.1) +errinj.set('ERRINJ_VY_RUN_WRITE_DELAY', false) +while i:stat().disk.compaction.count == 0 do fiber.sleep(0.01) end +i:stat().disk.compaction.time >= 0.1 +i:stat().disk.compaction.time <= fiber.time() - start_time +box.stat.vinyl().scheduler.compaction_time == i:stat().disk.compaction.time + +box.stat.reset() +i:stat().disk.dump.time == 0 +i:stat().disk.compaction.time == 0 +box.stat.vinyl().scheduler.dump_time == 0 +box.stat.vinyl().scheduler.compaction_time == 0 + +s:drop() + test_run:cmd("clear filter") test_run:cmd('switch default') test_run:cmd('stop server test') diff --git a/test/vinyl/stat.result b/test/vinyl/stat.result index 6b71d4c5..0920e3da 100644 --- a/test/vinyl/stat.result +++ b/test/vinyl/stat.result @@ -86,9 +86,14 @@ end; -- -- Note, latency measurement is beyond the scope of this test -- so we just filter it out. +-- +-- Filter dump/compaction time as we need error injection to +-- test them properly. function istat() local st = box.space.test.index.pk:stat() st.latency = nil + st.disk.dump.time = nil + st.disk.compaction.time = nil return st end; --- @@ -97,9 +102,14 @@ end; -- -- Note, checking correctness of the load regulator logic is beyond -- the scope of this test so we just filter out related statistics. +-- +-- Filter dump/compaction time as we need error injection to +-- test them properly. function gstat() local st = box.stat.vinyl() st.regulator = nil + st.scheduler.dump_time = nil + st.scheduler.compaction_time = nil return st end; --- @@ -156,17 +166,17 @@ istat() pages: 0 rows: 0 bytes: 0 - count: 0 - output: - bytes_compressed: 0 - pages: 0 - rows: 0 - bytes: 0 queue: bytes_compressed: 0 pages: 0 rows: 0 bytes: 0 + output: + bytes_compressed: 0 + pages: 0 + rows: 0 + bytes: 0 + count: 0 statement: inserts: 0 replaces: 0 @@ -176,12 +186,12 @@ istat() input: rows: 0 bytes: 0 - count: 0 output: bytes_compressed: 0 pages: 0 rows: 0 bytes: 0 + count: 0 bloom_size: 0 iterator: read: @@ -242,13 +252,13 @@ gstat() data: 0 index: 0 scheduler: - compaction_output: 0 tasks_inprogress: 0 dump_output: 0 - tasks_completed: 0 + compaction_queue: 0 + compaction_output: 0 dump_count: 0 tasks_failed: 0 - compaction_queue: 0 + tasks_completed: 0 dump_input: 0 compaction_input: 0 ... @@ -1009,17 +1019,17 @@ istat() pages: 0 rows: 0 bytes: 0 - count: 0 - output: - bytes_compressed: - pages: 0 - rows: 0 - bytes: 0 queue: bytes_compressed: pages: 0 rows: 0 bytes: 0 + output: + bytes_compressed: + pages: 0 + rows: 0 + bytes: 0 + count: 0 statement: inserts: 0 replaces: 100 @@ -1029,12 +1039,12 @@ istat() input: rows: 0 bytes: 0 - count: 0 output: bytes_compressed: pages: 0 rows: 0 bytes: 0 + count: 0 bloom_size: 140 iterator: read: @@ -1095,13 +1105,13 @@ gstat() data: 104300 index: 1190 scheduler: - compaction_output: 0 tasks_inprogress: 0 dump_output: 0 - tasks_completed: 0 + compaction_queue: 0 + compaction_output: 0 dump_count: 0 tasks_failed: 0 - compaction_queue: 0 + tasks_completed: 0 dump_input: 0 compaction_input: 0 ... @@ -1131,9 +1141,9 @@ box.snapshot() stat_diff(gstat(), st, 'scheduler') --- - dump_input: 104200 - dump_count: 1 - tasks_completed: 2 dump_output: 103592 + tasks_completed: 2 + dump_count: 1 ... for i = 1, 100, 10 do s:replace{i, i, string.rep('y', 1000)} end --- @@ -1148,9 +1158,9 @@ box.snapshot() stat_diff(gstat(), st, 'scheduler') --- - dump_input: 10420 - dump_count: 1 - tasks_completed: 2 dump_output: 10371 + tasks_completed: 2 + dump_count: 1 ... st = gstat() --- diff --git a/test/vinyl/stat.test.lua b/test/vinyl/stat.test.lua index f2acf3e8..818ec730 100644 --- a/test/vinyl/stat.test.lua +++ b/test/vinyl/stat.test.lua @@ -69,9 +69,14 @@ end; -- -- Note, latency measurement is beyond the scope of this test -- so we just filter it out. +-- +-- Filter dump/compaction time as we need error injection to +-- test them properly. function istat() local st = box.space.test.index.pk:stat() st.latency = nil + st.disk.dump.time = nil + st.disk.compaction.time = nil return st end; @@ -79,9 +84,14 @@ end; -- -- Note, checking correctness of the load regulator logic is beyond -- the scope of this test so we just filter out related statistics. +-- +-- Filter dump/compaction time as we need error injection to +-- test them properly. function gstat() local st = box.stat.vinyl() st.regulator = nil + st.scheduler.dump_time = nil + st.scheduler.compaction_time = nil return st end; -- 2.11.0