*: add stats version in slow_query and slow log. (#10082)

cmd/explaintest/r/explain_easy.result

@@ -78,7 +78,7 @@ IndexLookUp_12	1.11	root
 ├─Selection_10	3.33	cop	gt(test.t1.c1, 1)
 │ └─IndexScan_8	10.00	cop	table:t1, index:c2, range:[1,1], keep order:false, stats:pseudo
 └─Selection_11	1.11	cop	lt(test.t1.c3, 1)
-  └─TableScan_9	3.33	cop	table:t1, keep order:false
+  └─TableScan_9	3.33	cop	table:t1, keep order:false, stats:pseudo
 explain select * from t1 where c1 = 1 and c2 > 1;
 id	count	task	operator info
 TableReader_7	0.33	root	data:Selection_6
@@ -118,7 +118,7 @@ Projection_12	10000.00	root	eq(test.t1.c2, test.t2.c2)
     └─IndexLookUp_43	1.00	root	
       ├─Limit_42	1.00	cop	offset:0, count:1
       │ └─IndexScan_40	1.25	cop	table:t2, index:c1, range: decided by [eq(test.t1.c1, test.t2.c1)], keep order:true, stats:pseudo
-      └─TableScan_41	1.00	cop	table:t2, keep order:false
+      └─TableScan_41	1.00	cop	table:t2, keep order:false, stats:pseudo
 explain select * from t1 order by c1 desc limit 1;
 id	count	task	operator info
 Limit_10	1.00	root	offset:0, count:1
@@ -133,7 +133,7 @@ Limit_9	1.00	root	offset:0, count:1
   │ └─IndexScan_12	9.00	cop	table:t4, index:a, b, range:(1 +inf,+inf +inf], keep order:false, stats:pseudo
   └─Limit_16	1.00	cop	offset:0, count:1
     └─Selection_15	1.00	cop	gt(test.t4.c, 1)
-      └─TableScan_13	3.00	cop	table:t4, keep order:false
+      └─TableScan_13	3.00	cop	table:t4, keep order:false, stats:pseudo
 explain select * from t4 where a > 1 and c > 1 limit 1;
 id	count	task	operator info
 Limit_8	1.00	root	offset:0, count:1

cmd/explaintest/r/explain_easy_stats.result

@@ -50,7 +50,7 @@ Projection_6	2481.25	root	test.t1.c1, test.t1.c2, test.t1.c3, test.t2.c1, test.t
   ├─IndexLookUp_17	1998.00	root	
   │ ├─Selection_16	1998.00	cop	gt(test.t1.c1, 1)
   │ │ └─IndexScan_14	1999.00	cop	table:t1, index:c2, range:[NULL,+inf], keep order:true
-  │ └─TableScan_15	1998.00	cop	table:t1, keep order:false
+  │ └─TableScan_15	1998.00	cop	table:t1, keep order:false, stats:pseudo
   └─IndexLookUp_21	1985.00	root	
     ├─IndexScan_19	1985.00	cop	table:t2, index:c1, range:[NULL,+inf], keep order:true
     └─TableScan_20	1985.00	cop	table:t2, keep order:false
@@ -84,7 +84,7 @@ IndexLookUp_12	0.00	root
 ├─Selection_10	0.00	cop	gt(test.t1.c1, 1)
 │ └─IndexScan_8	0.00	cop	table:t1, index:c2, range:[1,1], keep order:false
 └─Selection_11	0.00	cop	lt(test.t1.c3, 1)
-  └─TableScan_9	0.00	cop	table:t1, keep order:false
+  └─TableScan_9	0.00	cop	table:t1, keep order:false, stats:pseudo
 explain select * from t1 where c1 = 1 and c2 > 1;
 id	count	task	operator info
 TableReader_7	0.50	root	data:Selection_6
@@ -106,7 +106,7 @@ Projection_12	1999.00	root	eq(test.t1.c2, test.t2.c2)
     └─IndexLookUp_43	1.00	root	
       ├─Limit_42	1.00	cop	offset:0, count:1
       │ └─IndexScan_40	1.25	cop	table:t2, index:c1, range: decided by [eq(test.t1.c1, test.t2.c1)], keep order:true
-      └─TableScan_41	1.00	cop	table:t2, keep order:false
+      └─TableScan_41	1.00	cop	table:t2, keep order:false, stats:pseudo
 explain select * from t1 order by c1 desc limit 1;
 id	count	task	operator info
 Limit_10	1.00	root	offset:0, count:1
@@ -163,14 +163,14 @@ Limit_9	1.00	root	offset:1, count:1
 └─IndexLookUp_15	1.00	root	
   ├─Limit_14	1.00	cop	offset:0, count:2
   │ └─IndexScan_12	1.00	cop	table:index_prune, index:a, b, range:[1010010404050976781 26467085526790,1010010404050976781 26467085526790], keep order:false
-  └─TableScan_13	1.00	cop	table:index_prune, keep order:false
+  └─TableScan_13	1.00	cop	table:index_prune, keep order:false, stats:pseudo
 explain select * from index_prune WHERE a = 1010010404050976781 AND b = 26467085526790 LIMIT 1, 0;
 id	count	task	operator info
 Limit_9	0.00	root	offset:1, count:0
 └─IndexLookUp_15	0.00	root	
   ├─Limit_14	0.00	cop	offset:0, count:1
   │ └─IndexScan_12	1.00	cop	table:index_prune, index:a, b, range:[1010010404050976781 26467085526790,1010010404050976781 26467085526790], keep order:false
-  └─TableScan_13	0.00	cop	table:index_prune, keep order:false
+  └─TableScan_13	0.00	cop	table:index_prune, keep order:false, stats:pseudo
 explain select * from index_prune WHERE a = 1010010404050976781 AND b = 26467085526790 LIMIT 0, 1;
 id	count	task	operator info
 Point_Get_1	1.00	root	table:index_prune, index:a b

cmd/explaintest/r/topn_push_down.result

@@ -176,7 +176,7 @@ Projection_12	0.00	root	te.expect_time
     │   │ ├─Selection_80	0.00	cop	eq(tr.business_type, 18), in(tr.trade_type, 1)
     │   │ │ └─IndexScan_78	10.00	cop	table:tr, index:shop_identy, trade_status, business_type, trade_pay_status, trade_type, delivery_type, source, biz_date, range:[810094178,810094178], keep order:false, stats:pseudo
     │   │ └─Selection_81	0.00	cop	eq(tr.brand_identy, 32314), eq(tr.domain_type, 2)
-    │   │   └─TableScan_79	0.00	cop	table:tr, keep order:false
+    │   │   └─TableScan_79	0.00	cop	table:tr, keep order:false, stats:pseudo
     │   └─IndexLookUp_33	250.00	root	
     │     ├─IndexScan_30	10.00	cop	table:te, index:trade_id, range: decided by [tr.id], keep order:false, stats:pseudo
     │     └─Selection_32	250.00	cop	ge(te.expect_time, 2018-04-23 00:00:00.000000), le(te.expect_time, 2018-04-23 23:59:59.000000)

executor/adapter.go

@@ -402,12 +402,13 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) {
 		indexIDs = strings.Replace(fmt.Sprintf("%v", a.Ctx.GetSessionVars().StmtCtx.IndexIDs), " ", ",", -1)
 	}
 	execDetail := sessVars.StmtCtx.GetExecDetails()
