Repository: tikv/tikv (language: rust)

Issue:
Storage async write duration is inaccurate
## Bug Report

<!-- Thanks for your bug report! Don't worry if you can't fill out all the sections. -->

As title, because it mistakenly includes task wait time in the scheduler worker pool.
As a result, the metric is higher than the actual value, particularly when TiKV is under load.

https://github.com/tikv/tikv/blob/ff78c79606a24610f96cd5b01a9d5268795027d1/src/server/raftkv/mod.rs#L585-L601

I believe this change is made by  accident because it is introduced in a refactor PR https://github.com/tikv/tikv/pull/13854 .


### What version of TiKV are you using?
<!-- You can run `tikv-server --version` -->

v7.5.2

### Steps to reproduce
<!-- If possible, provide a recipe for reproducing the error. A complete runnable program is good. -->

Run go-yscb 100% update with 1000 threads.

### What did you expect?

Do not include task wait time in the scheduler worker pool.



Discussion / hints:

Fix patch:
diff --git a/src/server/raftkv/mod.rs b/src/server/raftkv/mod.rs
index 56b0b1adfe7..e5d5e7f4565 100644
--- a/src/server/raftkv/mod.rs
+++ b/src/server/raftkv/mod.rs
@@ -44,8 +44,8 @@ use raftstore::{
     errors::Error as RaftServerError,
     router::{LocalReadRouter, RaftStoreRouter},
     store::{
-        self, Callback as StoreCallback, RaftCmdExtraOpts, ReadCallback, ReadIndexContext,
-        ReadResponse, RegionSnapshot, StoreMsg, WriteResponse,
+        self, Callback as StoreCallback, RaftCmdExtraOpts, ReadIndexContext, ReadResponse,
+        RegionSnapshot, StoreMsg, WriteResponse,
     },
 };
 use thiserror::Error;
@@ -55,7 +55,7 @@ use tikv_util::{
     future::{paired_future_callback, paired_must_called_future_callback},
     time::Instant,
 };
-use tracker::GLOBAL_TRACKERS;
+use tracker::{get_tls_tracker_token, GLOBAL_TRACKERS};
 use txn_types::{Key, TimeStamp, TxnExtra, TxnExtraScheduler, WriteBatchFlags};
 
 use super::metrics::*;
@@ -482,6 +482,10 @@ where
         let applied_cb = Box::new(move |resp: WriteResponse| {
             let mut res = match on_write_result::<E::Snapshot>(resp) {
                 Ok(CmdRes::Resp(_)) => {
+                    ASYNC_REQUESTS_COUNTER_VEC.write.success.inc();
+                    ASYNC_REQUESTS_DURATIONS_VEC
+                        .write
+                        .observe(begin_instant.saturating_elapsed_secs());
                     fail_point!("raftkv_async_write_finish");
                     Ok(())
                 }
@@ -509,18 +513,9 @@ where
             tx.notify(res);
         }
         rx.inspect(move |ev| {
-            let WriteEvent::Finished(res) = ev else { return };
-            match res {
-                Ok(()) => {
-                    ASYNC_REQUESTS_COUNTER_VEC.write.success.inc();
-                    ASYNC_REQUESTS_DURATIONS_VEC
-                        .write
-                        .observe(begin_instant.saturating_elapsed_secs());
-                }
-                Err(e) => {
-                    let status_kind = get_status_kind_from_engine_error(e);
-                    ASYNC_REQUESTS_COUNTER_VEC.write.get(status_kind).inc();
-                }
+            if let WriteEvent::Finished(Err(e)) = ev {
+                let status_kind = get_status_kind_from_engine_error(e);
+                ASYNC_REQUESTS_COUNTER_VEC.write.get(status_kind).inc();
             }
         })
     }
@@ -564,10 +559,39 @@ where
         let mut cmd = RaftCmdRequest::default();
         cmd.set_header(header);
         cmd.set_requests(vec![req].into());
+        let tracker = get_tls_tracker_token();
         let store_cb = StoreCallback::read(Box::new(move |resp| {
-            cb(on_read_result(resp).map_err(Error::into));
+            let res = on_read_result(resp).map_err(Error::into);
+            if res.is_ok() {
+                let elapse = begin_instant.saturating_elapsed_secs();
+                GLOBAL_TRACKERS.with_tracker(tracker, |tracker| {
+                    if tracker.metrics.read_index_propose_wait_nanos > 0 {
+                        ASYNC_REQUESTS_DURATIONS_VEC
+                            .snapshot_read_index_propose_wait
+                            .observe(
+                                tracker.metrics.read_index_propose_wait_nanos as f64
+                                    / 1_000_000_000.0,
+                            );
+                        // snapshot may be handled by lease read in raftstore
+                        if tracker.metrics.read_index_confirm_wait_nanos > 0 {
+                            ASYNC_REQUESTS_DURATIONS_VEC
+                                .snapshot_read_index_confirm
+                                .observe(
+                                    tracker.metrics.read_index_confirm_wait_nanos as f64
+                                        / 1_000_000_000.0,
+                                );
+                        }
+                    } else if tracker.metrics.local_read {
+                        ASYNC_REQUESTS_DURATIONS_VEC
+                            .snapshot_local_read
+                            .observe(elapse);
+                    }
+                });
+                ASYNC_REQUESTS_DURATIONS_VEC.snapshot.observe(elapse);
+                ASYNC_REQUESTS_COUNTER_VEC.snapshot.success.inc();
+            }
+            cb(res);
         }));
-        let tracker = *store_cb.read_tracker().unwrap();
 
         if res.is_ok() {
             res = self
@@ -598,35 +622,7 @@ where
                     };
                     Err(e)
                 }
-                Ok(CmdRes::Snap(s)) => {
-                    let elapse = begin_instant.saturating_elapsed_secs();
-                    GLOBAL_TRACKERS.with_tracker(tracker, |tracker| {
-                        if tracker.metrics.read_index_propose_wait_nanos > 0 {
-                            ASYNC_REQUESTS_DURATIONS_VEC
-                                .snapshot_read_index_propose_wait
-                                .observe(
-                                    tracker.metrics.read_index_propose_wait_nanos as f64
-                                        / 1_000_000_000.0,
-                                );
-                            // snapshot may be hanlded by lease read in raftstore
-                            if tracker.metrics.read_index_confirm_wait_nanos > 0 {
-                                ASYNC_REQUESTS_DURATIONS_VEC
-                                    .snapshot_read_index_confirm
-                                    .observe(
-                                        tracker.metrics.read_index_confirm_wait_nanos as f64
-                                            / 1_000_000_000.0,
-                                    );
-                            }
-                        } else if tracker.metrics.local_read {
-                            ASYNC_REQUESTS_DURATIONS_VEC
-                                .snapshot_local_read
-                                .observe(elapse);
-                        }
-                    });
-                    ASYNC_REQUESTS_DURATIONS_VEC.snapshot.observe(elapse);
-                    ASYNC_REQUESTS_COUNTER_VEC.snapshot.success.inc();
-                    Ok(s)
-                }
+                Ok(CmdRes::Snap(s)) => Ok(s),
                 Err(e) => {
                     let status_kind = get_status_kind_from_engine_error(&e);
                     ASYNC_REQUESTS_COUNTER_VEC.snapshot.get(status_kind).inc();


Test patch: