# Slow Log And Execution Detail Triage

Use this reference when the user already has a TiDB slow log, statement summary
entry, or `EXPLAIN ANALYZE` output and wants to know whether the query is really
slow inside TiKV, and if so, which TiKV stage is slow first.

This reference is code-backed against the local `v8.5` code lines in:
- TiDB `release-8.5`
- client-go `tidb-8.5`
- TiKV `release-8.5`

## Code Provenance

The key field-generation path is:

1. TiKV fills protobuf execution details.
   - Coprocessor path: `src/coprocessor/tracker.rs`
   - KV get / batch-get / scan path: `src/server/service/kv.rs`
   - Write-stage detail path: `components/tracker/src/lib.rs`
2. client-go converts protobuf details into printable structures.
   - `util/execdetails.go`
3. TiDB prints them into slow log or `EXPLAIN ANALYZE`.
   - slow log: `pkg/sessionctx/variable/session.go`
   - statement detail formatting: `pkg/util/execdetails/execdetails.go`
   - `cop_task` root runtime stats: `pkg/distsql/select_result.go`
   - `tikv_task`, `scan_detail`, `time_detail` runtime stats:
     `pkg/util/execdetails/execdetails.go`

## What The Time Fields Really Mean

client-go defines these semantics in `util/execdetails.go`:

- `tikv_wall_time`
  - printed from `TimeDetail.TotalRPCWallTime`
  - meaning: total wall-clock time spent on this RPC inside TiKV
- `total_process_time`
  - printed from `TimeDetail.ProcessTime`
  - meaning: time spent actually processing the request payload inside TiKV
  - close to CPU-ish wall time, but can still include some internal waits such
    as RocksDB mutex waits
- `total_wait_time`
  - printed from `TimeDetail.WaitTime`
  - meaning: off-CPU waiting inside TiKV, usually queue or other serial waits
- `total_suspend_time`
  - printed from `TimeDetail.SuspendTime`
  - meaning: coprocessor task self-yield time
- `total_kv_read_wall_time`
  - printed from `TimeDetail.KvReadWallTime`
  - meaning: time spent in KV scan/get

For KV read requests in TiKV storage code:
- `wait_wall_time = schedule_wait + snapshot_wait`
- `process_wall_time = time after snapshot received until the request finishes`

For coprocessor requests in TiKV tracker code:
- `process_wall_time` and `wait_wall_time` are tracked separately
- `kv_read_wall_time` is derived from scan / get work
- scan counters and RocksDB block-read counters are attached to `scan_detail`

For write requests, TiKV also attaches `write_detail`, which client-go prints as:
- `store_batch_wait`
- `propose_send_wait`
- `persist_log`
  - `write_leader_wait`
  - `sync_log`
  - `write_memtable`
- `commit_log`
- `apply_batch_wait`
- `apply`
  - `mutex_lock`
  - `write_leader_wait`
  - `write_wal`
  - `write_memtable`

## Parse Surfaces

### TiDB Slow Log

Look for these statement-level fields first:
- `Process_time`
- `Wait_time`
- `Backoff_time`
- `Request_count`
- `Process_keys`
- `Total_keys`
- `Prewrite_time`
- `Commit_time`
- `Get_commit_ts_time`
- `Resolve_lock_time`

Then look for embedded TiKV-local RPC detail blocks:
- `Slowest_prewrite_rpc_detail: {...}`
- `Commit_primary_rpc_detail: {...}`
- `slowest_rpc: {...}` inside `lock_keys`

Inside those embedded blocks, parse:
- `total: ...`
- `time_detail: {...}`
- `scan_detail: {...}`
- `write_detail: {...}`

### EXPLAIN ANALYZE

Look for both root and cop nodes:

- root node:
  - `cop_task: {num, max, avg, p95, tot_proc, tot_wait, ...}`
  - `rpc_info:{...}`
- `cop[tikv]` node:
  - `tikv_task:{...}`
  - `scan_detail:{...}`
  - `time_detail:{...}`
- write DML runtime:
  - `commit_txn:{...}`
  - `slowest_prewrite_rpc:{...}`
  - `commit_primary_rpc:{...}`
  - `lock_keys:{...}`

## Enter Or Exit Rules

### Enter TiKV Diagnosis

Enter `tikv-slow-diagnosis` when:
- a TiKV-local detail block exists
- and `tikv_wall_time` is present
- and `tikv_wall_time` is the main cost inside that block

Use these conservative tests:
- if the block contains `total: X`, treat TiKV as dominant only when
  `tikv_wall_time` is at least the majority of `X`
- if the block has `total_process_time`, `total_wait_time`, and
  `tikv_wall_time`, treat TiKV as dominant only when `tikv_wall_time` is not a
  small leftover after subtracting obvious upstream wait or backoff
- if `EXPLAIN ANALYZE` shows a slow root `cop_task` but the `cop[tikv]` node
  has small `tikv_task` / weak `time_detail`, do not force a TiKV-local
  conclusion

### Exit TiKV Diagnosis

