// Copyright 2022 TiKV Project Authors. Licensed under Apache-2.0. // Modifications Copyright 2022 PingCAP, Inc. mod metrics; mod slab; mod tls; use std::time::Instant; use kvproto::kvrpcpb as pb; pub use self::{ slab::{GLOBAL_TRACKERS, INVALID_TRACKER_TOKEN, TrackerToken}, tls::*, }; #[derive(Debug)] pub struct Tracker { pub req_info: RequestInfo, pub metrics: RequestMetrics, // TODO: Add request stage info // pub current_stage: RequestStage, } impl Tracker { pub fn new(req_info: RequestInfo) -> Self { Self { req_info, metrics: Default::default(), } } pub fn write_scan_detail(&self, detail_v2: &mut pb::ScanDetailV2) { detail_v2.set_rocksdb_block_read_byte(self.metrics.block_read_byte); detail_v2.set_rocksdb_block_read_count(self.metrics.block_read_count); detail_v2.set_rocksdb_block_read_nanos(self.metrics.block_read_nanos); detail_v2.set_rocksdb_block_cache_hit_count(self.metrics.block_cache_hit_count); detail_v2.set_rocksdb_key_skipped_count(self.metrics.internal_key_skipped_count); detail_v2.set_rocksdb_delete_skipped_count(self.metrics.deleted_key_skipped_count); detail_v2.set_get_snapshot_nanos(self.metrics.get_snapshot_nanos); detail_v2.set_read_index_propose_wait_nanos(self.metrics.read_index_propose_wait_nanos); detail_v2.set_read_index_confirm_wait_nanos(self.metrics.read_index_confirm_wait_nanos); detail_v2.set_read_pool_schedule_wait_nanos(self.metrics.read_pool_schedule_wait_nanos); detail_v2.set_ia_remote_read_segment_count(self.metrics.ia_remote_read_segment_count); detail_v2.set_ia_remote_read_segment_bytes(self.metrics.ia_remote_read_segment_bytes); detail_v2.set_ia_remote_read_segment_nanos(self.metrics.ia_remote_read_segment_nanos); detail_v2.set_ia_cache_hit_count(self.metrics.ia_cache_hit_count); } pub fn write_write_detail(&self, detail: &mut pb::WriteDetail) { detail.set_latch_wait_nanos(self.metrics.latch_wait_nanos); detail.set_process_nanos(self.metrics.scheduler_process_nanos); detail.set_throttle_nanos(self.metrics.scheduler_throttle_nanos); detail.set_pessimistic_lock_wait_nanos(self.metrics.pessimistic_lock_wait_nanos); detail.set_store_batch_wait_nanos(self.metrics.wf_batch_wait_nanos); detail.set_propose_send_wait_nanos( self.metrics .wf_send_proposal_nanos .saturating_sub(self.metrics.wf_send_to_queue_nanos), ); detail.set_persist_log_nanos( // Some requests can respond before persisting log, e.g., acquire_pessimistic_lock. // Use saturating_sub to avoid underflow. self.metrics .wf_persist_log_nanos .saturating_sub(self.metrics.wf_send_to_queue_nanos), ); detail.set_raft_db_write_leader_wait_nanos( self.metrics.store_mutex_lock_nanos + self.metrics.store_thread_wait_nanos, ); detail.set_raft_db_sync_log_nanos(self.metrics.store_write_wal_nanos); detail.set_raft_db_write_memtable_nanos(self.metrics.store_write_memtable_nanos); // It's an approximation considering generating proposal is fast CPU operation. // And note that the time before flushing the raft message to the RPC channel is // also counted in this value (to be improved in the future). detail.set_commit_log_nanos( // Some requests can respond before committing log, e.g., acquire_pessimistic_lock. // Use saturating_sub to avoid underflow. self.metrics .wf_commit_log_nanos .saturating_sub(self.metrics.wf_batch_wait_nanos), ); detail.set_apply_batch_wait_nanos(self.metrics.apply_wait_nanos); // When async_prewrite_apply is set, the `apply_time_nanos` could be less than // apply_wait_nanos. if self.metrics.apply_time_nanos > self.metrics.apply_wait_nanos { detail .set_apply_log_nanos(self.metrics.apply_time_nanos - self.metrics.apply_wait_nanos); } detail.set_apply_mutex_lock_nanos(self.metrics.apply_mutex_lock_nanos); detail.set_apply_write_leader_wait_nanos(self.metrics.apply_thread_wait_nanos); detail.set_apply_write_wal_nanos(self.metrics.apply_write_wal_nanos); detail.set_apply_write_memtable_nanos(self.metrics.apply_write_memtable_nanos); } pub fn write_ru_v2(&self, ru_v2: &mut pb::Ruv2) { ru_v2.set_kv_engine_cache_miss(self.metrics.kv_engine_cache_miss); } /// Returns read-pool task details when the request has collected at least /// one poll sample. pub fn read_pool_task_details(&self) -> Option { let metrics = &self.metrics.read_pool; if metrics.poll_count == 0 { return None; } let mut details = pb::PoolTaskDetails::default(); details.set_poll_count(metrics.poll_count); details.set_dispatch_count(metrics.dispatch_count); details.set_total_wall_nanos(metrics.total_wall_nanos); details.set_total_queue_wait_nanos(metrics.total_queue_wait_nanos); details.set_max_queue_wait_nanos(metrics.max_queue_wait_nanos); details.set_min_queue_wait_nanos(metrics.min_queue_wait_nanos); details.set_total_wake_wait_nanos(metrics.total_wake_wait_nanos); details.set_max_wake_wait_nanos(metrics.max_wake_wait_nanos); details.set_min_wake_wait_nanos(metrics.min_wake_wait_nanos); details.set_fair_queue_enabled(metrics.fair_queue_enabled); details .set_total_fair_queue_waited_task_slices(metrics.total_fair_queue_waited_task_slices); details.set_max_fair_queue_waited_task_slices(metrics.max_fair_queue_waited_task_slices); details.set_min_fair_queue_waited_task_slices(metrics.min_fair_queue_waited_task_slices); details.set_poll_cpu_nanos(metrics.poll_cpu_nanos); details.set_max_poll_cpu_nanos(metrics.max_poll_cpu_nanos); details.set_min_poll_cpu_nanos(metrics.min_poll_cpu_nanos); details.set_poll_wall_nanos(metrics.poll_wall_nanos); details.set_min_poll_wall_nanos(metrics.min_poll_wall_nanos); details.set_max_poll_wall_nanos(metrics.max_poll_wall_nanos); Some(details) } } #[derive(Debug, Default)] pub struct RequestInfo { pub region_id: u64, pub start_ts: u64, pub task_id: u64, pub resource_group_tag: Vec, pub request_type: RequestType, pub is_remote: bool, } impl RequestInfo { pub fn new(ctx: &pb::Context, request_type: RequestType, start_ts: u64) -> RequestInfo { RequestInfo { region_id: ctx.get_region_id(), start_ts, task_id: ctx.get_task_id(), resource_group_tag: ctx.get_resource_group_tag().to_vec(), request_type, is_remote: false, } } } #[derive(Debug, Clone, Copy, PartialEq, Default)] pub enum RequestType { #[default] Unknown, KvGet, KvBatchGet, KvBatchGetCommand, KvScan, KvScanLock, KvPrewrite, KvCommit, KvPessimisticLock, KvCheckTxnStatus, KvCheckSecondaryLocks, KvCleanup, KvResolveLock, KvTxnHeartBeat, KvRollback, KvPessimisticRollback, KvFlashbackToVersion, CoprocessorDag, CoprocessorAnalyze, CoprocessorChecksum, } /// Per-request scheduling and execution metrics for a task running in a worker /// pool. /// /// The following timeline shows how the duration and count fields relate to /// one another. It is not drawn to scale. /// /// ```text /// tracked/scheduled #1 dispatch #1 scheduled #2 dispatch #2 /// t0/s1 d1 s2 d2 /// |==================|[ poll #1 ][ immediate poll #2 ]~~~~～|===============|[ poll #3 ]| /// | <-------- one dispatch -------> | /// |<------------------------------ total wall ----------------------------------------->| /// < queue wait #1 > /// ``` /// /// Tracking starts immediately before the first submission, so `t0` and `s1` /// are shown at the same point even though they are separate timestamps. /// `total_wall_nanos` covers `t0` through the final poll's completion. /// - A queue-wait sample covers `scheduled` through `dispatch`, while the task /// is ready to run but still waiting for a worker. Fair-queue waited-slice /// samples describe the same queue-wait period when fairness is enabled. /// - A wake-wait sample covers the previous poll's completion through the next /// `scheduled` time, while the task is pending and has not yet been /// rescheduled. It is zero when the task was already scheduled by the time /// the previous poll completed. /// - A poll-wall sample covers one call to `Future::poll`; its poll-CPU sample /// is the thread CPU time consumed within that wall-time interval. /// - Immediate repolls create additional poll samples but remain in the same /// dispatch, so they do not create new queue-wait or wake-wait samples. #[derive(Debug, Default, Clone)] pub struct PoolTaskMetrics { /// Total wall time from starting task tracking immediately before pool /// submission until the task's final poll completes. pub total_wall_nanos: u64, /// Cumulative time from enqueueing the task until dispatching it to a /// worker. pub total_queue_wait_nanos: u64, /// Maximum queue wait time among all dispatches. pub max_queue_wait_nanos: u64, /// Minimum queue wait time among all dispatches, or zero if none was /// recorded. pub min_queue_wait_nanos: u64, /// Cumulative time spent pending while waiting to be woken. pub total_wake_wait_nanos: u64, /// Maximum pending-to-wake time among all wakeups. pub max_wake_wait_nanos: u64, /// Minimum pending-to-wake time among all wakeups, or zero if none was /// recorded. pub min_wake_wait_nanos: u64, /// Whether this task was dispatched through a fair queue. /// /// When this is false, zero-valued fair-queue wait metrics mean that no /// fair-queue data was recorded rather than that the task waited for zero /// task slices. pub fair_queue_enabled: bool, /// Total number of task slices dispatched ahead of this task while it /// waited in a fair queue. pub total_fair_queue_waited_task_slices: u64, /// Maximum number of task slices dispatched ahead of this task during one /// fair-queue wait. pub max_fair_queue_waited_task_slices: u64, /// Minimum number of task slices dispatched ahead of this task during one /// fair-queue wait, or zero if none was recorded. pub min_fair_queue_waited_task_slices: u64, /// Number of times the task is dispatched from the queue to a worker. /// /// Immediate repolls in the same worker dispatch are not counted /// separately. pub dispatch_count: u64, /// Cumulative thread CPU time consumed by all future polls. pub poll_cpu_nanos: u64, /// Maximum thread CPU time consumed by a single future poll. pub max_poll_cpu_nanos: u64, /// Minimum thread CPU time consumed by a single future poll, or zero if /// none was recorded. pub min_poll_cpu_nanos: u64, /// Cumulative wall time consumed by all future polls. pub poll_wall_nanos: u64, /// Minimum wall time consumed by a single future poll, or zero if none was /// recorded. pub min_poll_wall_nanos: u64, /// Maximum wall time consumed by a single future poll. pub max_poll_wall_nanos: u64, /// Number of times the future is polled, including immediate repolls within /// one worker dispatch. pub poll_count: u64, } #[derive(Debug, Default, Clone)] pub struct RequestMetrics { pub get_snapshot_nanos: u64, pub read_index_propose_wait_nanos: u64, pub read_index_confirm_wait_nanos: u64, pub read_pool_schedule_wait_nanos: u64, /// Scheduling and execution metrics for this request's read-pool task. pub read_pool: PoolTaskMetrics, pub local_read: bool, pub block_cache_hit_count: u64, pub block_read_count: u64, pub block_read_byte: u64, pub block_read_nanos: u64, pub internal_key_skipped_count: u64, pub deleted_key_skipped_count: u64, /// Number of IA segments fetched from remote storage for this request. pub ia_remote_read_segment_count: u64, /// Total bytes fetched by those IA remote segment reads. pub ia_remote_read_segment_bytes: u64, /// Total time spent on those IA remote segment reads. pub ia_remote_read_segment_nanos: u64, /// Number of request-visible reads that were served from the IA cache. /// /// This includes executor reads that hit a segment populated by an earlier /// prefetch in the same request. pub ia_cache_hit_count: u64, pub pessimistic_lock_wait_nanos: u64, pub latch_wait_nanos: u64, pub scheduler_process_nanos: u64, pub scheduler_throttle_nanos: u64, // temp instant used in raftstore metrics, first be the instant when creating the write // callback, then reset when it is ready to apply pub write_instant: Option, pub wf_batch_wait_nanos: u64, pub wf_send_to_queue_nanos: u64, pub wf_send_proposal_nanos: u64, pub wf_persist_log_nanos: u64, pub wf_before_write_nanos: u64, pub wf_write_end_nanos: u64, pub wf_kvdb_end_nanos: u64, pub wf_commit_log_nanos: u64, pub commit_not_persisted: bool, pub store_mutex_lock_nanos: u64, // should be 0 if using raft-engine pub store_thread_wait_nanos: u64, pub store_write_wal_nanos: u64, pub store_write_memtable_nanos: u64, pub store_time_nanos: u64, pub apply_wait_nanos: u64, pub apply_time_nanos: u64, pub apply_mutex_lock_nanos: u64, pub apply_thread_wait_nanos: u64, pub apply_write_wal_nanos: u64, pub apply_write_memtable_nanos: u64, pub kv_engine_cache_miss: u64, // recorded outside the read_pool thread, accessed inside the read_pool thread for topsql usage pub grpc_req_size: u64, }