From 36ea109b83c5558a3122b139abf1d141efbc0435 Mon Sep 17 00:00:00 2001 From: crazycs Date: Tue, 9 Jun 2020 12:16:47 +0800 Subject: [PATCH] *: record execute runtime information in slow log (#17573) --- expression/integration_test.go | 10 +++++ planner/core/common_plans.go | 78 ++++++++++++++++++---------------- planner/core/encode.go | 3 +- planner/core/plan_test.go | 24 +++++++++++ util/plancodec/codec.go | 27 +++++++++++- 5 files changed, 104 insertions(+), 38 deletions(-) diff --git a/expression/integration_test.go b/expression/integration_test.go index a39f99b4644c9..f0f5b0730aed1 100755 --- a/expression/integration_test.go +++ b/expression/integration_test.go @@ -4407,6 +4407,16 @@ func (s *testIntegrationSuite) TestTiDBDecodePlanFunc(c *C) { "\t └─TableReader_21 \troot\t0 \tdata:Selection_20\n" + "\t └─Selection_20 \tcop \t0 \tlt(Column#9, NULL), not(isnull(Column#10)), not(isnull(Column#9))\n" + "\t └─TableScan_19\tcop \t10000\ttable:t2, range:[-inf,+inf], keep order:false, stats:pseudo")) + tk.MustQuery("select tidb_decode_plan('rwPwcTAJNV8xNAkwCTEJZnVuY3M6bWF4KHRlc3QudC5hKS0+Q29sdW1uIzQJMQl0aW1lOj" + + "IyMy45MzXCtXMsIGxvb3BzOjIJMTI4IEJ5dGVzCU4vQQoxCTE2XzE4CTAJMQlvZmZzZXQ6MCwgY291bnQ6MQkxCQlHFDE4LjQyMjJHAAhOL0" + + "EBBCAKMgkzMl8yOAkBlEBpbmRleDpMaW1pdF8yNwkxCQ0+DDYuODUdPSwxLCBycGMgbnVtOiANDAUpGDE1MC44MjQFKjhwcm9jIGtleXM6MA" + + "kxOTgdsgAzAbIAMgFearIAFDU3LjM5NgVKAGwN+BGxIDQJMTNfMjYJMQGgHGFibGU6dCwgCbqwaWR4KGEpLCByYW5nZTooMCwraW5mXSwga2" + + "VlcCBvcmRlcjp0cnVlLCBkZXNjAT8kaW1lOjU2LjY2MR1rJDEJTi9BCU4vQQo=')").Check(testkit.Rows("" + + "\tStreamAgg_14 \troot\t1\tfuncs:max(test.t.a)->Column#4 \t1\ttime:223.935µs, loops:2 \t128 Bytes\tN/A\n" + + "\t└─Limit_18 \troot\t1\toffset:0, count:1 \t1\ttime:218.422µs, loops:2 \tN/A \tN/A\n" + + "\t └─IndexReader_28 \troot\t1\tindex:Limit_27 \t1\ttime:216.85µs, loops:1, rpc num: 1, rpc time:150.824µs, proc keys:0\t198 Bytes\tN/A\n" + + "\t └─Limit_27 \tcop \t1\toffset:0, count:1 \t1\ttime:57.396µs, loops:2 \tN/A \tN/A\n" + + "\t └─IndexScan_26\tcop \t1\ttable:t, index:idx(a), range:(0,+inf], keep order:true, desc\t1\ttime:56.661µs, loops:1 \tN/A \tN/A")) } func (s *testIntegrationSuite) TestTiDBInternalFunc(c *C) { diff --git a/planner/core/common_plans.go b/planner/core/common_plans.go index 8ddfb2a51d8ac..7045fffe035b9 100644 --- a/planner/core/common_plans.go +++ b/planner/core/common_plans.go @@ -938,6 +938,47 @@ func (e *Explain) explainPlanInRowFormat(p Plan, taskType, driverSide, indent st return } +func getRuntimeInfo(ctx sessionctx.Context, p Plan) (actRows, analyzeInfo, memoryInfo, diskInfo string) { + runtimeStatsColl := ctx.GetSessionVars().StmtCtx.RuntimeStatsColl + if runtimeStatsColl == nil { + return + } + explainID := p.ExplainID().String() + + // There maybe some mock information for cop task to let runtimeStatsColl.Exists(p.ExplainID()) is true. + // So check copTaskEkxecDetail first and print the real cop task information if it's not empty. + if runtimeStatsColl.ExistsCopStats(explainID) { + copstats := runtimeStatsColl.GetCopStats(explainID) + analyzeInfo = copstats.String() + actRows = fmt.Sprint(copstats.GetActRows()) + } else if runtimeStatsColl.ExistsRootStats(explainID) { + rootstats := runtimeStatsColl.GetRootStats(explainID) + analyzeInfo = rootstats.String() + actRows = fmt.Sprint(rootstats.GetActRows()) + } else { + analyzeInfo = "time:0ns, loops:0" + } + switch p.(type) { + case *PhysicalTableReader, *PhysicalIndexReader, *PhysicalIndexLookUpReader: + if s := runtimeStatsColl.GetReaderStats(explainID); s != nil && len(s.String()) > 0 { + analyzeInfo += ", " + s.String() + } + } + + memoryInfo = "N/A" + memTracker := ctx.GetSessionVars().StmtCtx.MemTracker.SearchTracker(p.ExplainID().String()) + if memTracker != nil { + memoryInfo = memTracker.BytesToString(memTracker.MaxConsumed()) + } + + diskInfo = "N/A" + diskTracker := ctx.GetSessionVars().StmtCtx.DiskTracker.SearchTracker(p.ExplainID().String()) + if diskTracker != nil { + diskInfo = diskTracker.BytesToString(diskTracker.MaxConsumed()) + } + return +} + // prepareOperatorInfo generates the following information for every plan: // operator id, estimated rows, task type, access object and other operator info. func (e *Explain) prepareOperatorInfo(p Plan, taskType, driverSide, indent string, isLastChild bool) { @@ -962,42 +1003,7 @@ func (e *Explain) prepareOperatorInfo(p Plan, taskType, driverSide, indent strin var row []string if e.Analyze { - runtimeStatsColl := e.ctx.GetSessionVars().StmtCtx.RuntimeStatsColl - explainID := p.ExplainID().String() - var actRows, analyzeInfo string - - // There maybe some mock information for cop task to let runtimeStatsColl.Exists(p.ExplainID()) is true. - // So check copTaskEkxecDetail first and print the real cop task information if it's not empty. - if runtimeStatsColl.ExistsCopStats(explainID) { - copstats := runtimeStatsColl.GetCopStats(explainID) - analyzeInfo = copstats.String() - actRows = fmt.Sprint(copstats.GetActRows()) - } else if runtimeStatsColl.ExistsRootStats(explainID) { - rootstats := runtimeStatsColl.GetRootStats(explainID) - analyzeInfo = rootstats.String() - actRows = fmt.Sprint(rootstats.GetActRows()) - } else { - analyzeInfo = "time:0ns, loops:0" - } - switch p.(type) { - case *PhysicalTableReader, *PhysicalIndexReader, *PhysicalIndexLookUpReader: - if s := runtimeStatsColl.GetReaderStats(explainID); s != nil && len(s.String()) > 0 { - analyzeInfo += ", " + s.String() - } - } - - memoryInfo := "N/A" - memTracker := e.ctx.GetSessionVars().StmtCtx.MemTracker.SearchTracker(p.ExplainID().String()) - if memTracker != nil { - memoryInfo = memTracker.BytesToString(memTracker.MaxConsumed()) - } - - diskInfo := "N/A" - diskTracker := e.ctx.GetSessionVars().StmtCtx.DiskTracker.SearchTracker(p.ExplainID().String()) - if diskTracker != nil { - diskInfo = diskTracker.BytesToString(diskTracker.MaxConsumed()) - } - + actRows, analyzeInfo, memoryInfo, diskInfo := getRuntimeInfo(e.ctx, p) row = []string{id, estRows, actRows, taskType, accessObject, analyzeInfo, operatorInfo, memoryInfo, diskInfo} } else { row = []string{id, estRows, taskType, accessObject, operatorInfo} diff --git a/planner/core/encode.go b/planner/core/encode.go index ca8ee7bcabb5f..e9f70f54b42e5 100644 --- a/planner/core/encode.go +++ b/planner/core/encode.go @@ -57,7 +57,8 @@ func (pn *planEncoder) encodePlanTree(p PhysicalPlan) string { } func (pn *planEncoder) encodePlan(p PhysicalPlan, isRoot bool, depth int) { - plancodec.EncodePlanNode(depth, p.ID(), p.TP(), isRoot, p.statsInfo().RowCount, p.ExplainInfo(), &pn.buf) + actRows, analyzeInfo, memoryInfo, diskInfo := getRuntimeInfo(p.SCtx(), p) + plancodec.EncodePlanNode(depth, p.ID(), p.TP(), isRoot, p.statsInfo().RowCount, p.ExplainInfo(), actRows, analyzeInfo, memoryInfo, diskInfo, &pn.buf) pn.encodedPlans[p.ID()] = true depth++ diff --git a/planner/core/plan_test.go b/planner/core/plan_test.go index a166a5cd7b668..fa9936b0c55f3 100644 --- a/planner/core/plan_test.go +++ b/planner/core/plan_test.go @@ -20,6 +20,7 @@ import ( "github.com/pingcap/tidb/domain" "github.com/pingcap/tidb/kv" "github.com/pingcap/tidb/planner/core" + "github.com/pingcap/tidb/util/israce" "github.com/pingcap/tidb/util/plancodec" "github.com/pingcap/tidb/util/testkit" "github.com/pingcap/tidb/util/testleak" @@ -84,6 +85,29 @@ func (s *testPlanNormalize) TestNormalizedPlan(c *C) { } } +func (s *testPlanNormalize) TestEncodeDecodePlan(c *C) { + if israce.RaceEnabled { + c.Skip("skip race test") + } + tk := testkit.NewTestKit(c, s.store) + tk.MustExec("use test") + tk.MustExec("drop table if exists t1,t2") + tk.MustExec("create table t1 (a int key,b int,c int, index (b));") + tk.MustExec("set tidb_enable_collect_execution_info=1;") + + tk.Se.GetSessionVars().PlanID = 0 + tk.MustExec("select max(a) from t1 where a>0;") + info := tk.Se.ShowProcess() + c.Assert(info, NotNil) + p, ok := info.Plan.(core.Plan) + c.Assert(ok, IsTrue) + encodeStr := core.EncodePlan(p) + planTree, err := plancodec.DecodePlan(encodeStr) + c.Assert(err, IsNil) + c.Assert(strings.Contains(planTree, "time"), IsTrue) + c.Assert(strings.Contains(planTree, "loops"), IsTrue) +} + func (s *testPlanNormalize) TestNormalizedDigest(c *C) { tk := testkit.NewTestKit(c, s.store) tk.MustExec("use test") diff --git a/util/plancodec/codec.go b/util/plancodec/codec.go index 971bb94d84f75..8ff46b38cb66c 100644 --- a/util/plancodec/codec.go +++ b/util/plancodec/codec.go @@ -177,6 +177,19 @@ func (pd *planDecoder) alignFields(planInfos []*planInfo) { if len(planInfos) == 0 { return } + // Align fields length. Some plan may doesn't have runtime info, need append `` to align with other plan fields. + maxLen := -1 + for _, p := range planInfos { + if len(p.fields) > maxLen { + maxLen = len(p.fields) + } + } + for _, p := range planInfos { + for len(p.fields) < maxLen { + p.fields = append(p.fields, "") + } + } + fieldsLen := len(planInfos[0].fields) // Last field no need to align. fieldsLen-- @@ -253,7 +266,8 @@ func decodePlanInfo(str string) (*planInfo, error) { } // EncodePlanNode is used to encode the plan to a string. -func EncodePlanNode(depth, pid int, planType string, isRoot bool, rowCount float64, explainInfo string, buf *bytes.Buffer) { +func EncodePlanNode(depth, pid int, planType string, isRoot bool, rowCount float64, + explainInfo, actRows, analyzeInfo, memoryInfo, diskInfo string, buf *bytes.Buffer) { buf.WriteString(strconv.Itoa(depth)) buf.WriteByte(separator) buf.WriteString(encodeID(planType, pid)) @@ -267,6 +281,17 @@ func EncodePlanNode(depth, pid int, planType string, isRoot bool, rowCount float buf.WriteString(strconv.FormatFloat(rowCount, 'f', -1, 64)) buf.WriteByte(separator) buf.WriteString(explainInfo) + // Check whether has runtime info. + if len(actRows) > 0 || len(analyzeInfo) > 0 || len(memoryInfo) > 0 || len(diskInfo) > 0 { + buf.WriteByte(separator) + buf.WriteString(actRows) + buf.WriteByte(separator) + buf.WriteString(analyzeInfo) + buf.WriteByte(separator) + buf.WriteString(memoryInfo) + buf.WriteByte(separator) + buf.WriteString(diskInfo) + } buf.WriteByte(lineBreaker) }