log: generate digest and log it in slow log

domain/topn_slow_query.go

@@ -225,4 +225,5 @@ type SlowQueryInfo struct {
 	TableIDs string
 	IndexIDs string
 	Internal bool
+	Digest   string
 }

executor/adapter.go

@@ -388,9 +388,13 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) {
 	}
 	execDetail := sessVars.StmtCtx.GetExecDetails()
 	if costTime < threshold {
-		logutil.SlowQueryLogger.Debugf(sessVars.SlowLogFormat(txnTS, costTime, execDetail, indexIDs, sql))
+		if logutil.SlowQueryLogger.IsLevelEnabled(log.DebugLevel) {
+			_, digest := sessVars.StmtCtx.SQLDigest()
+			logutil.SlowQueryLogger.Debugf(sessVars.SlowLogFormat(txnTS, costTime, execDetail, indexIDs, digest, sql))
+		}
 	} else {
-		logutil.SlowQueryLogger.Warnf(sessVars.SlowLogFormat(txnTS, costTime, execDetail, indexIDs, sql))
+		_, digest := sessVars.StmtCtx.SQLDigest()
+		logutil.SlowQueryLogger.Warnf(sessVars.SlowLogFormat(txnTS, costTime, execDetail, indexIDs, digest, sql))
 		metrics.TotalQueryProcHistogram.Observe(costTime.Seconds())
 		metrics.TotalCopProcHistogram.Observe(execDetail.ProcessTime.Seconds())
 		metrics.TotalCopWaitHistogram.Observe(execDetail.WaitTime.Seconds())
@@ -400,6 +404,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) {
 		}
 		domain.GetDomain(a.Ctx).LogSlowQuery(&domain.SlowQueryInfo{
 			SQL:      sql,
+			Digest:   digest,
 			Start:    a.StartTime,
 			Duration: costTime,
 			Detail:   sessVars.StmtCtx.GetExecDetails(),

executor/executor.go

@@ -617,6 +617,7 @@ func (e *ShowSlowExec) Next(ctx context.Context, req *chunk.RecordBatch) error {
 		} else {
 			req.AppendInt64(11, 1)
 		}
+		req.AppendString(12, slow.Digest)
 		e.cursor++
 	}
 	return nil
@@ -1398,6 +1399,7 @@ func ResetContextOfStmt(ctx sessionctx.Context, s ast.StmtNode) (err error) {
 	if err != nil {
 		return errors.Trace(err)
 	}
+	sc.OriginalSQL = s.Text()
 	vars.StmtCtx = sc
 	return
 }

executor/prepared.go

@@ -278,6 +278,7 @@ func CompileExecutePreparedStmt(ctx sessionctx.Context, ID uint32, args ...inter
 	}
 	if prepared, ok := ctx.GetSessionVars().PreparedStmts[ID]; ok {
 		stmt.Text = prepared.Stmt.Text()
+		ctx.GetSessionVars().StmtCtx.OriginalSQL = stmt.Text
 	}
 	return stmt, nil
 }

infoschema/slow_log.go

@@ -46,6 +46,7 @@ var slowQueryCols = []columnInfo{
 	{variable.SlowLogDBStr, mysql.TypeVarchar, 64, 0, nil, nil},
 	{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.SlowLogQuerySQLStr, mysql.TypeVarchar, 4096, 0, nil, nil},
 }
 
@@ -136,6 +137,7 @@ type slowQueryTuple struct {
 	db           string
 	indexNames   string
 	isInternal   bool
+	digest       string
 	sql          string
 }
 
@@ -212,6 +214,8 @@ func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string)
 		st.indexNames = value
 	case variable.SlowLogIsInternalStr:
 		st.isInternal = value == "true"
+	case variable.SlowLogDigestStr:
+		st.digest = value
 	case variable.SlowLogQuerySQLStr:
 		st.sql = value
 	}
@@ -238,6 +242,7 @@ func (st *slowQueryTuple) convertToDatumRow() []types.Datum {
 	record = append(record, types.NewStringDatum(st.db))
 	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.sql))
 	return record
 }

infoschema/slow_log_test.go

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

infoschema/tables_test.go

@@ -256,15 +256,16 @@ func (s *testSuite) TestSlowQuery(c *C) {
 # Process_time: 0.161 Request_count: 1 Total_keys: 100001 Process_keys: 100000
 # DB: test
 # Is_internal: false
+# Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772
 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|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|0|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|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|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|0|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|select * from t_slim;"))
 }

planner/core/planbuilder.go