+	statsInfos := a.getStatsInfo()
 	if costTime < threshold {
 		_, digest := sessVars.StmtCtx.SQLDigest()
-		logutil.SlowQueryLogger.Debugf(sessVars.SlowLogFormat(txnTS, costTime, execDetail, indexIDs, digest, sql))
+		logutil.SlowQueryLogger.Debug(sessVars.SlowLogFormat(txnTS, costTime, execDetail, indexIDs, digest, statsInfos, sql))
 	} else {
 		_, digest := sessVars.StmtCtx.SQLDigest()
-		logutil.SlowQueryLogger.Warnf(sessVars.SlowLogFormat(txnTS, costTime, execDetail, indexIDs, digest, sql))
+		logutil.SlowQueryLogger.Warn(sessVars.SlowLogFormat(txnTS, costTime, execDetail, indexIDs, digest, statsInfos, sql))
 		metrics.TotalQueryProcHistogram.Observe(costTime.Seconds())
 		metrics.TotalCopProcHistogram.Observe(execDetail.ProcessTime.Seconds())
 		metrics.TotalCopWaitHistogram.Observe(execDetail.WaitTime.Seconds())
@@ -433,6 +434,28 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) {
 	}
 }
 
+func (a *ExecStmt) getStatsInfo() map[string]uint64 {
+	var physicalPlan plannercore.PhysicalPlan
+	switch p := a.Plan.(type) {
+	case *plannercore.Insert:
+		physicalPlan = p.SelectPlan
+	case *plannercore.Update:
+		physicalPlan = p.SelectPlan
+	case *plannercore.Delete:
+		physicalPlan = p.SelectPlan
+	case plannercore.PhysicalPlan:
+		physicalPlan = p
+	}
+
+	if physicalPlan == nil {
+		return nil
+	}
+
+	statsInfos := make(map[string]uint64)
+	statsInfos = plannercore.CollectPlanStatsVersion(physicalPlan, statsInfos)
+	return statsInfos
+}
+
 // IsPointGetWithPKOrUniqueKeyByAutoCommit returns true when meets following conditions:
 //  1. ctx is auto commit tagged
 //  2. txn is not valid

