add time details

pingcap · Apr 3, 2024 · 0ca425e · 0ca425e
1 parent 8a10278
commit 0ca425e
Show file tree

Hide file tree

Showing 3 changed files with 38 additions and 6 deletions.
diff --git a/pkg/distsql/select_result.go b/pkg/distsql/select_result.go
@@ -527,6 +527,9 @@ func (r *selectResult) updateCopRuntimeStats(ctx context.Context, copStats *copr
 	if copStats.ScanDetail != nil && len(r.copPlanIDs) > 0 {
 		r.ctx.RuntimeStatsColl.RecordScanDetail(r.copPlanIDs[len(r.copPlanIDs)-1], r.storeType.Name(), copStats.ScanDetail)
 	}
+	if len(r.copPlanIDs) > 0 {
+		r.ctx.RuntimeStatsColl.RecordTimeDetail(r.copPlanIDs[len(r.copPlanIDs)-1], r.storeType.Name(), &copStats.TimeDetail)
+	}
 
 	// If hasExecutor is true, it means the summary is returned from TiFlash.
 	hasExecutor := false

diff --git a/pkg/util/execdetails/execdetails.go b/pkg/util/execdetails/execdetails.go
@@ -733,6 +733,7 @@ type CopRuntimeStats struct {
 	// executed on each instance.
 	stats      map[string]*basicCopRuntimeStats
 	scanDetail *util.ScanDetail
+	timeDetail *util.TimeDetail
 	// do not use kv.StoreType because it will meet cycle import error
 	storeType string
 	sync.Mutex
@@ -859,11 +860,20 @@ func (crs *CopRuntimeStats) String() string {
 			buf.WriteString("}")
 		}
 	}
-	if !isTiFlashCop && crs.scanDetail != nil {
-		detail := crs.scanDetail.String()
-		if detail != "" {
-			buf.WriteString(", ")
-			buf.WriteString(detail)
+	if !isTiFlashCop {
+		if crs.scanDetail != nil {
+			detail := crs.scanDetail.String()
+			if detail != "" {
+				buf.WriteString(", ")
+				buf.WriteString(detail)
+			}
+		}
+		if crs.timeDetail != nil {
+			timeDetailStr := crs.timeDetail.String()
+			if timeDetailStr != "" {
+				buf.WriteString(", ")
+				buf.WriteString(timeDetailStr)
+			}
 		}
 	}
 	return buf.String()
@@ -1358,6 +1368,7 @@ func (e *RuntimeStatsColl) GetOrCreateCopStats(planID int, storeType string) *Co
 		copStats = &CopRuntimeStats{
 			stats:      make(map[string]*basicCopRuntimeStats),
 			scanDetail: &util.ScanDetail{},
+			timeDetail: &util.TimeDetail{},
 			storeType:  storeType,
 		}
 		e.copStats[planID] = copStats
@@ -1393,6 +1404,14 @@ func (e *RuntimeStatsColl) RecordScanDetail(planID int, storeType string, detail
 	copStats.scanDetail.Merge(detail)
 }
 
+// RecordTimeDetail records a specific cop tasks's time detail.
+func (e *RuntimeStatsColl) RecordTimeDetail(planID int, storeType string, detail *util.TimeDetail) {
+	copStats := e.GetOrCreateCopStats(planID, storeType)
+	if detail != nil {
+		copStats.timeDetail.Merge(detail)
+	}
+}
+
 // ExistsRootStats checks if the planID exists in the rootStats collection.
 func (e *RuntimeStatsColl) ExistsRootStats(planID int) bool {
 	e.mu.Lock()

diff --git a/pkg/util/execdetails/execdetails_test.go b/pkg/util/execdetails/execdetails_test.go
@@ -478,15 +478,25 @@ func TestCopRuntimeStats2(t *testing.T) {
 		RocksdbBlockReadCount:     20,
 		RocksdbBlockReadByte:      100,
 	}
+	timeDetail := &util.TimeDetail{
+		ProcessTime:      10 * time.Millisecond,
+		SuspendTime:      20 * time.Millisecond,
+		WaitTime:         30 * time.Millisecond,
+		KvReadWallTime:   5 * time.Millisecond,
+		TotalRPCWallTime: 50 * time.Millisecond,
+	}
 	stats.RecordScanDetail(tableScanID, "tikv", scanDetail)
 	for i := 0; i < 1005; i++ {
 		stats.RecordOneCopTask(tableScanID, "tikv", "8.8.8.9", mockExecutorExecutionSummary(2, 2, 2))
 		stats.RecordScanDetail(tableScanID, "tikv", scanDetail)
+		stats.RecordTimeDetail(tableScanID, "tikv", timeDetail)
 	}
 
 	cop := stats.GetOrCreateCopStats(tableScanID, "tikv")
 	expected := "tikv_task:{proc max:0s, min:0s, avg: 2ns, p80:2ns, p95:2ns, iters:2010, tasks:1005}, " +
-		"scan_detail: {total_process_keys: 10060, total_process_keys_size: 10060, total_keys: 15090, rocksdb: {delete_skipped_count: 5030, key_skipped_count: 1006, block: {cache_hit_count: 10060, read_count: 20120, read_byte: 98.2 KB}}}"
+		"scan_detail: {total_process_keys: 10060, total_process_keys_size: 10060, total_keys: 15090, " +
+		"rocksdb: {delete_skipped_count: 5030, key_skipped_count: 1006, block: {cache_hit_count: 10060, read_count: 20120, read_byte: 98.2 KB}}}, " +
+		"total_process_time: 10.1s, total_suspend_time: 20.1s, total_wait_time: 30.2s, total_kv_read_wall_time: 5.03s, tikv_wall_time: 50.3s"
 	require.Equal(t, expected, cop.String())
 	require.Equal(t, expected, cop.String())
 }