execdetails: export grpc process and wait time to time details (#1614)

Signed-off-by: Neil Shen <overvenus@gmail.com>

Co-authored-by: Bisheng Huang <hbisheng@gmail.com>
This commit is contained in:
Neil Shen 2025-03-25 19:05:43 +08:00 committed by GitHub
parent 70e1ca6d5c
commit 0c0c1d1c92
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
2 changed files with 32 additions and 6 deletions

View File

@ -666,6 +666,12 @@ type TimeDetail struct {
// KvReadWallTime is the time used in KV Scan/Get. For get/batch_get,
// this is total duration, which is almost the same with grpc duration.
KvReadWallTime time.Duration
// KvGrpcProcessTime is the time used in TiKV gRPC request processing,
// measured from receiving the request to the start of handling the request.
KvGrpcProcessTime time.Duration
// KvGrpcWaitTime is the time used in TiKV gRPC response waiting, measured
// from when the response is ready to when sending begins.
KvGrpcWaitTime time.Duration
// TotalRPCWallTime is Total wall clock time spent on this RPC in TiKV.
TotalRPCWallTime time.Duration
}
@ -701,6 +707,20 @@ func (td *TimeDetail) String() string {
buf.WriteString("total_kv_read_wall_time: ")
buf.WriteString(FormatDuration(td.KvReadWallTime))
}
if td.KvGrpcProcessTime > 0 {
if buf.Len() > 0 {
buf.WriteString(", ")
}
buf.WriteString("tikv_grpc_process_time: ")
buf.WriteString(FormatDuration(td.KvGrpcProcessTime))
}
if td.KvGrpcWaitTime > 0 {
if buf.Len() > 0 {
buf.WriteString(", ")
}
buf.WriteString("tikv_grpc_wait_time: ")
buf.WriteString(FormatDuration(td.KvGrpcWaitTime))
}
if td.TotalRPCWallTime > 0 {
if buf.Len() > 0 {
buf.WriteString(", ")
@ -722,6 +742,8 @@ func (td *TimeDetail) Merge(detail *TimeDetail) {
atomic.AddInt64((*int64)(&td.SuspendTime), int64(detail.SuspendTime))
atomic.AddInt64((*int64)(&td.WaitTime), int64(detail.WaitTime))
atomic.AddInt64((*int64)(&td.KvReadWallTime), int64(detail.KvReadWallTime))
atomic.AddInt64((*int64)(&td.KvGrpcProcessTime), int64(detail.KvGrpcProcessTime))
atomic.AddInt64((*int64)(&td.KvGrpcWaitTime), int64(detail.KvGrpcWaitTime))
atomic.AddInt64((*int64)(&td.TotalRPCWallTime), int64(detail.TotalRPCWallTime))
}
}
@ -733,6 +755,8 @@ func (td *TimeDetail) MergeFromTimeDetail(timeDetailV2 *kvrpcpb.TimeDetailV2, ti
td.ProcessTime += time.Duration(timeDetailV2.ProcessWallTimeNs) * time.Nanosecond
td.SuspendTime += time.Duration(timeDetailV2.ProcessSuspendWallTimeNs) * time.Nanosecond
td.KvReadWallTime += time.Duration(timeDetailV2.KvReadWallTimeNs) * time.Nanosecond
td.KvGrpcProcessTime += time.Duration(timeDetailV2.KvGrpcProcessTimeNs) * time.Nanosecond
td.KvGrpcWaitTime += time.Duration(timeDetailV2.KvGrpcWaitTimeNs) * time.Nanosecond
td.TotalRPCWallTime += time.Duration(timeDetailV2.TotalRpcWallTimeNs) * time.Nanosecond
} else if timeDetail != nil {
td.WaitTime += time.Duration(timeDetail.WaitWallTimeMs) * time.Millisecond

View File

@ -93,11 +93,13 @@ func TestTimeDetail(t *testing.T) {
detail := &TimeDetail{KvReadWallTime: time.Millisecond * 2, TotalRPCWallTime: time.Millisecond * 3}
assert.Equal(t, "time_detail: {total_kv_read_wall_time: 2ms, tikv_wall_time: 3ms}", detail.String())
detail = &TimeDetail{
ProcessTime: time.Millisecond * 2,
SuspendTime: time.Millisecond * 3,
WaitTime: time.Millisecond * 4,
KvReadWallTime: time.Millisecond * 5,
TotalRPCWallTime: time.Millisecond * 6,
ProcessTime: time.Millisecond * 2,
SuspendTime: time.Millisecond * 3,
WaitTime: time.Millisecond * 4,
KvReadWallTime: time.Millisecond * 5,
KvGrpcProcessTime: time.Millisecond * 6,
KvGrpcWaitTime: time.Millisecond * 7,
TotalRPCWallTime: time.Millisecond * 8,
}
assert.Equal(t, "time_detail: {total_process_time: 2ms, total_suspend_time: 3ms, total_wait_time: 4ms, total_kv_read_wall_time: 5ms, tikv_wall_time: 6ms}", detail.String())
assert.Equal(t, "time_detail: {total_process_time: 2ms, total_suspend_time: 3ms, total_wait_time: 4ms, total_kv_read_wall_time: 5ms, tikv_grpc_process_time: 6ms, tikv_grpc_wait_time: 7ms, tikv_wall_time: 8ms}", detail.String())
}