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()) diff --git a/sessionctx/stmtctx/stmtctx.go b/sessionctx/stmtctx/stmtctx.go index de6cd9fb1857e..d36a8c6e49ca5 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 @@ -376,6 +378,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] @@ -392,6 +396,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 +428,46 @@ 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} + 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.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.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 +} + +//CopTasksDetails collects some useful information of cop-tasks during execution. +type CopTasksDetails struct { + NumCopTasks int + + AvgProcessTime time.Duration + P90ProcessTime time.Duration + MaxProcessAddress string + MaxProcessTime time.Duration + + AvgWaitTime time.Duration + P90WaitTime time.Duration + MaxWaitAddress string + MaxWaitTime time.Duration +} 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..16978984fde4c 100644 --- a/sessionctx/variable/session.go +++ b/sessionctx/variable/session.go @@ -897,6 +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" + // 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. @@ -912,8 +918,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 +965,15 @@ func (s *SessionVars) SlowLogFormat(txnTS uint64, costTime time.Duration, execDe } buf.WriteString("\n") } + if copTasks != nil { + 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 389a8facbd0b1..40392bb44e917 100644 --- a/sessionctx/variable/session_test.go +++ b/sessionctx/variable/session_test.go @@ -19,6 +19,7 @@ import ( . "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" ) @@ -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,12 @@ func (*testSessionSuite) TestSlowLogFormat(c *C) { # Is_internal: true # Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772 # Stats: t1:pseudo +# 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) - 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) }