[PATCH 11/12] vinyl: add dump/compaction time to statistics
Vladimir Davydov
vdavydov.dev at gmail.com
Tue Jan 15 17:17:20 MSK 2019
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: <bytes_compressed>
- pages: 0
- rows: 0
- bytes: 0
queue:
bytes_compressed: <bytes_compressed>
pages: 0
rows: 0
bytes: 0
+ output:
+ bytes_compressed: <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: <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
More information about the Tarantool-patches
mailing list