From 39d8fb80ef42157b507a4a7c8d5565e97c73a4b7 Mon Sep 17 00:00:00 2001 From: qw4990 Date: Tue, 16 Apr 2019 14:40:22 +0800 Subject: [PATCH 1/6] add CopTasksDetails --- sessionctx/stmtctx/stmtctx.go | 45 +++++++++++++++++++++++++++++++++++ 1 file changed, 45 insertions(+) diff --git a/sessionctx/stmtctx/stmtctx.go b/sessionctx/stmtctx/stmtctx.go index de6cd9fb1857e..3471c322ac644 100644 --- a/sessionctx/stmtctx/stmtctx.go +++ b/sessionctx/stmtctx/stmtctx.go @@ -15,6 +15,7 @@ package stmtctx import ( "math" + "sort" "sync" "time" @@ -95,6 +96,7 @@ type StatementContext struct { warnings []SQLWarn histogramsNotLoad bool execDetails execdetails.ExecDetails + allExecDetails []*execdetails.ExecDetails } // PrevAffectedRows is the affected-rows value(DDL is 0, DML is the number of affected rows). PrevAffectedRows int64 @@ -392,6 +394,7 @@ func (sc *StatementContext) MergeExecDetails(details *execdetails.ExecDetails, c sc.mu.execDetails.RequestCount++ sc.mu.execDetails.TotalKeys += details.TotalKeys sc.mu.execDetails.ProcessedKeys += details.ProcessedKeys + sc.mu.allExecDetails = append(sc.mu.allExecDetails, details) } sc.mu.execDetails.CommitDetail = commitDetails sc.mu.Unlock() @@ -423,3 +426,45 @@ func (sc *StatementContext) ShouldIgnoreOverflowError() bool { } return false } + +// CopTasksDetails returns some useful information of cop-tasks during execution. +func (sc *StatementContext) CopTasksDetails() *CopTasksDetails { + sc.mu.Lock() + defer sc.mu.Unlock() + n := len(sc.mu.allExecDetails) + d := &CopTasksDetails{ + NumCopTasks: n, + AvgProcessTime: sc.mu.execDetails.ProcessTime / time.Duration(n), + AvgWaitTime: sc.mu.execDetails.WaitTime / time.Duration(n), + } + + sort.Slice(sc.mu.allExecDetails, func(i, j int) bool { + return sc.mu.allExecDetails[i].ProcessTime < sc.mu.allExecDetails[j].ProcessTime + }) + d.P99ProcessTime = sc.mu.allExecDetails[n*9/10].ProcessTime + d.MaxProcessTime = sc.mu.allExecDetails[n-1].ProcessTime + d.MaxProcessAddress = sc.mu.allExecDetails[n-1].CalleeAddress + + sort.Slice(sc.mu.allExecDetails, func(i, j int) bool { + return sc.mu.allExecDetails[i].WaitTime < sc.mu.allExecDetails[j].WaitTime + }) + d.P99WaitTime = sc.mu.allExecDetails[n*9/10].WaitTime + d.MaxProcessTime = sc.mu.allExecDetails[n-1].WaitTime + d.MaxProcessAddress = sc.mu.allExecDetails[n-1].CalleeAddress + return d +} + +//CopTasksDetails collects some useful information of cop-tasks during execution. +type CopTasksDetails struct { + NumCopTasks int + + AvgProcessTime time.Duration + P99ProcessTime time.Duration + MaxProcessAddress string + MaxProcessTime time.Duration + + AvgWaitTime time.Duration + P99WaitTime time.Duration + MaxWaitAddress string + MaxWaitTime time.Duration +} From bf9a15e215dc536c41ae725c47bf1f8b72adb781 Mon Sep 17 00:00:00 2001 From: qw4990 Date: Tue, 16 Apr 2019 15:08:51 +0800 Subject: [PATCH 2/6] add more tests --- sessionctx/stmtctx/stmtctx.go | 31 ++++++++++++------- sessionctx/stmtctx/stmtctx_test.go | 46 +++++++++++++++++++++++++++++ sessionctx/variable/session.go | 9 +++++- sessionctx/variable/session_test.go | 15 +++++++++- 4 files changed, 89 insertions(+), 12 deletions(-) create mode 100644 sessionctx/stmtctx/stmtctx_test.go diff --git a/sessionctx/stmtctx/stmtctx.go b/sessionctx/stmtctx/stmtctx.go index 3471c322ac644..d0f7b762212ae 100644 --- a/sessionctx/stmtctx/stmtctx.go +++ b/sessionctx/stmtctx/stmtctx.go @@ -14,6 +14,7 @@ package stmtctx import ( + "fmt" "math" "sort" "sync" @@ -432,25 +433,26 @@ func (sc *StatementContext) CopTasksDetails() *CopTasksDetails { sc.mu.Lock() defer sc.mu.Unlock() n := len(sc.mu.allExecDetails) - d := &CopTasksDetails{ - NumCopTasks: n, - AvgProcessTime: sc.mu.execDetails.ProcessTime / time.Duration(n), - AvgWaitTime: sc.mu.execDetails.WaitTime / time.Duration(n), + d := &CopTasksDetails{NumCopTasks: n} + if n == 0 { + return d } + d.AvgProcessTime = sc.mu.execDetails.ProcessTime / time.Duration(n) + d.AvgWaitTime = sc.mu.execDetails.WaitTime / time.Duration(n) sort.Slice(sc.mu.allExecDetails, func(i, j int) bool { return sc.mu.allExecDetails[i].ProcessTime < sc.mu.allExecDetails[j].ProcessTime }) - d.P99ProcessTime = sc.mu.allExecDetails[n*9/10].ProcessTime + d.P90ProcessTime = sc.mu.allExecDetails[n*9/10].ProcessTime d.MaxProcessTime = sc.mu.allExecDetails[n-1].ProcessTime d.MaxProcessAddress = sc.mu.allExecDetails[n-1].CalleeAddress sort.Slice(sc.mu.allExecDetails, func(i, j int) bool { return sc.mu.allExecDetails[i].WaitTime < sc.mu.allExecDetails[j].WaitTime }) - d.P99WaitTime = sc.mu.allExecDetails[n*9/10].WaitTime - d.MaxProcessTime = sc.mu.allExecDetails[n-1].WaitTime - d.MaxProcessAddress = sc.mu.allExecDetails[n-1].CalleeAddress + d.P90WaitTime = sc.mu.allExecDetails[n*9/10].WaitTime + d.MaxWaitTime = sc.mu.allExecDetails[n-1].WaitTime + d.MaxWaitAddress = sc.mu.allExecDetails[n-1].CalleeAddress return d } @@ -459,12 +461,21 @@ type CopTasksDetails struct { NumCopTasks int AvgProcessTime time.Duration - P99ProcessTime time.Duration + P90ProcessTime time.Duration MaxProcessAddress string MaxProcessTime time.Duration AvgWaitTime time.Duration - P99WaitTime time.Duration + P90WaitTime time.Duration MaxWaitAddress string MaxWaitTime time.Duration } + +// String implements the fmt.Stringer interface. +func (d CopTasksDetails) String() string { + // formatted like slow log + return fmt.Sprintf("Num_tasks: %d Avg_process_time %v P90_process_time %v Max_process_time %v"+ + "Max_process_address %s Avg_wait_time %v P90_wait_time %v Max_wait_time %v Max_wait_address %s", + d.NumCopTasks, d.AvgProcessTime, d.P90ProcessTime, d.MaxProcessTime, d.MaxProcessAddress, + d.AvgWaitTime, d.P90WaitTime, d.MaxWaitTime, d.MaxWaitAddress) +} diff --git a/sessionctx/stmtctx/stmtctx_test.go b/sessionctx/stmtctx/stmtctx_test.go new file mode 100644 index 0000000000000..3ef7fee235459 --- /dev/null +++ b/sessionctx/stmtctx/stmtctx_test.go @@ -0,0 +1,46 @@ +// Copyright 2019 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// See the License for the specific language governing permissions and +// limitations under the License. + +package stmtctx + +import ( + "fmt" + "testing" + "time" + + "github.com/pingcap/tidb/util/execdetails" +) + +func TestCopTasksDetails(t *testing.T) { + ctx := new(StatementContext) + for i := 0; i < 100; i++ { + d := &execdetails.ExecDetails{ + CalleeAddress: fmt.Sprintf("%v", i+1), + ProcessTime: time.Second * time.Duration(i+1), + WaitTime: time.Millisecond * time.Duration(i+1), + } + ctx.MergeExecDetails(d, nil) + } + c := ctx.CopTasksDetails() + if c.NumCopTasks != 100 || + c.AvgProcessTime != time.Second*101/2 || + c.P90ProcessTime != time.Second*91 || + c.MaxProcessTime != time.Second*100 || + c.MaxProcessAddress != "100" || + c.AvgWaitTime != time.Millisecond*101/2 || + c.P90WaitTime != time.Millisecond*91 || + c.MaxWaitTime != time.Millisecond*100 || + c.MaxWaitAddress != "100" { + t.Fatal(c) + } +} diff --git a/sessionctx/variable/session.go b/sessionctx/variable/session.go index 31b004fc4f67b..64873aec26b6b 100644 --- a/sessionctx/variable/session.go +++ b/sessionctx/variable/session.go @@ -897,6 +897,8 @@ const ( SlowLogQuerySQLStr = "Query" // use for slow log table, slow log will not print this field name but print sql directly. // SlowLogStatsInfoStr is plan stats info. SlowLogStatsInfoStr = "Stats" + // SlowLogCopTasks includes some useful information about cop-tasks. + SlowLogCopTasks = "Cop_tasks" ) // SlowLogFormat uses for formatting slow log. @@ -912,8 +914,10 @@ const ( // # Is_internal: false // # Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772 // # Stats: t1:1,t2:2 +// # Cop_tasks: // select * from t_slim; -func (s *SessionVars) SlowLogFormat(txnTS uint64, costTime time.Duration, execDetail execdetails.ExecDetails, indexIDs string, digest string, statsInfos map[string]uint64, sql string) string { +func (s *SessionVars) SlowLogFormat(txnTS uint64, costTime time.Duration, execDetail execdetails.ExecDetails, indexIDs string, digest string, + statsInfos map[string]uint64, copTasks *stmtctx.CopTasksDetails, sql string) string { var buf bytes.Buffer execDetailStr := execDetail.String() buf.WriteString(SlowLogRowPrefixStr + SlowLogTxnStartTSStr + SlowLogSpaceMarkStr + strconv.FormatUint(txnTS, 10) + "\n") @@ -957,6 +961,9 @@ func (s *SessionVars) SlowLogFormat(txnTS uint64, costTime time.Duration, execDe } buf.WriteString("\n") } + if copTasks != nil { + buf.WriteString(SlowLogRowPrefixStr + SlowLogCopTasks + SlowLogSpaceMarkStr + copTasks.String() + "\n") + } if len(sql) == 0 { sql = ";" } diff --git a/sessionctx/variable/session_test.go b/sessionctx/variable/session_test.go index 389a8facbd0b1..5b7d650c361da 100644 --- a/sessionctx/variable/session_test.go +++ b/sessionctx/variable/session_test.go @@ -14,6 +14,7 @@ package variable_test import ( + "github.com/pingcap/tidb/sessionctx/stmtctx" "time" . "github.com/pingcap/check" @@ -106,6 +107,17 @@ func (*testSessionSuite) TestSlowLogFormat(c *C) { } statsInfos := make(map[string]uint64) statsInfos["t1"] = 0 + copTasks := &stmtctx.CopTasksDetails{ + NumCopTasks: 10, + AvgProcessTime: time.Second, + P90ProcessTime: time.Second * 2, + MaxProcessAddress: "10.6.131.78", + MaxProcessTime: time.Second * 3, + AvgWaitTime: time.Millisecond * 10, + P90WaitTime: time.Millisecond * 20, + MaxWaitTime: time.Millisecond * 30, + MaxWaitAddress: "10.6.131.79", + } resultString := `# Txn_start_ts: 406649736972468225 # User: root@192.168.0.1 # Conn_ID: 1 @@ -116,9 +128,10 @@ func (*testSessionSuite) TestSlowLogFormat(c *C) { # Is_internal: true # Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772 # Stats: t1:pseudo +# Cop_tasks: Num_tasks: 10 Avg_process_time 1s P90_process_time 2s Max_process_time 3sMax_process_address 10.6.131.78 Avg_wait_time 10ms P90_wait_time 20ms Max_wait_time 30ms Max_wait_address 10.6.131.79 select * from t;` sql := "select * from t" digest := parser.DigestHash(sql) - logString := seVar.SlowLogFormat(txnTS, costTime, execDetail, "[1,2]", digest, statsInfos, sql) + logString := seVar.SlowLogFormat(txnTS, costTime, execDetail, "[1,2]", digest, statsInfos, copTasks, sql) c.Assert(logString, Equals, resultString) } From 155b696936ace527211adca82d63b33c2b5e0161 Mon Sep 17 00:00:00 2001 From: qw4990 Date: Tue, 16 Apr 2019 15:11:38 +0800 Subject: [PATCH 3/6] refmt --- sessionctx/variable/session_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sessionctx/variable/session_test.go b/sessionctx/variable/session_test.go index 5b7d650c361da..e7e7c028d5624 100644 --- a/sessionctx/variable/session_test.go +++ b/sessionctx/variable/session_test.go @@ -14,12 +14,12 @@ package variable_test import ( - "github.com/pingcap/tidb/sessionctx/stmtctx" "time" . "github.com/pingcap/check" "github.com/pingcap/parser" "github.com/pingcap/parser/auth" + "github.com/pingcap/tidb/sessionctx/stmtctx" "github.com/pingcap/tidb/util/execdetails" "github.com/pingcap/tidb/util/mock" ) From 8182049d6ed26cabd76fb2442f7a16e19ba794d2 Mon Sep 17 00:00:00 2001 From: qw4990 Date: Tue, 16 Apr 2019 15:19:56 +0800 Subject: [PATCH 4/6] fix CI --- executor/adapter.go | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/executor/adapter.go b/executor/adapter.go index cb570a74e856c..03383cfe87684 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -413,13 +413,14 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) { indexIDs = strings.Replace(fmt.Sprintf("%v", a.Ctx.GetSessionVars().StmtCtx.IndexIDs), " ", ",", -1) } execDetail := sessVars.StmtCtx.GetExecDetails() + copTaskInfo := sessVars.StmtCtx.CopTasksDetails() statsInfos := a.getStatsInfo() if costTime < threshold { _, digest := sessVars.StmtCtx.SQLDigest() - logutil.SlowQueryLogger.Debug(sessVars.SlowLogFormat(txnTS, costTime, execDetail, indexIDs, digest, statsInfos, sql)) + logutil.SlowQueryLogger.Debug(sessVars.SlowLogFormat(txnTS, costTime, execDetail, indexIDs, digest, statsInfos, copTaskInfo, sql)) } else { _, digest := sessVars.StmtCtx.SQLDigest() - logutil.SlowQueryLogger.Warn(sessVars.SlowLogFormat(txnTS, costTime, execDetail, indexIDs, digest, statsInfos, sql)) + logutil.SlowQueryLogger.Warn(sessVars.SlowLogFormat(txnTS, costTime, execDetail, indexIDs, digest, statsInfos, copTaskInfo, sql)) metrics.TotalQueryProcHistogram.Observe(costTime.Seconds()) metrics.TotalCopProcHistogram.Observe(execDetail.ProcessTime.Seconds()) metrics.TotalCopWaitHistogram.Observe(execDetail.WaitTime.Seconds()) From f46eb91eb67cf873616118e79a1dc09b2b3d060e Mon Sep 17 00:00:00 2001 From: qw4990 Date: Tue, 16 Apr 2019 21:25:08 +0800 Subject: [PATCH 5/6] reset allExecDetails when retry --- sessionctx/stmtctx/stmtctx.go | 2 ++ 1 file changed, 2 insertions(+) diff --git a/sessionctx/stmtctx/stmtctx.go b/sessionctx/stmtctx/stmtctx.go index d0f7b762212ae..37a1ae3ea4b48 100644 --- a/sessionctx/stmtctx/stmtctx.go +++ b/sessionctx/stmtctx/stmtctx.go @@ -379,6 +379,8 @@ func (sc *StatementContext) ResetForRetry() { sc.mu.touched = 0 sc.mu.message = "" sc.mu.warnings = nil + sc.mu.execDetails = execdetails.ExecDetails{} + sc.mu.allExecDetails = make([]*execdetails.ExecDetails, 0, 4) sc.mu.Unlock() sc.TableIDs = sc.TableIDs[:0] sc.IndexIDs = sc.IndexIDs[:0] From 28c291d623be3b046fe4cb994d65e32d258af33e Mon Sep 17 00:00:00 2001 From: qw4990 Date: Wed, 17 Apr 2019 11:26:39 +0800 Subject: [PATCH 6/6] refine log format --- sessionctx/stmtctx/stmtctx.go | 10 ---------- sessionctx/variable/session.go | 16 +++++++++++++--- sessionctx/variable/session_test.go | 4 +++- 3 files changed, 16 insertions(+), 14 deletions(-) diff --git a/sessionctx/stmtctx/stmtctx.go b/sessionctx/stmtctx/stmtctx.go index 37a1ae3ea4b48..d36a8c6e49ca5 100644 --- a/sessionctx/stmtctx/stmtctx.go +++ b/sessionctx/stmtctx/stmtctx.go @@ -14,7 +14,6 @@ package stmtctx import ( - "fmt" "math" "sort" "sync" @@ -472,12 +471,3 @@ type CopTasksDetails struct { MaxWaitAddress string MaxWaitTime time.Duration } - -// String implements the fmt.Stringer interface. -func (d CopTasksDetails) String() string { - // formatted like slow log - return fmt.Sprintf("Num_tasks: %d Avg_process_time %v P90_process_time %v Max_process_time %v"+ - "Max_process_address %s Avg_wait_time %v P90_wait_time %v Max_wait_time %v Max_wait_address %s", - d.NumCopTasks, d.AvgProcessTime, d.P90ProcessTime, d.MaxProcessTime, d.MaxProcessAddress, - d.AvgWaitTime, d.P90WaitTime, d.MaxWaitTime, d.MaxWaitAddress) -} diff --git a/sessionctx/variable/session.go b/sessionctx/variable/session.go index 64873aec26b6b..16978984fde4c 100644 --- a/sessionctx/variable/session.go +++ b/sessionctx/variable/session.go @@ -897,8 +897,12 @@ const ( SlowLogQuerySQLStr = "Query" // use for slow log table, slow log will not print this field name but print sql directly. // SlowLogStatsInfoStr is plan stats info. SlowLogStatsInfoStr = "Stats" - // SlowLogCopTasks includes some useful information about cop-tasks. - SlowLogCopTasks = "Cop_tasks" + // 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" ) // SlowLogFormat uses for formatting slow log. @@ -962,7 +966,13 @@ func (s *SessionVars) SlowLogFormat(txnTS uint64, costTime time.Duration, execDe buf.WriteString("\n") } if copTasks != nil { - buf.WriteString(SlowLogRowPrefixStr + SlowLogCopTasks + SlowLogSpaceMarkStr + copTasks.String() + "\n") + buf.WriteString(SlowLogRowPrefixStr + SlowLogNumCopTasksStr + SlowLogSpaceMarkStr + strconv.FormatInt(int64(copTasks.NumCopTasks), 10) + "\n") + buf.WriteString(SlowLogRowPrefixStr + SlowLogCopProcessStr + SlowLogSpaceMarkStr + + fmt.Sprintf("Avg_time: %v P90_time: %v Max_time: %v Max_addr: %v", copTasks.AvgProcessTime, + copTasks.P90ProcessTime, copTasks.MaxProcessTime, copTasks.MaxProcessAddress) + "\n") + buf.WriteString(SlowLogRowPrefixStr + SlowLogCopWaitStr + SlowLogSpaceMarkStr + + fmt.Sprintf("Avg_time: %v P90_time: %v Max_time: %v Max_Addr: %v", copTasks.AvgWaitTime, + copTasks.P90WaitTime, copTasks.MaxWaitTime, copTasks.MaxWaitAddress) + "\n") } if len(sql) == 0 { sql = ";" diff --git a/sessionctx/variable/session_test.go b/sessionctx/variable/session_test.go index e7e7c028d5624..40392bb44e917 100644 --- a/sessionctx/variable/session_test.go +++ b/sessionctx/variable/session_test.go @@ -128,7 +128,9 @@ func (*testSessionSuite) TestSlowLogFormat(c *C) { # Is_internal: true # Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772 # Stats: t1:pseudo -# Cop_tasks: Num_tasks: 10 Avg_process_time 1s P90_process_time 2s Max_process_time 3sMax_process_address 10.6.131.78 Avg_wait_time 10ms P90_wait_time 20ms Max_wait_time 30ms Max_wait_address 10.6.131.79 +# Num_cop_tasks: 10 +# Cop_process: Avg_time: 1s P90_time: 2s Max_time: 3s Max_addr: 10.6.131.78 +# Cop_wait: Avg_time: 10ms P90_time: 20ms Max_time: 30ms Max_Addr: 10.6.131.79 select * from t;` sql := "select * from t" digest := parser.DigestHash(sql)