diff --git a/executor/adapter.go b/executor/adapter.go index d11b4611b5b8f..b37c85e5c86fa 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -36,10 +36,12 @@ import ( "github.com/pingcap/tidb/plugin" "github.com/pingcap/tidb/sessionctx" "github.com/pingcap/tidb/sessionctx/variable" + "github.com/pingcap/tidb/types" "github.com/pingcap/tidb/util/chunk" "github.com/pingcap/tidb/util/logutil" "github.com/pingcap/tidb/util/memory" "github.com/pingcap/tidb/util/sqlexec" + "github.com/pingcap/tidb/util/stringutil" "go.uber.org/zap" "go.uber.org/zap/zapcore" "golang.org/x/net/context" @@ -125,7 +127,8 @@ func (a *recordSet) Close() error { err := a.executor.Close() a.stmt.LogSlowQuery(a.txnStartTS, a.lastErr == nil) sessVars := a.stmt.Ctx.GetSessionVars() - sessVars.PrevStmt = FormatSQL(a.stmt.OriginText(), sessVars) + pps := types.CopyRow(sessVars.PreparedParams) + sessVars.PrevStmt = FormatSQL(a.stmt.OriginText(), pps) a.stmt.logAudit() return errors.Trace(err) } @@ -396,17 +399,20 @@ 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) +func FormatSQL(sql string, pps variable.PreparedParams) stringutil.StringerFunc { + return func() 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) + pps.String() } - 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() level := log.GetLevel() cfg := config.GetGlobalConfig() costTime := time.Since(a.Ctx.GetSessionVars().StartTime) @@ -414,8 +420,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) { if costTime < threshold && level > zapcore.DebugLevel { return } - sessVars := a.Ctx.GetSessionVars() - sql := FormatSQL(a.Text, sessVars) + sql := FormatSQL(a.Text, sessVars.PreparedParams) var tableIDs, indexNames string if len(sessVars.StmtCtx.TableIDs) > 0 { @@ -431,7 +436,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) { _, digest := sessVars.StmtCtx.SQLDigest() slowItems := &variable.SlowQueryLogItems{ TxnTS: txnTS, - SQL: sql, + SQL: sql.String(), Digest: digest, TimeTotal: costTime, TimeParse: a.Ctx.GetSessionVars().DurationParse, @@ -444,7 +449,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) { Succ: succ, } if _, ok := a.StmtNode.(*ast.CommitStmt); ok { - slowItems.PrevStmt = sessVars.PrevStmt + slowItems.PrevStmt = sessVars.PrevStmt.String() } if costTime < threshold { logutil.SlowQueryLogger.Debug(sessVars.SlowLogFormat(slowItems)) @@ -458,7 +463,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) { userString = sessVars.User.String() } domain.GetDomain(a.Ctx).LogSlowQuery(&domain.SlowQueryInfo{ - SQL: sql, + SQL: sql.String(), Digest: digest, Start: a.Ctx.GetSessionVars().StartTime, Duration: costTime, diff --git a/server/conn_stmt.go b/server/conn_stmt.go index 1c09932dca8f2..06f22837b724c 100644 --- a/server/conn_stmt.go +++ b/server/conn_stmt.go @@ -569,7 +569,7 @@ func (cc *clientConn) handleSetOption(data []byte) (err error) { func (cc *clientConn) preparedStmt2String(stmtID uint32) string { sv := cc.ctx.GetSessionVars() if prepared, ok := sv.PreparedStmts[stmtID]; ok { - return prepared.Stmt.Text() + sv.GetExecuteArgumentsInfo() + return prepared.Stmt.Text() + sv.PreparedParams.String() } return fmt.Sprintf("prepared statement not found, ID: %d", stmtID) } diff --git a/session/session.go b/session/session.go index 3c2be3cd66cdb..7d8a78e126c7d 100644 --- a/session/session.go +++ b/session/session.go @@ -536,7 +536,7 @@ func (s *session) retry(ctx context.Context, maxCnt uint) (err error) { zap.Int64("schemaVersion", schemaVersion), zap.Uint("retryCnt", retryCnt), zap.Int("queryNum", i), - zap.String("sql", sqlForLog(st.OriginText())+sessVars.GetExecuteArgumentsInfo())) + zap.String("sql", sqlForLog(st.OriginText())+sessVars.PreparedParams.String())) } else { logutil.Logger(ctx).Warn("retrying", zap.Int64("schemaVersion", schemaVersion), @@ -1601,6 +1601,6 @@ func logQuery(query string, vars *variable.SessionVars) { zap.Int64("schemaVersion", vars.TxnCtx.SchemaVersion), zap.Uint64("txnStartTS", vars.TxnCtx.StartTS), zap.String("current_db", vars.CurrentDB), - zap.String("sql", query+vars.GetExecuteArgumentsInfo())) + zap.String("sql", query+vars.PreparedParams.String())) } } diff --git a/session/tidb.go b/session/tidb.go index 79448f8a99be0..8815122abc910 100644 --- a/session/tidb.go +++ b/session/tidb.go @@ -34,6 +34,7 @@ import ( "github.com/pingcap/tidb/kv" "github.com/pingcap/tidb/sessionctx" "github.com/pingcap/tidb/sessionctx/variable" + "github.com/pingcap/tidb/types" "github.com/pingcap/tidb/util" "github.com/pingcap/tidb/util/chunk" "github.com/pingcap/tidb/util/logutil" @@ -204,7 +205,8 @@ 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 = executor.FormatSQL(s.OriginText(), sessVars) + pps := types.CopyRow(sessVars.PreparedParams) + sessVars.PrevStmt = executor.FormatSQL(s.OriginText(), pps) } }() diff --git a/sessionctx/variable/session.go b/sessionctx/variable/session.go index 22058fc80486a..05d896de2b1cc 100644 --- a/sessionctx/variable/session.go +++ b/sessionctx/variable/session.go @@ -187,7 +187,7 @@ type SessionVars struct { // preparedStmtID is id of prepared statement. preparedStmtID uint32 // PreparedParams params for prepared statements - PreparedParams []types.Datum + PreparedParams PreparedParams // retry information RetryInfo *RetryInfo @@ -350,7 +350,17 @@ type SessionVars struct { DurationCompile time.Duration // PrevStmt is used to store the previous executed statement in the current session. - PrevStmt string + PrevStmt fmt.Stringer +} + +// PreparedParams contains the parameters of the current prepared statement when executing it. +type PreparedParams []types.Datum + +func (pps PreparedParams) String() string { + if len(pps) == 0 { + return "" + } + return " [arguments: " + types.DatumsToStrNoErr(pps) + "]" } // ConnectionInfo present connection used by audit. @@ -520,26 +530,6 @@ func (s *SessionVars) Location() *time.Location { return loc } -// GetExecuteArgumentsInfo gets the argument list as a string of execute statement. -func (s *SessionVars) GetExecuteArgumentsInfo() string { - if len(s.PreparedParams) == 0 { - return "" - } - args := make([]string, 0, len(s.PreparedParams)) - for _, v := range s.PreparedParams { - if v.IsNull() { - args = append(args, "") - } else { - str, err := v.ToString() - if err != nil { - terror.Log(err) - } - args = append(args, str) - } - } - return fmt.Sprintf(" [arguments: %s]", strings.Join(args, ", ")) -} - // GetSystemVar gets the string value of a system variable. func (s *SessionVars) GetSystemVar(name string) (string, bool) { val, ok := s.systems[name] diff --git a/util/stringutil/string_util.go b/util/stringutil/string_util.go index 4bdf43fda7e14..c081806ba4047 100644 --- a/util/stringutil/string_util.go +++ b/util/stringutil/string_util.go @@ -14,6 +14,7 @@ package stringutil import ( + "fmt" "strings" "unicode/utf8" @@ -240,3 +241,27 @@ func DoMatch(str string, patChars, patTypes []byte) bool { func Copy(src string) string { return string(hack.Slice(src)) } + +// StringerFunc defines string func implement fmt.Stringer. +type StringerFunc func() string + +// String implements fmt.Stringer +func (l StringerFunc) String() string { + return l() +} + +// MemoizeStr returns memoized version of stringFunc. +func MemoizeStr(l func() string) fmt.Stringer { + return StringerFunc(func() string { + return l() + }) +} + +// StringerStr defines a alias to normal string. +// implement fmt.Stringer +type StringerStr string + +// String implements fmt.Stringer +func (i StringerStr) String() string { + return string(i) +}