database/tidb
2
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

execdetails: log tikv scheduler write details and grpc time in slow query (#60030)

Browse Source 
close pingcap/tidb#60028
This commit is contained in:
Neil Shen
2025-03-28 14:45:06 +08:00
committed by GitHub
parent 7c0c2b16f9
commit aacd24317b
1 changed files with 26 additions and 18 deletions
Download Patch File Download Diff File Expand all files Collapse all files

44
pkg/util/execdetails/execdetails_test.go
View File

@ -390,7 +390,9 @@ func TestRuntimeStatsWithCommit(t *testing.T) {
StoreAddr: "tikv-1:20160",
ExecDetails: util.TiKVExecDetails{
TimeDetail: &util.TimeDetail{
TotalRPCWallTime: 500 * time.Millisecond,
TotalRPCWallTime: 500 * time.Millisecond,
KvGrpcWaitTime: 100 * time.Millisecond,
KvGrpcProcessTime: 200 * time.Millisecond,
},
ScanDetail: &util.ScanDetail{
ProcessedKeys: 10,
@ -403,19 +405,23 @@ func TestRuntimeStatsWithCommit(t *testing.T) {
RocksdbBlockReadDuration: 20 * time.Millisecond,
},
WriteDetail: &util.WriteDetail{
StoreBatchWaitDuration: 10 * time.Microsecond,
ProposeSendWaitDuration: 20 * time.Microsecond,
PersistLogDuration: 30 * time.Microsecond,
RaftDbWriteLeaderWaitDuration: 40 * time.Microsecond,
RaftDbSyncLogDuration: 45 * time.Microsecond,
RaftDbWriteMemtableDuration: 50 * time.Microsecond,
CommitLogDuration: 60 * time.Microsecond,
ApplyBatchWaitDuration: 70 * time.Microsecond,
ApplyLogDuration: 80 * time.Microsecond,
ApplyMutexLockDuration: 90 * time.Microsecond,
ApplyWriteLeaderWaitDuration: 100 * time.Microsecond,
ApplyWriteWalDuration: 101 * time.Microsecond,
ApplyWriteMemtableDuration: 102 * time.Microsecond,
StoreBatchWaitDuration: 10 * time.Microsecond,
ProposeSendWaitDuration: 20 * time.Microsecond,
PersistLogDuration: 30 * time.Microsecond,
RaftDbWriteLeaderWaitDuration: 40 * time.Microsecond,
RaftDbSyncLogDuration: 45 * time.Microsecond,
RaftDbWriteMemtableDuration: 50 * time.Microsecond,
CommitLogDuration: 60 * time.Microsecond,
ApplyBatchWaitDuration: 70 * time.Microsecond,
ApplyLogDuration: 80 * time.Microsecond,
ApplyMutexLockDuration: 90 * time.Microsecond,
ApplyWriteLeaderWaitDuration: 100 * time.Microsecond,
ApplyWriteWalDuration: 101 * time.Microsecond,
ApplyWriteMemtableDuration: 102 * time.Microsecond,
SchedulerLatchWaitDuration: 103 * time.Microsecond,
SchedulerProcessDuration: 104 * time.Microsecond,
SchedulerThrottleDuration: 105 * time.Microsecond,
SchedulerPessimisticLockWaitDuration: 106 * time.Microsecond,
},
},
},
@ -433,12 +439,14 @@ func TestRuntimeStatsWithCommit(t *testing.T) {
Commit: commitDetail,
}
expect := "commit_txn: {prewrite:1s, get_commit_ts:1s, commit:1s, backoff: {time: 1s, prewrite type: [backoff1 backoff2]}, " +
"slowest_prewrite_rpc: {total: 1.000s, region_id: 1000, store: tikv-1:20160, time_detail: {tikv_wall_time: 500ms}, " +
"slowest_prewrite_rpc: {total: 1.000s, region_id: 1000, store: tikv-1:20160, " +
"time_detail: {tikv_grpc_process_time: 200ms, tikv_grpc_wait_time: 100ms, tikv_wall_time: 500ms}, " +
"scan_detail: {total_process_keys: 10, total_keys: 100, rocksdb: {delete_skipped_count: 1, key_skipped_count: 1, " +
"block: {cache_hit_count: 1, read_count: 1, read_byte: 100 Bytes, read_time: 20ms}}}, " +
"write_detail: {store_batch_wait: 10µs, propose_send_wait: 20µs, persist_log: {total: 30µs, write_leader_wait: 40µs, " +
"sync_log: 45µs, write_memtable: 50µs}, commit_log: 60µs, apply_batch_wait: 70µs, apply: {total:80µs, mutex_lock: 90µs, " +
"write_leader_wait: 100µs, write_wal: 101µs, write_memtable: 102µs}, scheduler: {process: 0s}}}, resolve_lock: 1s, region_num:5, write_keys:3" +
"write_leader_wait: 100µs, write_wal: 101µs, write_memtable: 102µs}, scheduler: {process: 104µs, latch_wait: 103µs, " +
"pessimistic_lock_wait: 106µs, throttle: 105µs}}}, resolve_lock: 1s, region_num:5, write_keys:3" +
", write_byte:66, txn_retry:2}"
require.Equal(t, expect, stats.String())
@ -508,8 +516,8 @@ func TestRuntimeStatsWithCommit(t *testing.T) {
"{total_process_keys: 10, total_keys: 100, rocksdb: {delete_skipped_count: 1, key_skipped_count: 1, block: " +
"{cache_hit_count: 1, read_count: 1, read_byte: 100 Bytes, read_time: 20ms}}}, write_detail: " +
"{store_batch_wait: 10µs, propose_send_wait: 20µs, persist_log: {total: 30µs, write_leader_wait: 40µs, sync_log: 45µs, write_memtable: 50µs}, " +
"commit_log: 60µs, apply_batch_wait: 70µs, apply: {total:80µs, mutex_lock: 90µs, write_leader_wait: 100µs, write_wal: 101µs, write_memtable: 102µs}, scheduler: {process: 0s}}}, " +
"lock_rpc:5s, rpc_count:50, retry_count:2}"
"commit_log: 60µs, apply_batch_wait: 70µs, apply: {total:80µs, mutex_lock: 90µs, write_leader_wait: 100µs, write_wal: 101µs, write_memtable: 102µs}, " +
"scheduler: {process: 0s}}}, lock_rpc:5s, rpc_count:50, retry_count:2}"
require.Equal(t, expect, stats.String())
}