pingcap / pingcap/tidb

SlowQuery: details of `PrewriteTime` missing, cannot check the real cost of time.

Open
#45,691 2 comments 0 reactions 0 assignees View on GitHub
severity/moderate sig/transaction type/bug
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:
![d9473313-e452-4b5e-987c-87f81b2ce94e](https://github.com/pingcap/tidb/assets/18441614/888bf3a7-b2e9-49e0-989c-4d528d947ee9)

2. others:
![img_v2_442811ee-2805-4bcf-808f-1b999107faeg](https://github.com/pingcap/tidb/assets/18441614/129a3992-250f-4298-8bb9-96fe8ee20177)

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.