Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
ti-chi-bot merged 2 commits into from
Mar 25, 2025
Merged

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
f0170da
execdetails: export grpc process and wait time to time details
overvenus Mar 13, 2025
e478cd8
Apply suggestions from code review
overvenus Mar 20, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
24 changes: 24 additions & 0 deletions util/execdetails.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Copy link
Member

@hbisheng hbisheng Mar 19, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

"KvGrpcScheduleTime" sounds like a better name for this measurement, but it might be hard to change the naming now because it's also used in TiKV.

// 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
}
Expand Down Expand Up @@ -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(", ")
Expand All @@ -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))
}
}
Expand All @@ -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
Expand Down
14 changes: 8 additions & 6 deletions util/misc_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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())
}
Loading