From 994e14e2e71ba16085c4e24d09d708a282beac18 Mon Sep 17 00:00:00 2001 From: Jack Yu Date: Tue, 3 Sep 2019 21:39:35 +0800 Subject: [PATCH] *: record previous statement when commit is slow (#11908) --- executor/adapter.go | 67 ++++++++++++++++------------------ infoschema/slow_log.go | 25 ++++++++----- infoschema/slow_log_test.go | 3 +- infoschema/tables_test.go | 5 ++- session/tidb.go | 1 + sessionctx/variable/session.go | 15 +++++++- 6 files changed, 68 insertions(+), 48 deletions(-) diff --git a/executor/adapter.go b/executor/adapter.go index 9c51e4b729017..5c4fabb5b6244 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -177,6 +177,7 @@ func (a *recordSet) NewChunk() *chunk.Chunk { func (a *recordSet) Close() error { err := a.executor.Close() a.stmt.LogSlowQuery(a.txnStartTS, a.lastErr == nil) + a.stmt.Ctx.GetSessionVars().PrevStmt = a.stmt.OriginText() a.stmt.logAudit() return err } @@ -682,6 +683,16 @@ func (a *ExecStmt) logAudit() { } } +// FormatSQL is used to format the original SQL, e.g. truncating long SQL, appending prepared arguments. +func FormatSQL(sql string, sessVars *variable.SessionVars) string { + cfg := config.GetGlobalConfig() + length := len(sql) + if maxQueryLen := atomic.LoadUint64(&cfg.Log.QueryLogMaxLen); uint64(length) > maxQueryLen { + sql = fmt.Sprintf("%.*q(len:%d)", maxQueryLen, sql, length) + } + return QueryReplacer.Replace(sql) + sessVars.GetExecuteArgumentsInfo() +} + // LogSlowQuery is used to print the slow query in the log files. func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) { sessVars := a.Ctx.GetSessionVars() @@ -695,11 +706,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) { if costTime < threshold && level > zapcore.DebugLevel { return } - sql := a.Text - if maxQueryLen := atomic.LoadUint64(&cfg.Log.QueryLogMaxLen); uint64(len(sql)) > maxQueryLen { - sql = fmt.Sprintf("%.*q(len:%d)", maxQueryLen, sql, len(a.Text)) - } - sql = QueryReplacer.Replace(sql) + sessVars.GetExecuteArgumentsInfo() + sql := FormatSQL(a.Text, sessVars) var tableIDs, indexNames string if len(sessVars.StmtCtx.TableIDs) > 0 { @@ -712,38 +719,28 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) { copTaskInfo := sessVars.StmtCtx.CopTasksDetails() statsInfos := plannercore.GetStatsInfo(a.Plan) memMax := sessVars.StmtCtx.MemTracker.MaxConsumed() + _, digest := sessVars.StmtCtx.SQLDigest() + slowItems := &variable.SlowQueryLogItems{ + TxnTS: txnTS, + SQL: sql, + Digest: digest, + TimeTotal: costTime, + TimeParse: a.Ctx.GetSessionVars().DurationParse, + TimeCompile: a.Ctx.GetSessionVars().DurationCompile, + IndexNames: indexNames, + StatsInfos: statsInfos, + CopTasks: copTaskInfo, + ExecDetail: execDetail, + MemMax: memMax, + Succ: succ, + } + if _, ok := a.StmtNode.(*ast.CommitStmt); ok { + slowItems.PrevStmt = FormatSQL(sessVars.PrevStmt, sessVars) + } if costTime < threshold { - _, digest := sessVars.StmtCtx.SQLDigest() - logutil.SlowQueryLogger.Debug(sessVars.SlowLogFormat(&variable.SlowQueryLogItems{ - TxnTS: txnTS, - SQL: sql, - Digest: digest, - TimeTotal: costTime, - TimeParse: a.Ctx.GetSessionVars().DurationParse, - TimeCompile: a.Ctx.GetSessionVars().DurationCompile, - IndexNames: indexNames, - StatsInfos: statsInfos, - CopTasks: copTaskInfo, - ExecDetail: execDetail, - MemMax: memMax, - Succ: succ, - })) + logutil.SlowQueryLogger.Debug(sessVars.SlowLogFormat(slowItems)) } else { - _, digest := sessVars.StmtCtx.SQLDigest() - logutil.SlowQueryLogger.Warn(sessVars.SlowLogFormat(&variable.SlowQueryLogItems{ - TxnTS: txnTS, - SQL: sql, - Digest: digest, - TimeTotal: costTime, - TimeParse: a.Ctx.GetSessionVars().DurationParse, - TimeCompile: a.Ctx.GetSessionVars().DurationCompile, - IndexNames: indexNames, - StatsInfos: statsInfos, - CopTasks: copTaskInfo, - ExecDetail: execDetail, - MemMax: memMax, - Succ: succ, - })) + logutil.SlowQueryLogger.Warn(sessVars.SlowLogFormat(slowItems)) metrics.TotalQueryProcHistogram.Observe(costTime.Seconds()) metrics.TotalCopProcHistogram.Observe(execDetail.ProcessTime.Seconds()) metrics.TotalCopWaitHistogram.Observe(execDetail.WaitTime.Seconds()) diff --git a/infoschema/slow_log.go b/infoschema/slow_log.go index 3096bfb72546d..a47c219950cfc 100644 --- a/infoschema/slow_log.go +++ b/infoschema/slow_log.go @@ -60,6 +60,7 @@ var slowQueryCols = []columnInfo{ {variable.SlowLogCopWaitAddr, mysql.TypeVarchar, 64, 0, nil, nil}, {variable.SlowLogMemMax, mysql.TypeLonglong, 20, 0, nil, nil}, {variable.SlowLogSucc, mysql.TypeTiny, 1, 0, nil, nil}, + {variable.SlowLogPrevStmt, mysql.TypeLongBlob, types.UnspecifiedLength, 0, nil, nil}, {variable.SlowLogQuerySQLStr, mysql.TypeLongBlob, types.UnspecifiedLength, 0, nil, nil}, } @@ -112,15 +113,19 @@ func ParseSlowLog(tz *time.Location, reader *bufio.Reader) ([][]types.Datum, err // Parse slow log field. if strings.HasPrefix(line, variable.SlowLogRowPrefixStr) { line = line[len(variable.SlowLogRowPrefixStr):] - fieldValues := strings.Split(line, " ") - for i := 0; i < len(fieldValues)-1; i += 2 { - field := fieldValues[i] - if strings.HasSuffix(field, ":") { - field = field[:len(field)-1] - } - err = st.setFieldValue(tz, field, fieldValues[i+1]) - if err != nil { - return rows, err + if strings.HasPrefix(line, variable.SlowLogPrevStmtPrefix) { + st.prevStmt = line[len(variable.SlowLogPrevStmtPrefix):] + } else { + fieldValues := strings.Split(line, " ") + for i := 0; i < len(fieldValues)-1; i += 2 { + field := fieldValues[i] + if strings.HasSuffix(field, ":") { + field = field[:len(field)-1] + } + err = st.setFieldValue(tz, field, fieldValues[i+1]) + if err != nil { + return rows, err + } } } } else if strings.HasSuffix(line, variable.SlowLogSQLSuffixStr) { @@ -195,6 +200,7 @@ type slowQueryTuple struct { maxWaitTime float64 maxWaitAddress string memMax int64 + prevStmt string sql string isInternal bool succ bool @@ -313,6 +319,7 @@ func (st *slowQueryTuple) convertToDatumRow() []types.Datum { } else { record = append(record, types.NewIntDatum(0)) } + record = append(record, types.NewStringDatum(st.prevStmt)) record = append(record, types.NewStringDatum(st.sql)) return record } diff --git a/infoschema/slow_log_test.go b/infoschema/slow_log_test.go index ff790ee42b475..efb0d02f700fb 100644 --- a/infoschema/slow_log_test.go +++ b/infoschema/slow_log_test.go @@ -38,6 +38,7 @@ func (s *testSuite) TestParseSlowLogFile(c *C) { # Cop_wait_avg: 0.05 Cop_wait_p90: 0.6 Cop_wait_max: 0.8 Cop_wait_addr: 0.0.0.0:20160 # Mem_max: 70724 # Succ: false +# Prev_stmt: update t set i = 1; select * from t;`) reader := bufio.NewReader(slowLog) loc, err := time.LoadLocation("Asia/Shanghai") @@ -54,7 +55,7 @@ select * from t;`) } recordString += str } - expectRecordString := "2019-04-28 15:24:04.309074,405888132465033227,,,0,0.216905,0.021,0,0,1,637,0,,,1,42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772,t1:1,t2:2,0.1,0.2,0.03,127.0.0.1:20160,0.05,0.6,0.8,0.0.0.0:20160,70724,0,select * from t;" + expectRecordString := "2019-04-28 15:24:04.309074,405888132465033227,,,0,0.216905,0.021,0,0,1,637,0,,,1,42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772,t1:1,t2:2,0.1,0.2,0.03,127.0.0.1:20160,0.05,0.6,0.8,0.0.0.0:20160,70724,0,update t set i = 1;,select * from t;" c.Assert(expectRecordString, Equals, recordString) // fix sql contain '# ' bug diff --git a/infoschema/tables_test.go b/infoschema/tables_test.go index 020cfd5c80551..ceaa7aa20fcc0 100644 --- a/infoschema/tables_test.go +++ b/infoschema/tables_test.go @@ -466,6 +466,7 @@ func (s *testTableSuite) TestSlowQuery(c *C) { # Cop_wait_avg: 0.05 Cop_wait_p90: 0.6 Cop_wait_max: 0.8 Cop_wait_addr: 0.0.0.0:20160 # Mem_max: 70724 # Succ: true +# Prev_stmt: update t set i = 2; select * from t_slim;`)) c.Assert(f.Sync(), IsNil) c.Assert(err, IsNil) @@ -474,10 +475,10 @@ select * from t_slim;`)) 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.101|0.092|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|0.1|0.2|0.03|127.0.0.1:20160|0.05|0.6|0.8|0.0.0.0:20160|70724|1|select * from t_slim;")) + "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|0.1|0.2|0.03|127.0.0.1:20160|0.05|0.6|0.8|0.0.0.0:20160|70724|1|update t set i = 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.101|0.092|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|0.1|0.2|0.03|127.0.0.1:20160|0.05|0.6|0.8|0.0.0.0:20160|70724|1|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|0.1|0.2|0.03|127.0.0.1:20160|0.05|0.6|0.8|0.0.0.0:20160|70724|1|update t set i = 2;|select * from t_slim;")) // Test for long query. _, err = f.Write([]byte(` diff --git a/session/tidb.go b/session/tidb.go index fce6c77cfff78..24b227e827821 100644 --- a/session/tidb.go +++ b/session/tidb.go @@ -218,6 +218,7 @@ func runStmt(ctx context.Context, sctx sessionctx.Context, s sqlexec.Statement) // then it could include the transaction commit time. if rs == nil { s.(*executor.ExecStmt).LogSlowQuery(origTxnCtx.StartTS, err == nil) + sessVars.PrevStmt = s.OriginText() } }() diff --git a/sessionctx/variable/session.go b/sessionctx/variable/session.go index 0d90099f1523c..f31e4db9ea215 100644 --- a/sessionctx/variable/session.go +++ b/sessionctx/variable/session.go @@ -409,11 +409,14 @@ type SessionVars struct { // StartTime is the start time of the last query. StartTime time.Time - // DurationParse is the duration of pasing SQL string to AST of the last query. + // DurationParse is the duration of parsing SQL string to AST of the last query. DurationParse time.Duration // DurationCompile is the duration of compiling AST to execution plan of the last query. DurationCompile time.Duration + + // PrevStmt is used to store the previous executed statement in the current session. + PrevStmt string } // ConnectionInfo present connection used by audit. @@ -1046,6 +1049,10 @@ const ( SlowLogMemMax = "Mem_max" // SlowLogSucc is used to indicate whether this sql execute successfully. SlowLogSucc = "Succ" + // SlowLogPrevStmt is used to show the previous executed statement. + SlowLogPrevStmt = "Prev_stmt" + // SlowLogPrevStmtPrefix is the prefix of Prev_stmt in slow log file. + SlowLogPrevStmtPrefix = SlowLogPrevStmt + SlowLogSpaceMarkStr ) // SlowQueryLogItems is a collection of items that should be included in the @@ -1063,6 +1070,7 @@ type SlowQueryLogItems struct { ExecDetail execdetails.ExecDetails MemMax int64 Succ bool + PrevStmt string } // SlowLogFormat uses for formatting slow log. @@ -1083,6 +1091,7 @@ type SlowQueryLogItems struct { // # Cop_wait: Avg_time: 10ms P90_time: 20ms Max_time: 30ms Max_Addr: 10.6.131.79 // # Memory_max: 4096 // # Succ: true +// # Prev_stmt: begin; // select * from t_slim; func (s *SessionVars) SlowLogFormat(logItems *SlowQueryLogItems) string { var buf bytes.Buffer @@ -1150,6 +1159,10 @@ func (s *SessionVars) SlowLogFormat(logItems *SlowQueryLogItems) string { writeSlowLogItem(&buf, SlowLogSucc, strconv.FormatBool(logItems.Succ)) + if logItems.PrevStmt != "" { + writeSlowLogItem(&buf, SlowLogPrevStmt, logItems.PrevStmt) + } + buf.WriteString(logItems.SQL) if len(logItems.SQL) == 0 || logItems.SQL[len(logItems.SQL)-1] != ';' { buf.WriteString(";")