diff --git a/domain/topn_slow_query.go b/domain/topn_slow_query.go index ee81c18c9a98b..ce1da7b885ede 100644 --- a/domain/topn_slow_query.go +++ b/domain/topn_slow_query.go @@ -225,4 +225,5 @@ type SlowQueryInfo struct { TableIDs string IndexIDs string Internal bool + Digest string } diff --git a/executor/adapter.go b/executor/adapter.go index 0c19f0410a3d7..7d44ee61233f9 100644 --- a/executor/adapter.go +++ b/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(), diff --git a/executor/executor.go b/executor/executor.go index 8654ee7d43273..8d1d1493114a3 100644 --- a/executor/executor.go +++ b/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,10 @@ func ResetContextOfStmt(ctx sessionctx.Context, s ast.StmtNode) (err error) { if err != nil { return errors.Trace(err) } + if s != nil { + // execute missed stmtID uses empty sql + sc.OriginalSQL = s.Text() + } vars.StmtCtx = sc return } diff --git a/executor/prepared.go b/executor/prepared.go index d720812ee494f..2cd16a05c4d8b 100644 --- a/executor/prepared.go +++ b/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 } diff --git a/infoschema/slow_log.go b/infoschema/slow_log.go index 292a7f02314a4..ea8ab80fa9183 100644 --- a/infoschema/slow_log.go +++ b/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 } diff --git a/infoschema/slow_log_test.go b/infoschema/slow_log_test.go index 462b684692f85..00f5228ac5d70 100644 --- a/infoschema/slow_log_test.go +++ b/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) } diff --git a/infoschema/tables_test.go b/infoschema/tables_test.go index 7a32c9789142d..6f8c15f0aaa69 100644 --- a/infoschema/tables_test.go +++ b/infoschema/tables_test.go @@ -256,6 +256,7 @@ 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) @@ -263,8 +264,8 @@ select * from t_slim;`)) 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;")) } diff --git a/planner/core/planbuilder.go b/planner/core/planbuilder.go index 41cdfc5a3b880..f32e26239cac2 100644 --- a/planner/core/planbuilder.go +++ b/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 } diff --git a/sessionctx/stmtctx/stmtctx.go b/sessionctx/stmtctx/stmtctx.go index ab308f7a8d1dd..e999a2921b6fe 100644 --- a/sessionctx/stmtctx/stmtctx.go +++ b/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. diff --git a/sessionctx/variable/session.go b/sessionctx/variable/session.go index aa322eaf04656..c1218dcdfffdf 100644 --- a/sessionctx/variable/session.go +++ b/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 = ";" } diff --git a/sessionctx/variable/session_test.go b/sessionctx/variable/session_test.go index 35520ff6fd7c3..9421bcbd84736 100644 --- a/sessionctx/variable/session_test.go +++ b/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) }