metrics: Accurate duration tracing of storage/scheduler message handling #8403

innerr · 2020-08-04T16:35:49Z

Signed-off-by: Liu Cong innerr@gmail.com

What problem does this PR solve?

The inaccurate duration tracing of TiKV

Problem Summary:

The tikv_raftstore_apply_wait_time_duration_secs is not only the duration in queue
Lack of duration recording (separated by message type) of async_write
The SCHED_LATCH_HISTOGRAM_VEC include duration in queue and latch time, which is not correct
For each storage message, the duration recording was not fully covered the whole executing progress now

What is changed and how it works?

Record only the in-queue duration
Add a metric to record it
Add a metric for in-queue duration
Add a group of metrics, to record the whole executing progress by parts

Tests

Manual test
CI test

Side effects

The related metrics' meaning will be different from before

Release note

Add accurate duration tracing of TiKV

Later works

About the 4, there will be some new Grafana panels to trace the duration of each message:

And, there will be a panel to show the accuracy of this trace:
(the red delta line should close to 0, means the trace is accurate)

sticnarf · 2020-08-05T03:05:42Z

src/storage/txn/scheduler.rs

                let mut statistics = Statistics::default();

                if task.cmd.readonly() {
                    self.process_read(snapshot, task, &mut statistics);
                } else {
+                    SCHED_PRE_HANDLE_2_DURATIONS_VEC


SCHED_PRE_HANDLE_2_DURATIONS_VEC seems no much different from SCHED_PRE_HANDLE_3_DURATIONS_VEC

SCHED_PRE_HANDLE_3_DURATIONS_VEC is intended to record the accurate duration of in-queue time,
SCHED_PRE_HANDLE_2_DURATIONS_VEC will not be recorded when task.cmd.readonly() is true.

But I agree what you said, so they will be merged into one.

sticnarf · 2020-08-05T03:10:01Z

src/storage/txn/scheduler.rs

@@ -374,6 +392,9 @@ impl<E: Engine, L: LockManager, P: PdClient + 'static> Scheduler<E, L, P> {
                            "process cmd with snapshot";
                            "cid" => task.cid, "cb_ctx" => ?cb_ctx
                        );
+                        SCHED_PRE_HANDLE_1_DURATIONS_VEC


Could it have a more descriptive name instead of 1, 2, 3... For example SCHED_AFTER_SNAPSHOT_DURATIONS_VEC because this is right after getting snapshot.

innerr · 2020-08-10T14:15:47Z

The changes after your last review:

tikv_scheduler_pre_handle_1_duration_seconds =>
tikv_scheduler_async_snapshot_duration_seconds

tikv_scheduler_pre_handle_2_duration_seconds =>
(merged with pre_handle_3)

tikv_scheduler_pre_handle_3_duration_seconds =>
tikv_scheduler_wait_for_thread_duration_seconds

tikv_scheduler_before_write_1_duration_seconds =>
tikv_scheduler_process_before_write_duration_seconds

tikv_scheduler_before_write_2_duration_seconds =>
(merged with before_write_1)

@sticnarf PTAL

BusyJay · 2020-08-26T07:46:36Z

components/raftstore/src/store/fsm/apply.rs

@@ -3127,6 +3127,10 @@ where
                    if channel_timer.is_none() {
                        channel_timer = Some(start);
                    }
