From 63ce7931b0be35084cc17890dc4cdc0be98f3dd4 Mon Sep 17 00:00:00 2001 From: crazycs Date: Wed, 30 Nov 2022 20:00:01 +0800 Subject: [PATCH] *: add foreign key check/cascade runtime stats information in explain analyze result (#39203) close pingcap/tidb#39202 --- distsql/distsql_test.go | 2 +- executor/adapter.go | 18 +- executor/fktest/foreign_key_test.go | 344 +++++++++++++++++++++++++++- executor/foreign_key.go | 134 ++++++++++- executor/insert_common.go | 15 +- executor/insert_test.go | 3 +- planner/core/common_plans.go | 4 +- planner/core/encode.go | 3 +- planner/core/flat_plan.go | 7 + planner/core/foreign_key.go | 4 + planner/core/point_get_plan.go | 6 +- planner/optimize.go | 8 +- util/execdetails/execdetails.go | 12 +- 13 files changed, 518 insertions(+), 42 deletions(-) diff --git a/distsql/distsql_test.go b/distsql/distsql_test.go index bf5593596a18b..f3988ea5f7c4d 100644 --- a/distsql/distsql_test.go +++ b/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()) diff --git a/executor/adapter.go b/executor/adapter.go index c047c2beaa05c..5f01aa51e0378 100644 --- a/executor/adapter.go +++ b/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 { diff --git a/executor/fktest/foreign_key_test.go b/executor/fktest/foreign_key_test.go index dbe02ccd52772..b4f96cdd34811 100644 --- a/executor/fktest/foreign_key_test.go +++ b/executor/fktest/foreign_key_test.go @@ -2006,18 +2006,19 @@ func TestDMLExplainAnalyzeFKInfo(t *testing.T) { tk.MustExec("insert into t1 values (1), (2)") tk.MustExec("insert into t2 values (1)") res := tk.MustQuery("explain analyze insert ignore into t3 values (1, 1, 1), (2, 1, 1), (3, 2, 1), (4, 1, 1), (5, 2, 1), (6, 2, 1)") - getExplainResultFn := func(res *testkit.Result) string { - resBuff := bytes.NewBufferString("") - for _, row := range res.Rows() { - _, _ = fmt.Fprintf(resBuff, "%s\t", row) - } - return resBuff.String() - } - explain := getExplainResultFn(res) - require.Regexpf(t, "time:.* loops:.* prepare:.* check_insert: {total_time:.* mem_insert_time:.* prefetch:.* fk_check:.* fk_num: 3.*", explain, "") + explain := getExplainResult(res) + require.Regexpf(t, "time:.* loops:.* prepare:.* check_insert: {total_time:.* mem_insert_time:.* prefetch:.* fk_check:.*", explain, "") res = tk.MustQuery("explain analyze insert ignore into t3 values (7, null, null), (8, null, null)") - explain = getExplainResultFn(res) - require.NotContains(t, explain, "fk_check", explain, "") + explain = getExplainResult(res) + require.Regexpf(t, "time:.* loops:.* prepare:.* check_insert: {total_time:.* mem_insert_time:.* prefetch:.* fk_check:.*", explain, "") +} + +func getExplainResult(res *testkit.Result) string { + resBuff := bytes.NewBufferString("") + for _, row := range res.Rows() { + _, _ = fmt.Fprintf(resBuff, "%s\t", row) + } + return resBuff.String() } func TestForeignKeyCascadeOnDiffColumnType(t *testing.T) { @@ -2107,3 +2108,324 @@ func TestForeignKeyIssue39419(t *testing.T) { tk.MustExec("update t1 set id=id+10 where id > 1") tk.MustQuery("select * from t1 order by id").Check(testkit.Rows("1 1", "12 12", "13 13")) } + +func TestExplainAnalyzeDMLWithFKInfo(t *testing.T) { + store := testkit.CreateMockStore(t) + tk := testkit.NewTestKit(t, store) + tk.MustExec("set @@global.tidb_enable_foreign_key=1") + tk.MustExec("set @@foreign_key_checks=1") + tk.MustExec("use test") + tk.MustExec("create table t1 (id int key);") + tk.MustExec("create table t2 (id int key, foreign key fk(id) references t1(id) ON UPDATE CASCADE ON DELETE CASCADE);") + tk.MustExec("create table t3 (id int, unique index idx(id));") + tk.MustExec("create table t4 (id int, index idx_id(id),foreign key fk(id) references t3(id));") + tk.MustExec("create table t5 (id int key, id2 int, id3 int, unique index idx2(id2), index idx3(id3));") + tk.MustExec("create table t6 (id int, id2 int, id3 int, index idx_id(id), index idx_id2(id2), " + + "foreign key fk_1 (id) references t5(id) ON UPDATE CASCADE ON DELETE SET NULL, " + + "foreign key fk_2 (id2) references t5(id2) ON UPDATE CASCADE, " + + "foreign key fk_3 (id3) references t5(id3) ON DELETE CASCADE);") + tk.MustExec("create table t7(id int primary key, pid int, index(pid), foreign key(pid) references t7(id) on delete cascade);") + + cases := []struct { + prepare []string + sql string + plan string + }{ + // Test foreign key use primary key. + { + prepare: []string{ + "insert into t1 values (1),(2),(3),(4),(5)", + }, + sql: "explain analyze insert into t2 values (1),(2),(3);", + plan: "Insert_. N/A 0 root time:.*, loops:1, prepare:.*, insert:.*" + + "└─Foreign_Key_Check_. 0.00 0 root table:t1 total:.*, check:.*, lock:.*, foreign_keys:3 foreign_key:fk, check_exist N/A N/A", + }, + { + sql: "explain analyze insert ignore into t2 values (10),(11),(12);", + plan: "Insert_.* fk_check.*" + + "└─Foreign_Key_Check_.* 0 root table:t1 total:0s, foreign_keys:3 foreign_key:fk, check_exist N/A N/A", + }, + { + sql: "explain analyze update t2 set id=id+2 where id >1", + plan: "Update_.* 0 root time:.*, loops:1.*" + + "├─TableReader_.*" + + "│ └─TableRangeScan.*" + + "└─Foreign_Key_Check_.* 0 root table:t1 total:.*, check:.*, lock:.*, foreign_keys:2 foreign_key:fk, check_exist N/A N/A", + }, + { + sql: "explain analyze delete from t1 where id>1", + plan: "Delete_.*" + + "├─TableReader_.*" + + "│ └─TableRangeScan_.*" + + "└─Foreign_Key_Cascade_.* 0 root table:t2 total:.*, foreign_keys:4 foreign_key:fk, on_delete:CASCADE N/A N/A.*" + + " └─Delete_.*" + + " └─Batch_Point_Get_.*", + }, + { + sql: "explain analyze update t1 set id=id+1 where id = 1", + plan: "Update_.*" + + "├─Point_Get_.*" + + "└─Foreign_Key_Cascade_.* 0 root table:t2 total:.*, foreign_keys:1 foreign_key:fk, on_update:CASCADE N/A N/A.*" + + " └─Update_.*" + + " ├─Batch_Point_Get_.*" + + " └─Foreign_Key_Check_.*", + }, + { + sql: "explain analyze insert into t1 values (1) on duplicate key update id = 100", + plan: "Insert_.*" + + "└─Foreign_Key_Cascade_.* 0 root table:t2 total:0s foreign_key:fk, on_update:CASCADE N/A N/A", + }, + { + sql: "explain analyze insert into t1 values (2) on duplicate key update id = 100", + plan: "Insert_.*" + + "└─Foreign_Key_Cascade_.* 0 root table:t2 total:.*, foreign_keys:1 foreign_key:fk, on_update:CASCADE N/A N/A.*" + + " └─Update_.*" + + " ├─Batch_Point_Get_.*" + + " └─Foreign_Key_Check_.* 0 root table:t1 total:.*, check:.*, lock:.*, foreign_keys:1 foreign_key:fk, check_exist N/A N/A", + }, + // Test foreign key use index. + { + prepare: []string{ + "insert into t3 values (1),(2),(3),(4),(5)", + }, + sql: "explain analyze insert into t4 values (1),(2),(3);", + plan: "Insert_.*" + + "└─Foreign_Key_Check_.* 0 root table:t3, index:idx total:.*, check:.*, lock:.*, foreign_keys:3 foreign_key:fk, check_exist N/A N/A", + }, + { + sql: "explain analyze update t4 set id=id+2 where id >1", + plan: "Update_.*" + + "├─IndexReader_.*" + + "│ └─IndexRangeScan_.*" + + "└─Foreign_Key_Check_.* 0 root table:t3, index:idx total:.*, check:.*, lock:.*, foreign_keys:2 foreign_key:fk, check_exist N/A N/A", + }, + { + sql: "explain analyze delete from t3 where id in (2,3)", + plan: "Delete_.*├─Batch_Point_Get_.*" + + "└─Foreign_Key_Check_.* 0 root table:t4, index:idx_id total:.*, check:.*, foreign_keys:2 foreign_key:fk, check_not_exist N/A N/A", + }, + { + prepare: []string{ + "insert into t3 values (2)", + }, + sql: "explain analyze update t3 set id=id+1 where id = 2", + plan: "Update_.*" + + "├─Point_Get_.*" + + "└─Foreign_Key_Check_.* 0 root table:t4, index:idx_id total:.*, check:.*, foreign_keys:1 foreign_key:fk, check_not_exist N/A N/A", + }, + + { + sql: "explain analyze insert into t3 values (2) on duplicate key update id = 100", + plan: "Insert_.*" + + "└─Foreign_Key_Check_.* 0 root table:t4, index:idx_id total:0s foreign_key:fk, check_not_exist N/A N/A", + }, + { + sql: "explain analyze insert into t3 values (3) on duplicate key update id = 100", + plan: "Insert_.*" + + "└─Foreign_Key_Check_.* 0 root table:t4, index:idx_id total:.*, check:.*, foreign_keys:1 foreign_key:fk, check_not_exist N/A N/A", + }, + // Test multi-foreign keys in on table. + { + prepare: []string{ + "insert into t5 values (1,1,1),(2,2,2),(3,3,3),(4,4,4),(5,5,5)", + }, + sql: "explain analyze insert into t6 values (1,1,1)", + plan: "Insert_.*" + + "├─Foreign_Key_Check_.* 0 root table:t5 total:.*, check:.*, lock:.*, foreign_keys:1 foreign_key:fk_1, check_exist N/A N/A.*" + + "├─Foreign_Key_Check_.* 0 root table:t5, index:idx2 total:.*, check:.*, lock:.*, foreign_keys:1 foreign_key:fk_2, check_exist N/A N/A.*" + + "└─Foreign_Key_Check_.* 0 root table:t5, index:idx3 total:.*, check:.*, lock:.*, foreign_keys:1 foreign_key:fk_3, check_exist N/A N/A", + }, + { + sql: "explain analyze insert ignore into t6 values (1,1,10)", + plan: "Insert_.* root time:.* loops:.* prepare:.* check_insert.* fk_check:.*" + + "├─Foreign_Key_Check.* 0 root table:t5 total:0s, foreign_keys:1 foreign_key:fk_1, check_exist N/A N/A.*" + + "├─Foreign_Key_Check.* 0 root table:t5, index:idx2 total:0s, foreign_keys:1 foreign_key:fk_2, check_exist N/A N/A.*" + + "└─Foreign_Key_Check.* 0 root table:t5, index:idx3 total:0s, foreign_keys:1 foreign_key:fk_3, check_exist N/A N/A", + }, + { + sql: "explain analyze update t6 set id=id+1, id3=id2+1 where id = 1", + plan: "Update_.*" + + "├─IndexLookUp_.*" + + "│ ├─IndexRangeScan_.*" + + "│ └─TableRowIDScan_.*" + + "├─Foreign_Key_Check_.* 0 root table:t5 total:.*, check:.*, lock:.*, foreign_keys:1 foreign_key:fk_1, check_exist N/A N/A.*" + + "└─Foreign_Key_Check_.* 0 root table:t5, index:idx3 total:.*, check:.*, lock:.*, foreign_keys:1 foreign_key:fk_3, check_exist N/A N/A", + }, + { + sql: "explain analyze delete from t5 where id in (4,5)", + plan: "Delete_.*" + + "├─Batch_Point_Get_.*" + + "├─Foreign_Key_Check_.* 0 root table:t6, index:idx_id2 total:.*, check:.*, foreign_keys:2 foreign_key:fk_2, check_not_exist N/A N/A.*" + + "├─Foreign_Key_Cascade_.* 0 root table:t6, index:idx_id total:.*, foreign_keys:2 foreign_key:fk_1, on_delete:SET NULL N/A N/A.*" + + "│ └─Update_.*" + + "│ │ ├─IndexRangeScan_.*" + + "│ │ └─TableRowIDScan_.*" + + "│ └─Foreign_Key_Check_.* 0 root table:t5 total:0s foreign_key:fk_1, check_exist N/A N/A.*" + + "└─Foreign_Key_Cascade_.* 0 root table:t6, index:fk_3 total:.*, foreign_keys:2 foreign_key:fk_3, on_delete:CASCADE N/A N/A.*" + + " └─Delete_.*" + + " └─IndexLookUp_.*" + + " ├─IndexRangeScan_.*" + + " └─TableRowIDScan_.*", + }, + { + sql: "explain analyze update t5 set id=id+1, id2=id2+1 where id = 3", + plan: "Update_.*" + + "├─Point_Get_.*" + + "├─Foreign_Key_Cascade_.* 0 root table:t6, index:idx_id total:.*, foreign_keys:1 foreign_key:fk_1, on_update:CASCADE N/A N/A.*" + + "│ └─Update_.*" + + "│ ├─IndexLookUp_.*" + + "│ │ ├─IndexRangeScan_.*" + + "│ │ └─TableRowIDScan_.*" + + "│ └─Foreign_Key_Check_.* 0 root table:t5 total:0s foreign_key:fk_1, check_exist N/A N/A.*" + + "└─Foreign_Key_Cascade_.* 0 root table:t6, index:idx_id2 total:.*, foreign_keys:1 foreign_key:fk_2, on_update:CASCADE N/A N/A.*" + + " └─Update_.*" + + " ├─IndexLookUp_.*" + + " │ ├─IndexRangeScan_.*" + + " │ └─TableRowIDScan_.*" + + " └─Foreign_Key_Check_.* 0 root table:t5, index:idx2 total:0s foreign_key:fk_2, check_exist N/A N/A", + }, + { + prepare: []string{ + "insert into t5 values (10,10,10)", + }, + sql: "explain analyze update t5 set id=id+1, id2=id2+1, id3=id3+1 where id = 10", + plan: "Update_.*" + + "├─Point_Get_.*" + + "├─Foreign_Key_Check_.* 0 root table:t6, index:fk_3 total:.*, check:.*, foreign_keys:1 foreign_key:.*, check_not_exist N/A N/A.*" + + "├─Foreign_Key_Cascade_.* 0 root table:t6, index:idx_id total:.*, foreign_keys:1 foreign_key:fk_1, on_update:CASCADE N/A N/A.*" + + "│ └─Update_.*" + + "│ ├─IndexLookUp_.*" + + "│ │ ├─IndexRangeScan_.*" + + "│ │ └─TableRowIDScan_.*" + + "│ └─Foreign_Key_Check_.*" + + "└─Foreign_Key_Cascade_.* 0 root table:t6, index:idx_id2 total:.*, foreign_keys:1 foreign_key:fk_2, on_update:CASCADE N/A N/A.*" + + " └─Update_.*" + + " ├─IndexLookUp_.*" + + " │ ├─IndexRangeScan_.*" + + " │ └─TableRowIDScan_.*" + + " └─Foreign_Key_Check_.* 0 root table:t5, index:idx2 total:0s foreign_key:fk_2, check_exist N/A N/A", + }, + { + sql: "explain analyze insert into t5 values (1,1,1) on duplicate key update id = 100, id3=100", + plan: "Insert_.*" + + "├─Foreign_Key_Check_.* 0 root table:t6, index:fk_3 total:.*, check:.*, foreign_keys:1 foreign_key:fk_3, check_not_exist N/A N/A.*" + + "└─Foreign_Key_Cascade_.* 0 root table:t6, index:idx_id total:.*, foreign_keys:1 foreign_key:fk_1, on_update:CASCADE N/A N/A.*" + + " └─Update_.*" + + " ├─IndexLookUp_.*" + + " │ ├─IndexRangeScan_.*" + + " │ └─TableRowIDScan_.*" + + " └─Foreign_Key_Check_.* 0 root table:t5 total:0s foreign_key:fk_1, check_exist N/A N/A", + }, + { + prepare: []string{ + "insert into t7 values(0,0),(1,0),(2,1),(3,2),(4,3),(5,4),(6,5),(7,6),(8,7),(9,8),(10,9),(11,10),(12,11),(13,12),(14,13);", + }, + sql: "explain analyze delete from t7 where id = 0;", + plan: "Delete_.*" + + "├─Point_Get_.*" + + "└─Foreign_Key_Cascade_.* 0 root table:t7, index:pid total:.* foreign_keys:1 foreign_key:fk_1, on_delete:CASCADE.*" + + " └─Delete_.*" + + " ├─UnionScan_.*" + + " │ └─IndexReader_.*" + + " │ └─IndexRangeScan_.*" + + " └─Foreign_Key_Cascade_.* 0 root table:t7, index:pid total:.* foreign_keys:2 foreign_key:fk_1, on_delete:CASCADE.*" + + " └─Delete_.*" + + " ├─UnionScan_.*" + + " │ └─IndexReader_.*" + + " │ └─IndexRangeScan_.*" + + " └─Foreign_Key_Cascade_.* 0 root table:t7, index:pid total:.*, foreign_keys:1 foreign_key:fk_1, on_delete:CASCADE.*" + + " └─Delete_.*" + + " ├─UnionScan_.*" + + " │ └─IndexReader_.*" + + " │ └─IndexRangeScan_.*" + + " └─Foreign_Key_Cascade_.* 0 root table:t7, index:pid total:.*, foreign_keys:1 foreign_key:fk_1, on_delete:CASCADE.*" + + " └─Delete_.*" + + " ├─UnionScan_.*" + + " │ └─IndexReader_.*" + + " │ └─IndexRangeScan_.*" + + " └─Foreign_Key_Cascade_.* 0 root table:t7, index:pid total:.*, foreign_keys:1 foreign_key:fk_1, on_delete:CASCADE.*" + + " └─Delete_.*" + + " ├─UnionScan_.*" + + " │ └─IndexReader_.*" + + " │ └─IndexRangeScan_.*" + + " └─Foreign_Key_Cascade_.* 0 root table:t7, index:pid total:.*, foreign_keys:1 foreign_key:fk_1, on_delete:CASCADE.*" + + " └─Delete_.*" + + " ├─UnionScan_.*" + + " │ └─IndexReader_.*" + + " │ └─IndexRangeScan_.*" + + " └─Foreign_Key_Cascade_.* 0 root table:t7, index:pid total:.*, foreign_keys:1 foreign_key:fk_1, on_delete:CASCADE.*" + + " └─Delete_.*" + + " ├─UnionScan_.*" + + " │ └─IndexReader_.*" + + " │ └─IndexRangeScan_.*" + + " └─Foreign_Key_Cascade_.* 0 root table:t7, index:pid total:.*, foreign_keys:1 foreign_key:fk_1, on_delete:CASCADE.*" + + " └─Delete_.*" + + " ├─UnionScan_.*" + + " │ └─IndexReader_.*" + + " │ └─IndexRangeScan_.*" + + " └─Foreign_Key_Cascade_.* 0 root table:t7, index:pid total:.*, foreign_keys:1 foreign_key:fk_1, on_delete:CASCADE.*" + + " └─Delete_.*" + + " ├─UnionScan_.*" + + " │ └─IndexReader_.*" + + " │ └─IndexRangeScan_.*" + + " └─Foreign_Key_Cascade_.* 0 root table:t7, index:pid total:.*, foreign_keys:1 foreign_key:fk_1, on_delete:CASCADE.*" + + " └─Delete_.*" + + " ├─UnionScan_.*" + + " │ └─IndexReader_.*" + + " │ └─IndexRangeScan_.*" + + " └─Foreign_Key_Cascade_.* 0 root table:t7, index:pid total:.*, foreign_keys:1 foreign_key:fk_1, on_delete:CASCADE.*" + + " └─Delete_.*" + + " ├─UnionScan_.*" + + " │ └─IndexReader_.*" + + " │ └─IndexRangeScan_.*" + + " └─Foreign_Key_Cascade_.* 0 root table:t7, index:pid total:.*, foreign_keys:1 foreign_key:fk_1, on_delete:CASCADE.*" + + " └─Delete_.*" + + " ├─UnionScan_.*" + + " │ └─IndexReader_.*" + + " │ └─IndexRangeScan_.*" + + " └─Foreign_Key_Cascade_.* 0 root table:t7, index:pid total:.*, foreign_keys:1 foreign_key:fk_1, on_delete:CASCADE.*" + + " └─Delete_.*" + + " ├─UnionScan_.*" + + " │ └─IndexReader_.*" + + " │ └─IndexRangeScan_.*" + + " └─Foreign_Key_Cascade_.* 0 root table:t7, index:pid total:.*, foreign_keys:1 foreign_key:fk_1, on_delete:CASCADE.*" + + " └─Delete_.*" + + " ├─UnionScan_.*" + + " │ └─IndexReader_.*" + + " │ └─IndexRangeScan_.*" + + " └─Foreign_Key_Cascade_.* 0 root table:t7, index:pid total:.*, foreign_keys:1 foreign_key:fk_1, on_delete:CASCADE.*" + + " └─Delete_.*" + + " ├─UnionScan_.*" + + " │ └─IndexReader_.*" + + " │ └─IndexRangeScan_.*" + + " └─Foreign_Key_Cascade_.* 0 root table:t7, index:pid total:0s foreign_key:fk_1, on_delete:CASCADE.*", + }, + } + for _, ca := range cases { + for _, sql := range ca.prepare { + tk.MustExec(sql) + } + res := tk.MustQuery(ca.sql) + explain := getExplainResult(res) + require.Regexp(t, ca.plan, explain) + } +} + +func TestForeignKeyRuntimeStats(t *testing.T) { + checkStats := executor.FKCheckRuntimeStats{ + Total: time.Second * 3, + Check: time.Second * 2, + Lock: time.Second, + Keys: 10, + } + require.Equal(t, "total:3s, check:2s, lock:1s, foreign_keys:10", checkStats.String()) + checkStats.Merge(checkStats.Clone()) + require.Equal(t, "total:6s, check:4s, lock:2s, foreign_keys:20", checkStats.String()) + cascadeStats := executor.FKCascadeRuntimeStats{ + Total: time.Second, + Keys: 10, + } + require.Equal(t, "total:1s, foreign_keys:10", cascadeStats.String()) + cascadeStats.Merge(cascadeStats.Clone()) + require.Equal(t, "total:2s, foreign_keys:20", cascadeStats.String()) +} diff --git a/executor/foreign_key.go b/executor/foreign_key.go index 8191c55029750..df293c76209e5 100644 --- a/executor/foreign_key.go +++ b/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 +} diff --git a/executor/insert_common.go b/executor/insert_common.go index 7fcc0821ce82d..dbd4a5ae264cd 100644 --- a/executor/insert_common.go +++ b/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 } diff --git a/executor/insert_test.go b/executor/insert_test.go index f3db8c6aca40f..314ebb63b6c3b 100644 --- a/executor/insert_test.go +++ b/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) { diff --git a/planner/core/common_plans.go b/planner/core/common_plans.go index b2abca66a5532..eccc3ad5bba91 100644 --- a/planner/core/common_plans.go +++ b/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 { diff --git a/planner/core/encode.go b/planner/core/encode.go index ebe1596a36a4c..663f743517953 100644 --- a/planner/core/encode.go +++ b/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) diff --git a/planner/core/flat_plan.go b/planner/core/flat_plan.go index 72dd18754c1ba..bbd6ea5f593f6 100644 --- a/planner/core/flat_plan.go +++ b/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 diff --git a/planner/core/foreign_key.go b/planner/core/foreign_key.go index de3ccaf5bf6c8..00b87e11c01f8 100644 --- a/planner/core/foreign_key.go +++ b/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. diff --git a/planner/core/point_get_plan.go b/planner/core/point_get_plan.go index de69438257f4e..859f175188056 100644 --- a/planner/core/point_get_plan.go +++ b/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() { diff --git a/planner/optimize.go b/planner/optimize.go index 28bea204d449e..b56ae4a1321a9 100644 --- a/planner/optimize.go +++ b/planner/optimize.go @@ -428,9 +428,11 @@ func OptimizeExecStmt(ctx context.Context, sctx sessionctx.Context, } func buildLogicalPlan(ctx context.Context, sctx sessionctx.Context, node ast.Node, builder *core.PlanBuilder) (core.Plan, error) { - sctx.GetSessionVars().PlanID = 0 - sctx.GetSessionVars().PlanColumnID = 0 - sctx.GetSessionVars().MapHashCode2UniqueID4ExtendedCol = nil + if !sctx.GetSessionVars().StmtCtx.InHandleForeignKeyTrigger { + sctx.GetSessionVars().PlanID = 0 + sctx.GetSessionVars().PlanColumnID = 0 + sctx.GetSessionVars().MapHashCode2UniqueID4ExtendedCol = nil + } failpoint.Inject("mockRandomPlanID", func() { sctx.GetSessionVars().PlanID = rand.Intn(1000) // nolint:gosec diff --git a/util/execdetails/execdetails.go b/util/execdetails/execdetails.go index aef6ecc88b18f..1867ebc1c945c 100644 --- a/util/execdetails/execdetails.go +++ b/util/execdetails/execdetails.go @@ -515,6 +515,10 @@ const ( TpBasicCopRunTimeStats // TpUpdateRuntimeStats is the tp for UpdateRuntimeStats TpUpdateRuntimeStats + // TpFKCheckRuntimeStats is the tp for FKCheckRuntimeStats + TpFKCheckRuntimeStats + // TpFKCascadeRuntimeStats is the tp for FKCascadeRuntimeStats + TpFKCascadeRuntimeStats ) // RuntimeStats is used to express the executor runtime information. @@ -621,11 +625,14 @@ type RootRuntimeStats struct { // NewRootRuntimeStats returns a new RootRuntimeStats func NewRootRuntimeStats() *RootRuntimeStats { - return &RootRuntimeStats{basic: &BasicRuntimeStats{}} + return &RootRuntimeStats{} } // GetActRows return total rows of RootRuntimeStats. func (e *RootRuntimeStats) GetActRows() int64 { + if e.basic == nil { + return 0 + } return e.basic.rows } @@ -638,8 +645,7 @@ func (e *RootRuntimeStats) MergeStats() (basic *BasicRuntimeStats, groups []Runt func (e *RootRuntimeStats) String() string { basic, groups := e.MergeStats() strs := make([]string, 0, len(groups)+1) - basicStr := basic.String() - if len(basicStr) > 0 { + if basic != nil { strs = append(strs, basic.String()) } for _, group := range groups {