*: add foreign key check/cascade runtime stats information in explain…

… analyze result (#39203)

close #39202

distsql/distsql_test.go

@@ -135,7 +135,7 @@ func TestSelectResultRuntimeStats(t *testing.T) {
 	}
 	stmtStats.RegisterStats(2, s1)
 	stats = stmtStats.GetRootStats(2)
-	expect = "time:0s, loops:0, cop_task: {num: 2, max: 1s, min: 1ms, avg: 500.5ms, p95: 1s, max_proc_keys: 200, p95_proc_keys: 200, tot_proc: 1s, tot_wait: 1s, rpc_num: 1, rpc_time: 1s, copr_cache_hit_ratio: 0.00, distsql_concurrency: 15}, backoff{RegionMiss: 1ms}"
+	expect = "cop_task: {num: 2, max: 1s, min: 1ms, avg: 500.5ms, p95: 1s, max_proc_keys: 200, p95_proc_keys: 200, tot_proc: 1s, tot_wait: 1s, rpc_num: 1, rpc_time: 1s, copr_cache_hit_ratio: 0.00, distsql_concurrency: 15}, backoff{RegionMiss: 1ms}"
 	require.Equal(t, expect, stats.String())
 	// Test for idempotence.
 	require.Equal(t, expect, stats.String())

executor/adapter.go

@@ -605,10 +605,6 @@ func (a *ExecStmt) handleForeignKeyTrigger(ctx context.Context, e Executor, dept
 	if !ok {
 		return nil
 	}
-	a.Ctx.GetSessionVars().StmtCtx.InHandleForeignKeyTrigger = true
-	defer func() {
-		a.Ctx.GetSessionVars().StmtCtx.InHandleForeignKeyTrigger = false
-	}()
 	fkChecks := exec.GetFKChecks()
 	for _, fkCheck := range fkChecks {
 		err := fkCheck.doCheck(ctx)
@@ -638,12 +634,26 @@ func (a *ExecStmt) handleForeignKeyTrigger(ctx context.Context, e Executor, dept
 //  4. `StmtCommit` to commit the kv change to transaction mem-buffer.
 //  5. If the foreign key cascade behaviour has more fk value need to be cascaded, go to step 1.
 func (a *ExecStmt) handleForeignKeyCascade(ctx context.Context, fkc *FKCascadeExec, depth int) error {
+	if a.Ctx.GetSessionVars().StmtCtx.RuntimeStatsColl != nil {
+		fkc.stats = &FKCascadeRuntimeStats{}
+		defer a.Ctx.GetSessionVars().StmtCtx.RuntimeStatsColl.RegisterStats(fkc.plan.ID(), fkc.stats)
+	}
 	if len(fkc.fkValues) == 0 && len(fkc.fkUpdatedValuesMap) == 0 {
 		return nil
 	}
 	if depth > maxForeignKeyCascadeDepth {
 		return ErrForeignKeyCascadeDepthExceeded.GenWithStackByArgs(maxForeignKeyCascadeDepth)
 	}
+	a.Ctx.GetSessionVars().StmtCtx.InHandleForeignKeyTrigger = true
+	defer func() {
+		a.Ctx.GetSessionVars().StmtCtx.InHandleForeignKeyTrigger = false
+	}()
+	if fkc.stats != nil {
+		start := time.Now()
+		defer func() {
+			fkc.stats.Total += time.Since(start)
+		}()
+	}
 	for {
 		e, err := fkc.buildExecutor(ctx)
 		if err != nil || e == nil {

executor/foreign_key.go

@@ -15,8 +15,11 @@
 package executor
 
 import (
+	"bytes"
 	"context"
+	"strconv"
 	"sync/atomic"
+	"time"
 
 	"github.com/pingcap/errors"
 	"github.com/pingcap/tidb/kv"
@@ -31,6 +34,7 @@ import (
 	"github.com/pingcap/tidb/types"
 	driver "github.com/pingcap/tidb/types/parser_driver"
 	"github.com/pingcap/tidb/util/codec"
+	"github.com/pingcap/tidb/util/execdetails"
 	"github.com/pingcap/tidb/util/set"
 	"github.com/tikv/client-go/v2/txnkv/txnsnapshot"
 )
@@ -60,12 +64,16 @@ type FKCheckExec struct {
 
 // FKCheckRuntimeStats contains the FKCheckExec runtime stats.
 type FKCheckRuntimeStats struct {
-	Keys int
+	Total time.Duration
+	Check time.Duration
+	Lock  time.Duration
+	Keys  int
 }
 
 // FKCascadeExec uses to execute foreign key cascade behaviour.
 type FKCascadeExec struct {
 	*fkValueHelper
+	plan       *plannercore.FKCascade
 	b          *executorBuilder
 	tp         plannercore.FKCascadeType
 	referredFK *model.ReferredFKInfo
@@ -78,6 +86,8 @@ type FKCascadeExec struct {
 	fkValues [][]types.Datum
 	// new-value-key => UpdatedValuesCouple
 	fkUpdatedValuesMap map[string]*UpdatedValuesCouple
+
+	stats *FKCascadeRuntimeStats
 }
 
 // UpdatedValuesCouple contains the updated new row the old rows, exporting for test.
@@ -86,6 +96,12 @@ type UpdatedValuesCouple struct {
 	OldValuesList [][]types.Datum
 }
 
+// FKCascadeRuntimeStats contains the FKCascadeExec runtime stats.
+type FKCascadeRuntimeStats struct {
+	Total time.Duration
+	Keys  int
+}
+
 func buildTblID2FKCheckExecs(sctx sessionctx.Context, tblID2Table map[int64]table.Table, tblID2FKChecks map[int64][]*plannercore.FKCheck) (map[int64][]*FKCheckExec, error) {
 	fkChecksMap := make(map[int64][]*FKCheckExec)
 	for tid, tbl := range tblID2Table {
@@ -175,6 +191,20 @@ func (fkc *FKCheckExec) addRowNeedToCheck(sc *stmtctx.StatementContext, row []ty
 }
 
 func (fkc *FKCheckExec) doCheck(ctx context.Context) error {
+	if fkc.ctx.GetSessionVars().StmtCtx.RuntimeStatsColl != nil {
+		fkc.stats = &FKCheckRuntimeStats{}
+		defer fkc.ctx.GetSessionVars().StmtCtx.RuntimeStatsColl.RegisterStats(fkc.ID(), fkc.stats)
+	}
+	if len(fkc.toBeCheckedKeys) == 0 && len(fkc.toBeCheckedPrefixKeys) == 0 {
+		return nil
+	}
+	start := time.Now()
+	if fkc.stats != nil {
+		defer func() {
+			fkc.stats.Keys = len(fkc.toBeCheckedKeys) + len(fkc.toBeCheckedPrefixKeys)
+			fkc.stats.Total = time.Since(start)
+		}()
+	}
 	txn, err := fkc.ctx.Txn(false)
 	if err != nil {
 		return err
@@ -187,6 +217,9 @@ func (fkc *FKCheckExec) doCheck(ctx context.Context) error {
 	if err != nil {
 		return err
 	}
+	if fkc.stats != nil {
+		fkc.stats.Check = time.Since(start)
+	}
 	if len(fkc.toBeLockedKeys) == 0 {
 		return nil
 	}
@@ -202,6 +235,9 @@ func (fkc *FKCheckExec) doCheck(ctx context.Context) error {
 	// doLockKeys may set TxnCtx.ForUpdate to 1, then if the lock meet write conflict, TiDB can't retry for update.
 	// So reset TxnCtx.ForUpdate to 0 then can be retry if meet write conflict.
 	atomic.StoreUint32(&sessVars.TxnCtx.ForUpdate, forUpdate)
+	if fkc.stats != nil {
+		fkc.stats.Lock = time.Since(start) - fkc.stats.Check
+	}
 	return err
 }
 
@@ -477,6 +513,10 @@ type fkCheckKey struct {
 }
 
 func (fkc FKCheckExec) checkRows(ctx context.Context, sc *stmtctx.StatementContext, txn kv.Transaction, rows []toBeCheckedRow) error {
+	if fkc.ctx.GetSessionVars().StmtCtx.RuntimeStatsColl != nil {
+		fkc.stats = &FKCheckRuntimeStats{}
+		defer fkc.ctx.GetSessionVars().StmtCtx.RuntimeStatsColl.RegisterStats(fkc.ID(), fkc.stats)
+	}
 	if len(rows) == 0 {
 		return nil
 	}
@@ -589,6 +629,7 @@ func (b *executorBuilder) buildFKCascadeExec(tbl table.Table, fkCascade *planner
 	return &FKCascadeExec{
 		b:                  b,
 		fkValueHelper:      helper,
+		plan:               fkCascade,
 		tp:                 fkCascade.Tp,
 		referredFK:         fkCascade.ReferredFK,
 		childTable:         fkCascade.ChildTable.Meta(),
@@ -641,6 +682,7 @@ func (fkc *FKCascadeExec) buildExecutor(ctx context.Context) (Executor, error) {
 	if err != nil || p == nil {
 		return nil, err
 	}
+	fkc.plan.CascadePlans = append(fkc.plan.CascadePlans, p)
 	e := fkc.b.build(p)
 	return e, fkc.b.err
 }
@@ -672,6 +714,9 @@ func (fkc *FKCascadeExec) buildFKCascadePlan(ctx context.Context) (plannercore.P
 		case model.ReferOptionCascade:
 			couple := fkc.fetchUpdatedValuesCouple()
 			if couple != nil && len(couple.NewValues) != 0 {
+				if fkc.stats != nil {
+					fkc.stats.Keys += len(couple.OldValuesList)
+				}
 				stmtNode = GenCascadeUpdateAST(fkc.referredFK.ChildSchema, fkc.childTable.Name, indexName, fkc.fkCols, couple)
 			}
 		case model.ReferOptionSetNull:
@@ -703,6 +748,9 @@ func (fkc *FKCascadeExec) fetchOnDeleteOrUpdateFKValues() [][]types.Datum {
 		fkValues = fkc.fkValues[:maxHandleFKValueInOneCascade]
 		fkc.fkValues = fkc.fkValues[maxHandleFKValueInOneCascade:]
 	}
+	if fkc.stats != nil {
+		fkc.stats.Keys += len(fkValues)
+	}
 	return fkValues
 }
 
@@ -815,3 +863,87 @@ func genWhereConditionAstForMultiColumn(cols []*model.ColumnInfo, fkValues [][]t
 		List: valueList,
 	}
 }
+
+// String implements the RuntimeStats interface.
+func (s *FKCheckRuntimeStats) String() string {
+	buf := bytes.NewBuffer(make([]byte, 0, 32))
+	buf.WriteString("total:")
+	buf.WriteString(execdetails.FormatDuration(s.Total))
+	if s.Check > 0 {
+		buf.WriteString(", check:")
+		buf.WriteString(execdetails.FormatDuration(s.Check))
+	}
+	if s.Lock > 0 {
+		buf.WriteString(", lock:")
+		buf.WriteString(execdetails.FormatDuration(s.Lock))
+	}
+	if s.Keys > 0 {
+		buf.WriteString(", foreign_keys:")
+		buf.WriteString(strconv.Itoa(s.Keys))
+	}
+	return buf.String()
+}
+
+// Clone implements the RuntimeStats interface.
+func (s *FKCheckRuntimeStats) Clone() execdetails.RuntimeStats {
+	newRs := &FKCheckRuntimeStats{
+		Total: s.Total,
+		Check: s.Check,
+		Lock:  s.Lock,
+		Keys:  s.Keys,
+	}
+	return newRs
+}
+
+// Merge implements the RuntimeStats interface.
+func (s *FKCheckRuntimeStats) Merge(other execdetails.RuntimeStats) {
+	tmp, ok := other.(*FKCheckRuntimeStats)
+	if !ok {
+		return
+	}
+	s.Total += tmp.Total
+	s.Check += tmp.Check
+	s.Lock += tmp.Lock
+	s.Keys += tmp.Keys
+}
+
+// Tp implements the RuntimeStats interface.
+func (s *FKCheckRuntimeStats) Tp() int {
+	return execdetails.TpFKCheckRuntimeStats
+}
+
+// String implements the RuntimeStats interface.
+func (s *FKCascadeRuntimeStats) String() string {
+	buf := bytes.NewBuffer(make([]byte, 0, 32))
+	buf.WriteString("total:")
+	buf.WriteString(execdetails.FormatDuration(s.Total))
+	if s.Keys > 0 {
+		buf.WriteString(", foreign_keys:")
+		buf.WriteString(strconv.Itoa(s.Keys))
+	}
+	return buf.String()
+}
+
+// Clone implements the RuntimeStats interface.
+func (s *FKCascadeRuntimeStats) Clone() execdetails.RuntimeStats {
+	newRs := &FKCascadeRuntimeStats{
+		Total: s.Total,
+		Keys:  s.Keys,
+	}
+	return newRs
+}
+
+// Merge implements the RuntimeStats interface.
+func (s *FKCascadeRuntimeStats) Merge(other execdetails.RuntimeStats) {
+	tmp, ok := other.(*FKCascadeRuntimeStats)
+	if !ok {
+		return
+	}
+	s.Total += tmp.Total
+	s.Keys += tmp.Keys
+}
+
+// Tp implements the RuntimeStats interface.
+func (s *FKCascadeRuntimeStats) Tp() int {
+	return execdetails.TpFKCascadeRuntimeStats
+}

executor/insert_common.go

@@ -1092,10 +1092,6 @@ func (e *InsertValues) collectRuntimeStatsEnabled() bool {
 				BasicRuntimeStats:     e.runtimeStats,
 				SnapshotRuntimeStats:  snapshotStats,
 				AllocatorRuntimeStats: autoid.NewAllocatorRuntimeStats(),
-				FKCheckStats:          &FKCheckRuntimeStats{},
-			}
-			for _, fkc := range e.fkChecks {
-				fkc.stats = e.stats.FKCheckStats
 			}
 		}
 		return true
@@ -1299,7 +1295,6 @@ type InsertRuntimeStat struct {
 	CheckInsertTime time.Duration
 	Prefetch        time.Duration
 	FKCheckTime     time.Duration
-	FKCheckStats    *FKCheckRuntimeStats
 }
 
 func (e *InsertRuntimeStat) String() string {
@@ -1341,10 +1336,8 @@ func (e *InsertRuntimeStat) String() string {
 			execdetails.FormatDuration(e.CheckInsertTime),
 			execdetails.FormatDuration(e.CheckInsertTime-e.Prefetch),
 			execdetails.FormatDuration(e.Prefetch)))
-		if e.FKCheckStats != nil && e.FKCheckStats.Keys > 0 {
-			buf.WriteString(fmt.Sprintf(", fk_check: %v, fk_num: %v",
-				execdetails.FormatDuration(e.FKCheckTime),
-				e.FKCheckStats.Keys))
+		if e.FKCheckTime > 0 {
+			buf.WriteString(fmt.Sprintf(", fk_check: %v", execdetails.FormatDuration(e.FKCheckTime)))
 		}
 		if e.SnapshotRuntimeStats != nil {
 			if rpc := e.SnapshotRuntimeStats.String(); len(rpc) > 0 {
@@ -1376,10 +1369,6 @@ func (e *InsertRuntimeStat) Clone() execdetails.RuntimeStats {
 	if e.AllocatorRuntimeStats != nil {
 		newRs.AllocatorRuntimeStats = e.AllocatorRuntimeStats.Clone()
 	}
-	if e.FKCheckStats != nil {
-		fkCheckStats := *e.FKCheckStats
-		newRs.FKCheckStats = &fkCheckStats
-	}
 	return newRs
 }
 

executor/insert_test.go

@@ -1056,8 +1056,7 @@ func TestInsertRuntimeStat(t *testing.T) {
 	stats.Merge(stats.Clone())
 	require.Equal(t, "prepare: 6s, check_insert: {total_time: 4s, mem_insert_time: 2s, prefetch: 2s}", stats.String())
 	stats.FKCheckTime = time.Second
-	stats.FKCheckStats = &executor.FKCheckRuntimeStats{Keys: 20}
-	require.Equal(t, "prepare: 6s, check_insert: {total_time: 4s, mem_insert_time: 2s, prefetch: 2s, fk_check: 1s, fk_num: 20}", stats.String())
+	require.Equal(t, "prepare: 6s, check_insert: {total_time: 4s, mem_insert_time: 2s, prefetch: 2s, fk_check: 1s}", stats.String())
 }
 
 func TestDuplicateEntryMessage(t *testing.T) {

planner/core/common_plans.go

@@ -1064,7 +1064,9 @@ func binaryOpFromFlatOp(explainCtx sessionctx.Context, op *FlatOperator, out *ti
 	rootStats, copStats, memTracker, diskTracker := getRuntimeInfo(explainCtx, op.Origin, nil)
 	if rootStats != nil {
 		basic, groups := rootStats.MergeStats()
-		out.RootBasicExecInfo = basic.String()
+		if basic != nil {
+			out.RootBasicExecInfo = basic.String()
+		}
 		for _, group := range groups {
 			str := group.String()
 			if len(str) > 0 {

planner/core/encode.go

@@ -275,11 +275,12 @@ func NormalizeFlatPlan(flat *FlatPhysicalPlan) (normalized string, digest *parse
 	// assume an operator costs around 30 bytes, preallocate space for them
 	d.buf.Grow(30 * len(selectPlan))
 	depthOffset := len(flat.Main) - len(selectPlan)
+loop1:
 	for _, op := range selectPlan {
 		switch op.Origin.(type) {
 		case *FKCheck, *FKCascade:
 			// Generate plan digest doesn't need to contain the foreign key check/cascade plan, so just break the loop.
-			continue
+			break loop1
 		}
 		taskTypeInfo := plancodec.EncodeTaskTypeForNormalize(op.IsRoot, op.StoreType)
 		p := op.Origin.(PhysicalPlan)

planner/core/flat_plan.go

@@ -398,6 +398,13 @@ func (f *FlatPhysicalPlan) flattenRecursively(p Plan, info *operatorCtx, target
 			target, childIdx = f.flattenRecursively(plan.TargetPlan, initInfo, target)
 			childIdxs = append(childIdxs, childIdx)
 		}
+	case *FKCascade:
+		for i, child := range plan.CascadePlans {
+			childCtx.label = Empty
+			childCtx.isLastChild = i == len(plan.CascadePlans)-1
+			target, childIdx = f.flattenRecursively(child, childCtx, target)
+			childIdxs = append(childIdxs, childIdx)
+		}
 	}
 	if flat != nil {
 		flat.ChildrenIdx = childIdxs

planner/core/foreign_key.go

@@ -51,6 +51,10 @@ type FKCascade struct {
 	FK         *model.FKInfo
 	FKCols     []*model.ColumnInfo
 	FKIdx      *model.IndexInfo
+	// CascadePlans contains the child cascade plan.
+	// CascadePlans will be filled during execution, so only `explain analyze` statement result contains the cascade plan,
+	// `explain` statement result doesn't contain the cascade plan.
+	CascadePlans []Plan
 }
 
 // FKCascadeType indicates in which (delete/update) statements.

planner/core/point_get_plan.go

@@ -533,8 +533,10 @@ func TryFastPlan(ctx sessionctx.Context, node ast.Node) (p Plan) {
 		return nil
 	}
 
-	ctx.GetSessionVars().PlanID = 0
-	ctx.GetSessionVars().PlanColumnID = 0
+	if !ctx.GetSessionVars().StmtCtx.InHandleForeignKeyTrigger {
+		ctx.GetSessionVars().PlanID = 0
+		ctx.GetSessionVars().PlanColumnID = 0
+	}
 	switch x := node.(type) {
 	case *ast.SelectStmt:
 		defer func() {