slowlog: execution plan targeting wrong TiKV nodes in Slowlog for performance analysis
- Dominant language
- Go
- Stars
- 40.5k
- Forks
- 6.2k
- PR merge metrics
- PR metrics pending
Description
## Bug Report
This issue occurs when injecting I/O delays to one TiKV, triggering leader eviction
during this tests. And there exists expected slow queries when evicting leaders,
but the execution plan has showed wrong TiKV nodes in Slowlog, which is
misleading for performance analysis.
Taking the following execution plan as an example:
```
| id | estRows | estCost | actRows | task | access object | execution info | operator info | memory | disk |
| Insert_1 | 0.00 | 0.00 | 0 | root | | time:58.9µs, loops:1, prepare: 14.2µs, insert:44.7µs, commit_txn: {prewrite:30.1s, get_commit_ts:215.2µs, commit:883.1µs, backoff: {time: 79ms, prewrite type: [tikvRPC]}, slowest_prewrite_rpc: {total: 30.083s, region_id: 754, store: [tc-tikv-1.tc-tikv-peer.io](http://tc-tikv-1.tc-tikv-peer.io/)-jitter-sysbench-tps-7746042-1-384.svc:20160, time_detail: {tikv_wall_time: 609µs}, scan_detail: {get_snapshot_time: 6.46µs, rocksdb: {block: {cache_hit_count: 17}}}, write_detail: {store_batch_wait: 5.45µs, propose_send_wait: 0s, persist_log: {total: 160.4µs, write_leader_wait: 60ns, sync_log: 29.4µs, write_memtable: 3.62µs}, commit_log: 388.3µs, apply_batch_wait: 18.5µs, apply: {total:61.6µs, mutex_lock: 0s, write_leader_wait: 0s, write_wal: 10.9µs, write_memtable: 27.4µs}}}, commit_primary_rpc: {total: 0.001s, region_id: 754, store: [tc-tikv-1.tc-tikv-peer.io](http://tc-tikv-1.tc-tikv-peer.io/)-jitter-sysbench-tps-7746042-1-384.svc:20160, time_detail: {tikv_wall_time: 579.6µs}, scan_detail: {get_snapshot_time: 6.57µs, rocksdb: {block: {}}}, write_detail: {store_batch_wait: 3.18µs, propose_send_wait: 0s, persist_log: {total: 68.9µs, write_leader_wait: 37ns, sync_log: 26.8µs, write_memtable: 6.15µs}, commit_log: 461.1µs, apply_batch_wait: 7.27µs, apply: {total:31.8µs, mutex_lock: 0s, write_leader_wait: 0s, write_wal: 4.33µs, write_memtable: 10.7µs}}}, region_num:2, write_keys:2, write_byte:254} | N/A | 466 Bytes | N/A |
```
where the real abnormal / slow node is `tikv-0` rather than `tikv-1`.
And after digging into the relevant logs in `tikv-0`, which is the real slow node,
I've found that the slow logs on scheduling:

Meanwhile, the metrics in TiKV also showed that the real slow node is `tikv-0`:

### 1. Minimal reproduce step (Required)
1. Prepare a workload and executing.
2. Inject I/O delays to one TiKV node, waiting for auto slow-node eviction (by `evict-slow-store-scheduler`).
3. Check the execution plan in the slow log of relevant slow queries.
### 2. What did you expect to see? (Required)
The execution plan can print the real slow node or abnormal node => `tikv-0`.
### 3. What did you see instead (Required)
The execution plan prints a wrong TiKV node => `tikv-`.
### 4. What is your TiDB version? (Required)
master -> v8.5.1
Contributor guide
Assessment
This issue has not been assessed yet.