session: Adjust cop-tasks' information in slow log to let it can be p…

…arsed by `pt-query` correctly (#10230) (#10300)
pingcap · Apr 29, 2019 · 0f6621d · 0f6621d
1 parent b51f531
commit 0f6621d
Show file tree

Hide file tree

Showing 2 changed files with 22 additions and 12 deletions.
diff --git a/sessionctx/variable/session.go b/sessionctx/variable/session.go
@@ -786,10 +786,18 @@ const (
 	SlowLogStatsInfoStr = "Stats"
 	// SlowLogNumCopTasksStr is the number of cop-tasks.
 	SlowLogNumCopTasksStr = "Num_cop_tasks"
-	// SlowLogCopProcessStr includes some useful information about cop-tasks' process time.
-	SlowLogCopProcessStr = "Cop_process"
-	// SlowLogCopWaitStr includes some useful information about cop-tasks' wait time.
-	SlowLogCopWaitStr = "Cop_wait"
+	// SlowLogCopProcAvg is the average process time of all cop-tasks.
+	SlowLogCopProcAvg = "Cop_proc_avg"
+	// SlowLogCopProcP90 is the p90 process time of all cop-tasks.
+	SlowLogCopProcP90 = "Cop_proc_p90"
+	// SlowLogCopProcMax is the max process time of all cop-tasks.
+	SlowLogCopProcMax = "Cop_proc_max"
+	// SlowLogCopWaitAvg is the average wait time of all cop-tasks.
+	SlowLogCopWaitAvg = "Cop_wait_avg"
+	// SlowLogCopWaitP90 is the p90 wait time of all cop-tasks.
+	SlowLogCopWaitP90 = "Cop_wait_p90"
+	// SlowLogCopWaitMax is the max wait time of all cop-tasks.
+	SlowLogCopWaitMax = "Cop_wait_max"
 	// SlowLogMemMax is the max number bytes of memory used in this statement.
 	SlowLogMemMax = "Mem_max"
 )
@@ -859,12 +867,14 @@ func (s *SessionVars) SlowLogFormat(txnTS uint64, costTime time.Duration, execDe
 	}
 	if copTasks != nil {
 		buf.WriteString(SlowLogPrefixStr + SlowLogNumCopTasksStr + SlowLogSpaceMarkStr + strconv.FormatInt(int64(copTasks.NumCopTasks), 10) + "\n")
-		buf.WriteString(SlowLogPrefixStr + SlowLogCopProcessStr + SlowLogSpaceMarkStr +
-			fmt.Sprintf("Avg_time: %v P90_time: %v Max_time: %v", copTasks.AvgProcessTime,
-				copTasks.P90ProcessTime, copTasks.MaxProcessTime) + "\n")
-		buf.WriteString(SlowLogPrefixStr + SlowLogCopWaitStr + SlowLogSpaceMarkStr +
-			fmt.Sprintf("Avg_time: %v P90_time: %v Max_time: %v", copTasks.AvgWaitTime,
-				copTasks.P90WaitTime, copTasks.MaxWaitTime) + "\n")
+		buf.WriteString(SlowLogPrefixStr + fmt.Sprintf("%v%v%v %v%v%v %v%v%v",
+			SlowLogCopProcAvg, SlowLogSpaceMarkStr, copTasks.AvgProcessTime.Seconds(),
+			SlowLogCopProcP90, SlowLogSpaceMarkStr, copTasks.P90ProcessTime.Seconds(),
+			SlowLogCopProcMax, SlowLogSpaceMarkStr, copTasks.MaxProcessTime.Seconds()) + "\n")
+		buf.WriteString(SlowLogPrefixStr + fmt.Sprintf("%v%v%v %v%v%v %v%v%v",
+			SlowLogCopWaitAvg, SlowLogSpaceMarkStr, copTasks.AvgWaitTime.Seconds(),
+			SlowLogCopWaitP90, SlowLogSpaceMarkStr, copTasks.P90WaitTime.Seconds(),
+			SlowLogCopWaitMax, SlowLogSpaceMarkStr, copTasks.MaxWaitTime.Seconds()) + "\n")
 	}
 	if memMax > 0 {
 		buf.WriteString(SlowLogPrefixStr + SlowLogMemMax + SlowLogSpaceMarkStr + strconv.FormatInt(memMax, 10) + "\n")

diff --git a/sessionctx/variable/session_test.go b/sessionctx/variable/session_test.go
@@ -100,8 +100,8 @@ func (*testSessionSuite) TestSlowLogFormat(c *C) {
 # Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772
 # Stats: t1:pseudo
 # Num_cop_tasks: 10
-# Cop_process: Avg_time: 1s P90_time: 2s Max_time: 3s
-# Cop_wait: Avg_time: 10ms P90_time: 20ms Max_time: 30ms
+# Cop_proc_avg: 1 Cop_proc_p90: 2 Cop_proc_max: 3
+# Cop_wait_avg: 0.01 Cop_wait_p90: 0.02 Cop_wait_max: 0.03
 # Mem_max: 2333
 select * from t;`
 	sql := "select * from t"