Exit this skill when any of these dominates instead:
- slow log is dominated by `Backoff_time`, `tikvRPC`, `regionMiss`, or similar
  retry / transport symptoms
- slow log is dominated by `Resolve_lock_time`, `lock_rpc`, or lock wait
- write latency is dominated by `Get_commit_ts_time`,
  `Wait_prewrite_binlog_time`, or other non-TiKV-local waits
- `Query_time` is high, but embedded TiKV-local blocks have weak or absent
  `tikv_wall_time`

## Stage Mapping: Read Path

Use the following mapping only after TiKV entry is justified.

### 1. Queue Or Scheduling Wait Is Slow

Evidence:
- `total_wait_time` dominates over `total_process_time`
- `tikv_wall_time` is large mainly because `total_wait_time` is large
- `cop_task.tot_wait` is high

Conclusion:
- the request is slow before doing real TiKV local work
- check read-pool wait, scheduler wait, snapshot wait, or broader TiKV
  contention first

### 2. Snapshot Acquisition Is Slow

Evidence:
- `scan_detail.get_snapshot_time` is high
- `total_wait_time` or early `process_wall_time` is also elevated

Conclusion:
- snapshot acquisition is the earliest visible slow stage
- route to cross-cutting or read-path checks for snapshot pressure, read index,
  and raftstore / snapshot backlog interactions

### 3. KV Scan / Storage Read Is Slow

Evidence:
- `total_kv_read_wall_time` is close to `tikv_wall_time`
- `scan_detail.total_process_keys`, `total_keys`, or
  `rocksdb.block.read_count / read_time / read_byte` are high
- `total_process_time` is also high

Conclusion:
- the main cost is inside KV scan / RocksDB read rather than transport
- if `rocksdb.block.read_time` is prominent, storage read IO is the strongest
  candidate
- if many keys are scanned with modest block-read time, scan volume or poor
  access pattern is the stronger explanation

### 4. Coprocessor Compute Is Slow

Evidence:
- `tikv_task` processing time is high on `cop[tikv]`
- `total_process_time` is high
- `scan_detail` does not show unusually heavy block reads

Conclusion:
- TiKV local executor compute is the first slow stage
- continue with read-path checks for coprocessor CPU, unified read pool, and
  operator-specific pressure

## Stage Mapping: Write Path

Use embedded `write_detail` from `slowest_prewrite_rpc`,
`commit_primary_rpc`, or `lock_keys.slowest_rpc`.

### 1. Store Loop Or Proposal Queue Wait Is Slow

Evidence:
- `store_batch_wait` is high
- or `propose_send_wait` is high

Conclusion:
- the request is waiting before raft persistence really starts
- check store loop backlog, raftstore queue pressure, or write-path flow control

### 2. Raft Log Persistence Is Slow

Evidence:
- `persist_log.total` dominates
- especially `persist_log.sync_log` or `persist_log.write_memtable`

Conclusion:
- raft-engine log persistence is the earliest clear bottleneck
- `sync_log` points more strongly to fsync / disk sync latency
- `write_memtable` points more strongly to raft-engine write path pressure

### 3. Commit Replication Wait Is Slow

Evidence:
- `commit_log` is much larger than local `persist_log.total`

Conclusion:
- leader-side local persistence finished, but waiting for follower
  acknowledgements is slow
- this is usually a raft replication, follower, or network-side stage, not pure
  local disk persistence

### 4. Apply Queue Wait Is Slow

Evidence:
- `apply_batch_wait` dominates

Conclusion:
- apply worker backlog is the earliest visible bottleneck
- continue with apply-thread, KV write, and downstream backlog checks

### 5. KV Apply Is Slow

Evidence:
- `apply.total` dominates
- and one of its subfields is clearly large

Sub-stage mapping:
- `apply.mutex_lock`
  - KV RocksDB lock acquisition / contention
- `apply.write_leader_wait`
  - waiting to become KV write leader
- `apply.write_wal`
  - KV WAL sync cost
- `apply.write_memtable`
  - KV memtable write cost

## Output Wording Rules

When this reference is used, the diagnosis must quote the exact parsed evidence,
for example:
- `Slowest_prewrite_rpc_detail.time_detail.tikv_wall_time = 420ms`
- `Commit_primary_rpc_detail.write_detail.commit_log = 310ms`
- ``cop[tikv] node time_detail: {total_process_time: 180ms, total_wait_time: 15ms, tikv_wall_time: 210ms}``

Use wording like:
- `TiKV-local time is dominant, so this case should enter tikv-slow-diagnosis.`
- `TiKV-local time is not dominant, so tikv-slow-diagnosis should exit and hand off to upstream diagnosis.`
- `Within TiKV, the earliest clearly slow stage is ...`

Do not overclaim:
- if `tikv_wall_time` is large but the field breakdown cannot distinguish
  queueing from storage IO, say that the bottleneck is narrowed to a TiKV-local
  stage but not yet final
- if the evidence points to `commit_log` rather than `persist_log`, do not call
  it a pure local-disk issue