From a050324f80862324be9be6ecb663d99e4b44d519 Mon Sep 17 00:00:00 2001 From: Yuanjia Zhang Date: Wed, 27 Nov 2019 01:00:26 -0600 Subject: [PATCH] executor: show `max-proc-keys` and `p95-proc-keys` in results of `explain analyze` (#13692) --- distsql/select_result.go | 8 +++++--- distsql/select_result_test.go | 6 +++--- util/execdetails/execdetails.go | 18 +++++++++++++----- util/execdetails/execdetails_test.go | 21 +++++++++++++++++++++ 4 files changed, 42 insertions(+), 11 deletions(-) diff --git a/distsql/select_result.go b/distsql/select_result.go index 1b5bbeb25e6ab..76389d2ac6f13 100644 --- a/distsql/select_result.go +++ b/distsql/select_result.go @@ -27,6 +27,7 @@ import ( "github.com/pingcap/tidb/types" "github.com/pingcap/tidb/util/chunk" "github.com/pingcap/tidb/util/codec" + "github.com/pingcap/tidb/util/execdetails" "github.com/pingcap/tidb/util/logutil" "github.com/pingcap/tidb/util/memory" "github.com/pingcap/tipb/go-tipb" @@ -107,7 +108,7 @@ func (r *selectResult) fetchResp(ctx context.Context) error { for _, warning := range r.selectResp.Warnings { sc.AppendWarning(terror.ClassTiKV.New(terror.ErrCode(warning.Code), warning.Msg)) } - r.updateCopRuntimeStats(resultSubset.GetExecDetails().CalleeAddress, resultSubset.RespTime()) + r.updateCopRuntimeStats(resultSubset.GetExecDetails(), resultSubset.RespTime()) r.feedback.Update(resultSubset.GetStartKey(), r.selectResp.OutputCounts) r.partialCount++ sc.MergeExecDetails(resultSubset.GetExecDetails(), nil) @@ -206,7 +207,8 @@ func (r *selectResult) readFromChunk(ctx context.Context, chk *chunk.Chunk) erro return nil } -func (r *selectResult) updateCopRuntimeStats(callee string, respTime time.Duration) { +func (r *selectResult) updateCopRuntimeStats(detail *execdetails.ExecDetails, respTime time.Duration) { + callee := detail.CalleeAddress if r.ctx.GetSessionVars().StmtCtx.RuntimeStatsColl == nil || callee == "" { return } @@ -218,7 +220,7 @@ func (r *selectResult) updateCopRuntimeStats(callee string, respTime time.Durati return } - r.ctx.GetSessionVars().StmtCtx.RuntimeStatsColl.RecordOneReaderStats(r.rootPlanID.String(), respTime) + r.ctx.GetSessionVars().StmtCtx.RuntimeStatsColl.RecordOneReaderStats(r.rootPlanID.String(), respTime, detail) for i, detail := range r.selectResp.GetExecutionSummaries() { if detail != nil && detail.TimeProcessedNs != nil && detail.NumProducedRows != nil && detail.NumIterations != nil { diff --git a/distsql/select_result_test.go b/distsql/select_result_test.go index 0e913ab0b2d04..9a77a2ab1f0f2 100644 --- a/distsql/select_result_test.go +++ b/distsql/select_result_test.go @@ -29,7 +29,7 @@ func (s *testSuite) TestUpdateCopRuntimeStats(c *C) { sr := selectResult{ctx: ctx} c.Assert(ctx.GetSessionVars().StmtCtx.RuntimeStatsColl, IsNil) sr.rootPlanID = copPlan{} - sr.updateCopRuntimeStats("a", 0) + sr.updateCopRuntimeStats(&execdetails.ExecDetails{CalleeAddress: "a"}, 0) ctx.GetSessionVars().StmtCtx.RuntimeStatsColl = execdetails.NewRuntimeStatsColl() t := uint64(1) @@ -39,13 +39,13 @@ func (s *testSuite) TestUpdateCopRuntimeStats(c *C) { }, } c.Assert(len(sr.selectResp.GetExecutionSummaries()) != len(sr.copPlanIDs), IsTrue) - sr.updateCopRuntimeStats("callee", 0) + sr.updateCopRuntimeStats(&execdetails.ExecDetails{CalleeAddress: "callee"}, 0) c.Assert(ctx.GetSessionVars().StmtCtx.RuntimeStatsColl.ExistsCopStats("callee"), IsFalse) sr.copPlanIDs = []fmt.Stringer{copPlan{}} c.Assert(ctx.GetSessionVars().StmtCtx.RuntimeStatsColl, NotNil) c.Assert(len(sr.selectResp.GetExecutionSummaries()), Equals, len(sr.copPlanIDs)) - sr.updateCopRuntimeStats("callee", 0) + sr.updateCopRuntimeStats(&execdetails.ExecDetails{CalleeAddress: "callee"}, 0) c.Assert(ctx.GetSessionVars().StmtCtx.RuntimeStatsColl.GetCopStats("callee").String(), Equals, "time:1ns, loops:1, rows:1") } diff --git a/util/execdetails/execdetails.go b/util/execdetails/execdetails.go index 03bf7c41e1f4e..5b7b8db97d0fa 100644 --- a/util/execdetails/execdetails.go +++ b/util/execdetails/execdetails.go @@ -282,13 +282,15 @@ type ReaderRuntimeStats struct { sync.Mutex copRespTime []time.Duration + procKeys []int64 } // recordOneCopTask record once cop response time to update maxcopRespTime -func (rrs *ReaderRuntimeStats) recordOneCopTask(t time.Duration) { +func (rrs *ReaderRuntimeStats) recordOneCopTask(t time.Duration, detail *ExecDetails) { rrs.Lock() defer rrs.Unlock() rrs.copRespTime = append(rrs.copRespTime, t) + rrs.procKeys = append(rrs.procKeys, detail.ProcessedKeys) } func (rrs *ReaderRuntimeStats) String() string { @@ -297,7 +299,7 @@ func (rrs *ReaderRuntimeStats) String() string { return "" } if size == 1 { - return fmt.Sprintf("rpc num:1, time:%v", rrs.copRespTime[0]) + return fmt.Sprintf("rpc num: 1, rpc time:%v, proc keys:%v", rrs.copRespTime[0], rrs.procKeys[0]) } sort.Slice(rrs.copRespTime, func(i, j int) bool { return rrs.copRespTime[i] < rrs.copRespTime[j] @@ -309,7 +311,13 @@ func (rrs *ReaderRuntimeStats) String() string { sum += float64(t) } vAvg := time.Duration(sum / float64(size)) - return fmt.Sprintf("rpc num:%v, max:%v, min:%v, avg:%v, p80:%v, p95:%v", size, vMax, vMin, vAvg, vP80, vP95) + + sort.Slice(rrs.procKeys, func(i, j int) bool { + return rrs.procKeys[i] < rrs.procKeys[j] + }) + keyMax := rrs.procKeys[size-1] + keyP95 := rrs.procKeys[size*19/20] + return fmt.Sprintf("rpc num: %v, rpc max:%v, min:%v, avg:%v, p80:%v, p95:%v, proc keys max:%v, p95:%v", size, vMax, vMin, vAvg, vP80, vP95, keyMax, keyP95) } // RuntimeStatsColl collects executors's execution info. @@ -367,9 +375,9 @@ func (e *RuntimeStatsColl) RecordOneCopTask(planID, address string, summary *tip } // RecordOneReaderStats records a specific stats for TableReader, IndexReader and IndexLookupReader. -func (e *RuntimeStatsColl) RecordOneReaderStats(planID string, copRespTime time.Duration) { +func (e *RuntimeStatsColl) RecordOneReaderStats(planID string, copRespTime time.Duration, detail *ExecDetails) { readerStats := e.GetReaderStats(planID) - readerStats.recordOneCopTask(copRespTime) + readerStats.recordOneCopTask(copRespTime, detail) } // ExistsRootStats checks if the planID exists in the rootStats collection. diff --git a/util/execdetails/execdetails_test.go b/util/execdetails/execdetails_test.go index 429ea11a1cf8b..0a72e58d03e98 100644 --- a/util/execdetails/execdetails_test.go +++ b/util/execdetails/execdetails_test.go @@ -110,3 +110,24 @@ func TestCopRuntimeStats(t *testing.T) { t.Fatal("table_reader not exists") } } + +func TestReaderStats(t *testing.T) { + r := new(ReaderRuntimeStats) + if r.String() != "" { + t.Fatal() + } + + r.procKeys = append(r.procKeys, 100) + r.copRespTime = append(r.copRespTime, time.Millisecond*100) + if r.String() != "rpc num: 1, rpc time:100ms, proc keys:100" { + t.Fatal() + } + + for i := 0; i < 100; i++ { + r.procKeys = append(r.procKeys, int64(i)) + r.copRespTime = append(r.copRespTime, time.Millisecond*time.Duration(i)) + } + if r.String() != "rpc num: 101, rpc max:100ms, min:0s, avg:50ms, p80:80ms, p95:95ms, proc keys max:100, p95:95" { + t.Fatal() + } +}