SlowQuery: details of `PrewriteTime` missing, cannot check the real cost of time.
- Dominant language
- Go
- Stars
- 40.5k
- Forks
- 6.2k
- PR merge metrics
- PR metrics pending
Description
## Bug Report
Got a slow-query, but cannot inspect the details on the cost of time:
+ `QueryTime` != `Backoff_Time` + others.
+ Missing details on `PrewriteTime`.
+ Missing `Prewrite_Backoff_Time`.
The slow-query:
```
# Time: 2023-07-31T04:23:27.570998027Z
# Txn_start_ts: 443227146209198086
# User@Host: root[root] @ 10.233.108.19 [10.233.108.19]
# Conn_ID: 2782921198
# Query_time: 24.833789483
# Parse_time: 0.000006661
# Compile_time: 0.000027808
# Rewrite_time: 0.000000927
# Optimize_time: 0.000265165
# Wait_TS: 0
# Prewrite_time: 24.818357465 Commit_time: 0.014932688 Get_commit_ts_time: 0.000168216 Get_latest_ts_time: 0.000215814 Commit_backoff_time: 6.086 Prewrite_Backoff_types: [tikvRPC regionMiss regionMiss regionMiss re
gionMiss regionMiss regionMiss regionMiss regionMiss regionMiss regionMiss regionMiss regionMiss regionMiss regionMiss regionMiss regionMiss regionMiss regionScheduling regionMiss regionScheduling regionMiss] Slowe
st_prewrite_rpc_detail: {total:0.002s, region_id: 312, store: tc-tikv-1.tc-tikv-peer.endless-ha-test-tps-1862622-1-404.svc:20160, tikv_wall_time: 1.35ms, scan_detail: {get_snapshot_time: 4.4µs, rocksdb: {block: {}}
}, write_detail: {store_batch_wait: 60.5µs, propose_send_wait: 0s, persist_log: {total: 543.1µs, write_leader_wait: 61ns, sync_log: 94.7µs, write_memtable: 8.75µs}, commit_log: 685.5µs, apply_batch_wait: 49.7µs, ap
ply: {total:227.8µs, mutex_lock: 0s, write_leader_wait: 0s, write_wal: 68.1µs, write_memtable: 100.8µs}}} Commit_primary_rpc_detail: {total:0.002s, region_id: 312, store: tc-tikv-1.tc-tikv-peer.endless-ha-test-tps-
1862622-1-404.svc:20160, tikv_wall_time: 1.35ms, scan_detail: {get_snapshot_time: 4.4µs, rocksdb: {block: {}}}, write_detail: {store_batch_wait: 60.5µs, propose_send_wait: 0s, persist_log: {total: 543.1µs, write_le
ader_wait: 61ns, sync_log: 94.7µs, write_memtable: 8.75µs}, commit_log: 685.5µs, apply_batch_wait: 49.7µs, apply: {total:227.8µs, mutex_lock: 0s, write_leader_wait: 0s, write_wal: 68.1µs, write_memtable: 100.8µs}}}
Write_keys: 31 Write_size: 3855 Prewrite_region: 11
# DB: tpcc
# Is_internal: false
# Digest: 9505cacb7c710ed17125fcc6cb3669e8ddca6c8cd8af6a31f6b3cd64604c3098
# Num_cop_tasks: 0
# Mem_max: 8192
# Prepared: false
# Plan_from_cache: false
# Plan_from_binding: false
# Has_more_results: false
# KV_total: 74.862785454
# PD_total: 0.017029345
# Backoff_total: 19.86
# Write_sql_response_total: 0
# Result_rows: 0
# Succ: true
# IsExplicitTxn: true
# IsSyncStatsFailed: false
# Prev_stmt: INSERT into order_line (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_quantity, ol_amount, ol_dist_info) VALUES (?,?,?,?,?,?,?,?,?),(?,?,?,?,?,?,?,?,?),(?,?,?,?,?,?,?,?,?),(?,?,?,?,
?,?,?,?,?),(?,?,?,?,?,?,?,?,?),(?,?,?,?,?,?,?,?,?) [arguments: (3005, 7, 650, 1, 75632, 650, 7, 600.6443374700999, "BCIRXIUVSJVOMTJGRRDJURAL", 3005, 7, 650, 2, 56632, 650, 1, 27.956497484699998, "KGPVGDQNLILFNRRNBY
YKYKWM", 3005, 7, 650, 3, 38506, 650, 7, 666.4224535541999, "EMXASVSHHNUTZLQQQMTQUZGN", 3005, 7, 650, 4, 22844, 650, 5, 521.2444791779999, "QBZZZBOIOOOEAPNHHFNHBPWO", 3005, 7, 650, 5, 71936, 650, 7, 689.44106948849
99, "AKOOBQXKIWVKOZVLSDUPQBVK", 3005, 7, 650, 6, 73148, 650, 7, 726.4645391304, "SJOQDNNVHTXNHPJPENEIQVUX")]
use tpcc;
COMMIT;
```
### 1. Minimal reproduce step (Required)
### 2. What did you expect to see? (Required)
The missing details of `prewrite` can be showed, matching the `QueryTime`.
### 3. What did you see instead (Required)
`QueryTime` != `Backoff_Time` + others.
### 4. What is your TiDB version? (Required)
Master branch.
```
[printer.go:47] ["Welcome to TiDB."]
["Release Version"=v7.3.0-alpha] [Edition=Community]
["Git Commit Hash"=06ea55d0c5b90c1451690951856e595d2290a55c]
["Git Branch"=heads/refs/tags/v7.3.0-alpha]
["UTC Build Time"="2023-07-29 11:46:11"]
[GoVersion=go1.20.6]
["Race Enabled"=false]
["Check Table Before Drop"=false]
```
Question: what's the details in `PrewriteTime`?
And more details about this case:
1. gRPC on `kv_prewrite` did not cost a lot from TiKV metrics:

2. others:

Contributor guide
Assessment
This issue has not been assessed yet.