executor/aggregate_test.go

@@ -239,7 +239,7 @@ func (s *testSuite) TestAggregation(c *C) {
 
 	result = tk.MustQuery("select count(*) from information_schema.columns")
 	// When adding new memory columns in information_schema, please update this variable.
-	columnCountOfAllInformationSchemaTables := "785"
+	columnCountOfAllInformationSchemaTables := "786"
 	result.Check(testkit.Rows(columnCountOfAllInformationSchemaTables))
 
 	tk.MustExec("drop table if exists t1")

infoschema/slow_log.go

@@ -47,6 +47,7 @@ var slowQueryCols = []columnInfo{
 	{variable.SlowLogIndexIDsStr, mysql.TypeVarchar, 100, 0, nil, nil},
 	{variable.SlowLogIsInternalStr, mysql.TypeTiny, 1, 0, nil, nil},
 	{variable.SlowLogDigestStr, mysql.TypeVarchar, 64, 0, nil, nil},
+	{variable.SlowLogStatsInfoStr, mysql.TypeVarchar, 512, 0, nil, nil},
 	{variable.SlowLogQuerySQLStr, mysql.TypeVarchar, 4096, 0, nil, nil},
 }
 
@@ -138,6 +139,7 @@ type slowQueryTuple struct {
 	indexNames   string
 	isInternal   bool
 	digest       string
+	statsInfo    string
 	sql          string
 }
 
@@ -216,6 +218,8 @@ func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string)
 		st.isInternal = value == "true"
 	case variable.SlowLogDigestStr:
 		st.digest = value
+	case variable.SlowLogStatsInfoStr:
+		st.statsInfo = value
 	case variable.SlowLogQuerySQLStr:
 		st.sql = value
 	}
@@ -243,6 +247,7 @@ func (st *slowQueryTuple) convertToDatumRow() []types.Datum {
 	record = append(record, types.NewStringDatum(st.indexNames))
 	record = append(record, types.NewDatum(st.isInternal))
 	record = append(record, types.NewStringDatum(st.digest))
+	record = append(record, types.NewStringDatum(st.statsInfo))
 	record = append(record, types.NewStringDatum(st.sql))
 	return record
 }

infoschema/slow_log_test.go

@@ -31,6 +31,7 @@ func (s *testSuite) TestParseSlowLogFile(c *C) {
 # Process_time: 0.021 Request_count: 1 Total_keys: 637 Processed_keys: 436
 # Is_internal: true
 # Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772
+# Stats: t1:1,t2:2
 select * from t;`)
 	scanner := bufio.NewScanner(slowLog)
 	loc, err := time.LoadLocation("Asia/Shanghai")
@@ -47,7 +48,7 @@ select * from t;`)
 		}
 		recordString += str
 	}
-	expectRecordString := "2019-01-24 22:32:29.313255,405888132465033227,,0,0.216905,0.021,0,0,1,637,0,,,1,42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772,select * from t;"
+	expectRecordString := "2019-01-24 22:32:29.313255,405888132465033227,,0,0.216905,0.021,0,0,1,637,0,,,1,42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772,t1:1,t2:2,select * from t;"
 	c.Assert(expectRecordString, Equals, recordString)
 }
 

infoschema/tables_test.go

@@ -302,18 +302,21 @@ func (s *testSuite) TestSlowQuery(c *C) {
 # Conn_ID: 6
 # Query_time: 4.895492
 # Process_time: 0.161 Request_count: 1 Total_keys: 100001 Process_keys: 100000
+# Wait_time: 0.101
+# Backoff_time: 0.092
 # DB: test
 # Is_internal: false
 # Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772
+# Stats: t1:1,t2:2
 select * from t_slim;`))
 	c.Assert(f.Close(), IsNil)
 	c.Assert(err, IsNil)
 
 	tk.MustExec(fmt.Sprintf("set @@tidb_slow_query_file='%v'", slowLogFileName))
 	tk.MustExec("set time_zone = '+08:00';")
 	re := tk.MustQuery("select * from information_schema.slow_query")
-	re.Check(testutil.RowsWithSep("|", "2019-02-12 19:33:56.571953|406315658548871171|root@127.0.0.1|6|4.895492|0.161|0|0|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|select * from t_slim;"))
+	re.Check(testutil.RowsWithSep("|", "2019-02-12 19:33:56.571953|406315658548871171|root@127.0.0.1|6|4.895492|0.161|0.101|0.092|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|select * from t_slim;"))
 	tk.MustExec("set time_zone = '+00:00';")
 	re = tk.MustQuery("select * from information_schema.slow_query")
-	re.Check(testutil.RowsWithSep("|", "2019-02-12 11:33:56.571953|406315658548871171|root@127.0.0.1|6|4.895492|0.161|0|0|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|select * from t_slim;"))
+	re.Check(testutil.RowsWithSep("|", "2019-02-12 11:33:56.571953|406315658548871171|root@127.0.0.1|6|4.895492|0.161|0.101|0.092|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|select * from t_slim;"))
 }

planner/core/exhaust_physical_plans.go

@@ -24,6 +24,7 @@ import (
 	"github.com/pingcap/tidb/expression"
 	"github.com/pingcap/tidb/expression/aggregation"
 	"github.com/pingcap/tidb/planner/property"
+	"github.com/pingcap/tidb/statistics"
 	"github.com/pingcap/tidb/types"
 	"github.com/pingcap/tidb/util/ranger"
 	"github.com/pingcap/tidb/util/set"
@@ -491,7 +492,10 @@ func (p *LogicalJoin) constructInnerTableScan(ds *DataSource, pk *expression.Col
 	ts.SetSchema(ds.schema)
 
 	ts.stats = property.NewSimpleStats(1)
-	ts.stats.UsePseudoStats = ds.statisticTable.Pseudo
+	ts.stats.StatsVersion = ds.statisticTable.Version
+	if ds.statisticTable.Pseudo {
+		ts.stats.StatsVersion = statistics.PseudoVersion
+	}
 
 	copTask := &copTask{
 		tablePlan:         ts,
@@ -526,7 +530,10 @@ func (p *LogicalJoin) constructInnerIndexScan(ds *DataSource, idx *model.IndexIn
 		rowCount = ds.statisticTable.PseudoAvgCountPerValue()
 	}
 	is.stats = property.NewSimpleStats(rowCount)
-	is.stats.UsePseudoStats = ds.statisticTable.Pseudo
+	is.stats.StatsVersion = ds.statisticTable.Version
+	if ds.statisticTable.Pseudo {
+		is.stats.StatsVersion = statistics.PseudoVersion
+	}
 
 	cop := &copTask{
 		indexPlan: is,

planner/core/explain.go

@@ -19,6 +19,7 @@ import (
 
 	"github.com/pingcap/tidb/expression"
 	"github.com/pingcap/tidb/expression/aggregation"
+	"github.com/pingcap/tidb/statistics"
 )
 
 // ExplainInfo implements PhysicalPlan interface.
@@ -67,7 +68,7 @@ func (p *PhysicalIndexScan) ExplainInfo() string {
 	if p.Desc {
 		buffer.WriteString(", desc")
 	}
-	if p.stats.UsePseudoStats {
+	if p.stats.StatsVersion == statistics.PseudoVersion {
 		buffer.WriteString(", stats:pseudo")
 	}
 	return buffer.String()
@@ -108,7 +109,7 @@ func (p *PhysicalTableScan) ExplainInfo() string {
 	if p.Desc {
 		buffer.WriteString(", desc")
 	}
-	if p.stats.UsePseudoStats {
+	if p.stats.StatsVersion == statistics.PseudoVersion {
 		buffer.WriteString(", stats:pseudo")
 	}
 	return buffer.String()

planner/core/find_best_task.go

@@ -22,6 +22,7 @@ import (
 	"github.com/pingcap/tidb/expression"
 	"github.com/pingcap/tidb/infoschema"
 	"github.com/pingcap/tidb/planner/property"
+	"github.com/pingcap/tidb/statistics"
 	"github.com/pingcap/tidb/types"
 	"github.com/pingcap/tidb/util/chunk"
 	"golang.org/x/tools/container/intsets"
@@ -502,7 +503,11 @@ func (ds *DataSource) convertToIndexScan(prop *property.PhysicalProperty, candid
 		rowCount = math.Min(prop.ExpectedCnt/selectivity, rowCount)
 	}
 	is.stats = property.NewSimpleStats(rowCount)
-	is.stats.UsePseudoStats = ds.statisticTable.Pseudo
+	is.stats.StatsVersion = ds.statisticTable.Version
+	if ds.statisticTable.Pseudo {
+		is.stats.StatsVersion = statistics.PseudoVersion
+	}
+
 	cop.cst = rowCount * scanFactor
 	task = cop
 	if candidate.isMatchProp {
@@ -654,7 +659,11 @@ func (ds *DataSource) convertToTableScan(prop *property.PhysicalProperty, candid
 		rowCount = math.Min(prop.ExpectedCnt/selectivity, rowCount)
 	}
 	ts.stats = property.NewSimpleStats(rowCount)
-	ts.stats.UsePseudoStats = ds.statisticTable.Pseudo
+	ts.stats.StatsVersion = ds.statisticTable.Version
+	if ds.statisticTable.Pseudo {
+		ts.stats.StatsVersion = statistics.PseudoVersion
+	}
+
 	copTask.cst = rowCount * scanFactor
 	if candidate.isMatchProp {
 		if prop.Desc {

planner/core/physical_plans.go

@@ -374,3 +374,26 @@ type PhysicalTableDual struct {
 
 	RowCount int
 }
+
+// CollectPlanStatsVersion uses to collect the statistics version of the plan.
+func CollectPlanStatsVersion(plan PhysicalPlan, statsInfos map[string]uint64) map[string]uint64 {
+	for _, child := range plan.Children() {
+		statsInfos = CollectPlanStatsVersion(child, statsInfos)
+	}
+	switch copPlan := plan.(type) {
+	case *PhysicalTableReader:
+		statsInfos = CollectPlanStatsVersion(copPlan.tablePlan, statsInfos)
+	case *PhysicalIndexReader:
+		statsInfos = CollectPlanStatsVersion(copPlan.indexPlan, statsInfos)
+	case *PhysicalIndexLookUpReader:
+		// For index loop up, only the indexPlan is necessary,
+		// because they use the same stats and we do not set the stats info for tablePlan.
+		statsInfos = CollectPlanStatsVersion(copPlan.indexPlan, statsInfos)
+	case *PhysicalIndexScan:
+		statsInfos[copPlan.Table.Name.O] = copPlan.stats.StatsVersion
+	case *PhysicalTableScan:
+		statsInfos[copPlan.Table.Name.O] = copPlan.stats.StatsVersion
+	}
+
+	return statsInfos
+}

planner/core/stats.go

@@ -20,6 +20,7 @@ import (
 	"github.com/pingcap/errors"
 	"github.com/pingcap/tidb/expression"
 	"github.com/pingcap/tidb/planner/property"
+	"github.com/pingcap/tidb/statistics"
 	"github.com/pingcap/tidb/util/logutil"
 	"go.uber.org/zap"
 )
@@ -77,11 +78,15 @@ func (ds *DataSource) getColumnNDV(colID int64) (ndv float64) {
 
 func (ds *DataSource) getStatsByFilter(conds expression.CNFExprs) *property.StatsInfo {
 	profile := &property.StatsInfo{
-		RowCount:       float64(ds.statisticTable.Count),
-		Cardinality:    make([]float64, len(ds.Columns)),
-		HistColl:       ds.statisticTable.GenerateHistCollFromColumnInfo(ds.Columns, ds.schema.Columns),
-		UsePseudoStats: ds.statisticTable.Pseudo,
+		RowCount:     float64(ds.statisticTable.Count),
+		Cardinality:  make([]float64, len(ds.Columns)),
+		HistColl:     ds.statisticTable.GenerateHistCollFromColumnInfo(ds.Columns, ds.schema.Columns),
+		StatsVersion: ds.statisticTable.Version,
 	}
+	if ds.statisticTable.Pseudo {
+		profile.StatsVersion = statistics.PseudoVersion
+	}
+
 	for i, col := range ds.Columns {
 		profile.Cardinality[i] = ds.getColumnNDV(col.ID)
 	}

planner/property/stats_info.go

@@ -24,10 +24,10 @@ type StatsInfo struct {
 	RowCount    float64
 	Cardinality []float64
 
-	HistColl statistics.HistColl
-	// UsePseudoStats indicates whether the StatsInfo is calculated using the
-	// pseudo statistics on a table.
-	UsePseudoStats bool
+	HistColl *statistics.HistColl
+	// StatsVersion indicates the statistics version of a table.
+	// If the StatsInfo is calculated using the pseudo statistics on a table, StatsVersion will be PseudoVersion.
+	StatsVersion uint64
 }
 
 // NewSimpleStats creates a simple StatsInfo with rowCount.
@@ -48,10 +48,10 @@ func (s *StatsInfo) Count() int64 {
 // Scale receives a selectivity and multiplies it with RowCount and Cardinality.
 func (s *StatsInfo) Scale(factor float64) *StatsInfo {
 	profile := &StatsInfo{
-		RowCount:       s.RowCount * factor,
-		Cardinality:    make([]float64, len(s.Cardinality)),
-		HistColl:       s.HistColl,
-		UsePseudoStats: s.UsePseudoStats,
+		RowCount:     s.RowCount * factor,
+		Cardinality:  make([]float64, len(s.Cardinality)),
+		HistColl:     s.HistColl,
+		StatsVersion: s.StatsVersion,
 	}
 	for i := range profile.Cardinality {
 		profile.Cardinality[i] = s.Cardinality[i] * factor