*: wrap the previous statement for performance (pingcap#12283) (pingc…

…ap#12751)

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,26 +399,28 @@ 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)
 	threshold := time.Duration(atomic.LoadUint64(&cfg.Log.SlowThreshold)) * time.Millisecond
 	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,

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)
 }

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()))
 	}
 }

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)
 		}
 	}()
 

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, "<nil>")
-		} 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]

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)
+}