@@ -876,6 +876,7 @@ func buildShowSlowSchema() *expression.Schema {
 	schema.Append(buildColumn("", "TABLE_IDS", mysql.TypeVarchar, 256))
 	schema.Append(buildColumn("", "INDEX_IDS", mysql.TypeVarchar, 256))
 	schema.Append(buildColumn("", "INTERNAL", mysql.TypeTiny, tinySize))
+	schema.Append(buildColumn("", "DIGEST", mysql.TypeVarchar, 64))
 	return schema
 }
 

sessionctx/stmtctx/stmtctx.go

@@ -18,6 +18,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/pingcap/parser"
 	"github.com/pingcap/parser/mysql"
 	"github.com/pingcap/tidb/util/execdetails"
 	"github.com/pingcap/tidb/util/memory"
@@ -115,6 +116,21 @@ type StatementContext struct {
 	NowTs            time.Time
 	SysTs            time.Time
 	StmtType         string
+	OriginalSQL      string
+	digestMemo       struct {
+		sync.Once
+		normalized string
+		digest     string
+	}
+}
+
+// SQLDigest gets normalized and digest for provided sql.
+// it will cache result after first calling.
+func (sc *StatementContext) SQLDigest() (normalized, sqlDigest string) {
+	sc.digestMemo.Do(func() {
+		sc.digestMemo.normalized, sc.digestMemo.digest = parser.NormalizeDigest(sc.OriginalSQL)
+	})
+	return sc.digestMemo.normalized, sc.digestMemo.digest
 }
 
 // AddAffectedRows adds affected rows.

sessionctx/variable/session.go

@@ -839,6 +839,8 @@ const (
 	SlowLogIsInternalStr = "Is_internal"
 	// SlowLogIndexIDsStr is slow log field name.
 	SlowLogIndexIDsStr = "Index_ids"
+	// SlowLogDigestStr is slow log field name.
+	SlowLogDigestStr = "Digest"
 	// SlowLogQuerySQLStr is slow log field name.
 	SlowLogQuerySQLStr = "Query" // use for slow log table, slow log will not print this field name but print sql directly.
 )
@@ -855,7 +857,7 @@ const (
 // # Index_ids: [1,2]
 // # Is_internal: false
 // select * from t_slim;
-func (s *SessionVars) SlowLogFormat(txnTS uint64, costTime time.Duration, execDetail execdetails.ExecDetails, indexIDs string, sql string) string {
+func (s *SessionVars) SlowLogFormat(txnTS uint64, costTime time.Duration, execDetail execdetails.ExecDetails, indexIDs string, digest, sql string) string {
 	var buf bytes.Buffer
 	execDetailStr := execDetail.String()
 	buf.WriteString(SlowLogPrefixStr + SlowLogTxnStartTSStr + SlowLogSpaceMarkStr + strconv.FormatUint(txnTS, 10) + "\n")
@@ -876,6 +878,9 @@ func (s *SessionVars) SlowLogFormat(txnTS uint64, costTime time.Duration, execDe
 		buf.WriteString(SlowLogPrefixStr + SlowLogIndexIDsStr + SlowLogSpaceMarkStr + indexIDs + "\n")
 	}
 	buf.WriteString(SlowLogPrefixStr + SlowLogIsInternalStr + SlowLogSpaceMarkStr + strconv.FormatBool(s.InRestrictedSQL) + "\n")
+	if len(digest) > 0 {
+		buf.WriteString(SlowLogPrefixStr + SlowLogDigestStr + SlowLogSpaceMarkStr + digest + "\n")
+	}
 	if len(sql) == 0 {
 		sql = ";"
 	}

sessionctx/variable/session_test.go

@@ -17,6 +17,7 @@ import (
 	"time"
 
 	. "github.com/pingcap/check"
+	"github.com/pingcap/parser"
 	"github.com/pingcap/parser/auth"
 	"github.com/pingcap/tidb/util/execdetails"
 	"github.com/pingcap/tidb/util/mock"
@@ -111,7 +112,10 @@ func (*testSessionSuite) TestSlowLogFormat(c *C) {
 # DB: test
 # Index_ids: [1,2]
 # Is_internal: true
+# Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772
 select * from t;`
-	logString := seVar.SlowLogFormat(txnTS, costTime, execDetail, "[1,2]", "select * from t")
+	sql := "select * from t"
+	digest := parser.DigestHash(sql)
+	logString := seVar.SlowLogFormat(txnTS, costTime, execDetail, "[1,2]", digest, sql)
 	c.Assert(logString, Equals, resultString)
 }