+                    if let Some(timer) = channel_timer {
+                        let elapsed = duration_to_sec(timer.elapsed());
+                        APPLY_TASK_WAIT_TIME_HISTOGRAM.observe(elapsed);


It will be observed several times. I think it should either be moved to L3128 or just remove channel_timer.

BusyJay · 2020-08-26T07:49:11Z

src/server/raftkv.rs

+                    if let Some(tag) = tag {
+                        ASYNC_WRITE_DURATIONS_VEC
+                            .get(tag)
+                            .observe(begin_instant.elapsed_secs());


Can the value calculated at L387 be reused? Or how about just keeping one?

L387 doesn't record the duration by operating type (prewrite, commit, etc),
that's why we need a new metric here.

The idea of remove the origin metric crossed my mind,
but I think is not nice to simply remove it because it's depended by some panels,
We could keep both until the new panel totally replace the origin panel and the origin metric doesn't needed anymore.

How about reusing the metrics and add extra dimensions?

That will also make the origin panel malfunction

Why? I think prometheus is OK to be query with less dimensions.

Why? I think prometheus is OK to be query with less dimensions.

That require we rewrite the PromQL, before that, the panel will be error.

What I mean to do is two steps (the first step may last for a while and include more than one PR, that's why I separated it into 2 steps):
1, Improve metrics, as in this PR, not touch any old metrics to keep the old panels work
2, Improve panels, in the mean time, remove the old metrics as well

innerr · 2020-08-26T18:56:37Z

@BusyJay Addressed, PTAL

BusyJay · 2020-09-02T11:53:03Z

src/storage/txn/scheduler.rs

@@ -52,6 +52,17 @@ use crate::storage::{
    ErrorInner as StorageErrorInner,
 };

+use crate::storage::metrics::SCHED_POST_HANDLE_DURATIONS_VEC;


I think you can use use crate::storage::metrics::*;. We allow glob import for metrics.

BusyJay · 2020-09-02T11:55:16Z

src/storage/txn/scheduler.rs

-            tctx.on_schedule();
+            SCHED_LATCH_HISTOGRAM_VEC
+                .get(tctx.tag)
+                .observe(tctx.wait_timer.elapsed_secs());


The timer is reset at L247, so the latch wait time is always smaller than SCHED_WAIT?

This change is for fixing:

3. The SCHED_LATCH_HISTOGRAM_VEC include duration in queue and latch time, which is not correct

After this change, the SCHED_WAIT will response for waiting for an available thread, and SCHED_LATCH will response for waiting for the latch

BusyJay · 2020-09-02T11:57:37Z

src/server/raftkv.rs

+                    if let Some(tag) = tag {
+                        ASYNC_WRITE_DURATIONS_VEC
+                            .get(tag)
+                            .observe(begin_instant.elapsed_secs());


Why? I think prometheus is OK to be query with less dimensions.

Signed-off-by: Liu Cong <innerr@gmail.com>

innerr · 2020-09-04T21:22:28Z

@BusyJay PTAL

BusyJay · 2020-09-11T07:56:31Z

src/storage/txn/scheduler.rs

            .get(self.tag)
-            .observe(self.latch_timer.elapsed_secs());
+            .observe(self.wait_timer.elapsed_secs());


Reusing Instant::now_coarse() can reduce one function call.

BusyJay · 2020-09-11T08:06:39Z

src/storage/txn/scheduler.rs

@@ -379,6 +379,9 @@ impl<E: Engine, L: LockManager> Scheduler<E, L> {
                            "process cmd with snapshot";
                            "cid" => task.cid, "cb_ctx" => ?cb_ctx
                        );
+                        SCHED_ASYNC_SNAPSHOT_DURATIONS_VEC


Isn't it duplicated with storage async snapshot metrics?

CLAassistant · 2020-12-16T03:30:23Z

Thank you for your submission! We really appreciate it. Like many open source projects, we ask that you sign our Contributor License Agreement before we can accept your contribution.
_{You have signed the CLA already but the status is still pending? Let us recheck it.}

CLAassistant · 2020-12-16T03:30:32Z

Thank you for your submission! We really appreciate it. Like many open source projects, we ask that you sign our Contributor License Agreement before we can accept your contribution.
_{You have signed the CLA already but the status is still pending? Let us recheck it.}

ti-chi-bot · 2020-12-31T11:13:41Z

@innerr: PR needs rebase.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

innerr changed the title ~~metrics: Accurate duration tracing of scheduler message handling~~ metrics: Accurate duration tracing of storage/scheduler message handling Aug 4, 2020

sticnarf reviewed Aug 5, 2020

View reviewed changes

innerr force-pushed the accurate_trace branch from 6a9796a to 704cad7 Compare August 10, 2020 14:14

breezewish requested a review from zhongzc August 18, 2020 12:39

BusyJay reviewed Aug 26, 2020

View reviewed changes

innerr force-pushed the accurate_trace branch 3 times, most recently from a244a16 to 04b6c13 Compare August 28, 2020 01:43

BusyJay reviewed Sep 2, 2020

View reviewed changes

metrics: improve duration tracing to make it accurate

f26963f

Signed-off-by: Liu Cong <innerr@gmail.com>

innerr force-pushed the accurate_trace branch from 04b6c13 to f26963f Compare September 4, 2020 21:22

BusyJay reviewed Sep 11, 2020

View reviewed changes

ti-chi-bot added the needs-rebase label Dec 31, 2020

sticnarf mentioned this pull request Apr 14, 2022

Performance Diagnosis Enhancements #12362

Open

40 tasks

innerr closed this Jul 26, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

metrics: Accurate duration tracing of storage/scheduler message handling #8403

metrics: Accurate duration tracing of storage/scheduler message handling #8403

innerr commented Aug 4, 2020 •

edited

sticnarf Aug 5, 2020

innerr Aug 10, 2020 •

edited

sticnarf Aug 5, 2020

innerr Sep 4, 2020

innerr commented Aug 10, 2020 •

edited

BusyJay Aug 26, 2020

innerr Aug 27, 2020

BusyJay Aug 26, 2020

innerr Aug 26, 2020

BusyJay Aug 27, 2020

innerr Aug 27, 2020 •

edited

BusyJay Sep 2, 2020

innerr Sep 4, 2020

innerr commented Aug 26, 2020

BusyJay Sep 2, 2020

innerr Sep 4, 2020

BusyJay Sep 2, 2020

innerr Sep 4, 2020

BusyJay Sep 2, 2020

innerr commented Sep 4, 2020

BusyJay Sep 11, 2020

BusyJay Sep 11, 2020

CLAassistant commented Dec 16, 2020

CLAassistant commented Dec 16, 2020

ti-chi-bot commented Dec 31, 2020

metrics: Accurate duration tracing of storage/scheduler message handling #8403

metrics: Accurate duration tracing of storage/scheduler message handling #8403

Conversation

innerr commented Aug 4, 2020 • edited

What problem does this PR solve?

What is changed and how it works?

Release note

Later works

Choose a reason for hiding this comment

innerr Aug 10, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

innerr commented Aug 10, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

innerr Aug 27, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

innerr commented Aug 26, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

innerr commented Sep 4, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

CLAassistant commented Dec 16, 2020

CLAassistant commented Dec 16, 2020

ti-chi-bot commented Dec 31, 2020

innerr commented Aug 4, 2020 •

edited

innerr Aug 10, 2020 •

edited

innerr commented Aug 10, 2020 •

edited

innerr Aug 27, 2020 •

edited