From a26794d0c791bcdfcd4234a0ac188be2c5f714a1 Mon Sep 17 00:00:00 2001 From: Yuanjia Zhang Date: Mon, 22 Apr 2019 22:52:54 +0800 Subject: [PATCH] session: Adjust cop-tasks' information in slow log to let it can be parsed by `pt-query` correctly (#10230) --- sessionctx/variable/session.go | 30 +++++++++++++++++++---------- sessionctx/variable/session_test.go | 4 ++-- 2 files changed, 22 insertions(+), 12 deletions(-) diff --git a/sessionctx/variable/session.go b/sessionctx/variable/session.go index 2fd0690f11179..78616a1994efd 100644 --- 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 index c5bc9a717e801..89d9223d96d5a 100644 --- 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"