*: record execute runtime information in slow log

expression/integration_test.go

@@ -4400,6 +4400,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) {

planner/core/common_plans.go

@@ -937,6 +937,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) {
@@ -961,42 +1002,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}

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++

planner/core/plan_test.go

@@ -84,6 +84,33 @@ func (s *testPlanNormalize) TestNormalizedPlan(c *C) {
 	}
 }
 
+func (s *testPlanNormalize) TestEncodeDecodePlan(c *C) {
+	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)
+	result := "" +
+		"\tStreamAgg_13        \troot\t1\tfuncs:max.*->Column#4                               \t0\ttime:0s, loops:0 \t.* Bytes\tN/A\n" +
+		"\t└─Limit_17          \troot\t1\toffset:0, count:1                                            \t0\ttime:0s, loops:0 \tN/A      \tN/A\n" +
+		"\t  └─TableReader_27  \troot\t1\tdata:Limit_26                                                \t0\ttime:0s, loops:0 \t.* Bytes  \tN/A\n" +
+		"\t    └─Limit_26      \tcop \t1\toffset:0, count:1                                            \t \ttime:0ns, loops:0\tN/A      \tN/A\n" +
+		"\t      └─TableScan_25\tcop \t1\ttable:t1, range:.*, keep order:true, desc, stats:pseudo\t0\ttime:0s, loops:0 \tN/A      \tN/A"
+	planTree = strings.Replace(planTree, "\n", "", -1)
+	result = strings.Replace(result, "\n", "", -1)
+	c.Assert(planTree, Matches, result)
+}
+
 func (s *testPlanNormalize) TestNormalizedDigest(c *C) {
 	tk := testkit.NewTestKit(c, s.store)
 	tk.MustExec("use test")

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)
 }