pingcap / pingcap/tidb

slowlog: execution plan targeting wrong TiKV nodes in Slowlog for performance analysis

Open
#60,089 2 comments 0 reactions 0 assignees View on GitHub
component/tikv type/bug
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:

![Image](https://github.com/user-attachments/assets/d424be99-1229-45e4-9e72-d68cdec2807c)

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

![Image](https://github.com/user-attachments/assets/f78c210c-9085-42fd-b08b-fafc997ea26c)

### 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

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.