diff --git a/config/config_test.go b/config/config_test.go index 3d6e49d4f2030..df2f6785f37d8 100644 --- a/config/config_test.go +++ b/config/config_test.go @@ -115,7 +115,7 @@ max-sql-length=1024 // Make sure the example config is the same as default config. c.Assert(conf, DeepEquals, GetGlobalConfig()) - // Test for lof config. + // Test for log config. c.Assert(conf.Log.ToLogConfig(), DeepEquals, logutil.NewLogConfig("info", "text", "tidb-slow.log", conf.Log.File, false)) // Test for tracing config. diff --git a/executor/adapter.go b/executor/adapter.go index aac68603173ff..deeb613267f6f 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -198,11 +198,6 @@ func (a *ExecStmt) IsReadOnly(vars *variable.SessionVars) bool { // RebuildPlan rebuilds current execute statement plan. // It returns the current information schema version that 'a' is using. func (a *ExecStmt) RebuildPlan(ctx context.Context) (int64, error) { - startTime := time.Now() - defer func() { - a.Ctx.GetSessionVars().DurationCompile = time.Since(startTime) - }() - is := GetInfoSchema(a.Ctx) a.InfoSchema = is if err := plannercore.Preprocess(a.Ctx, a.StmtNode, is, plannercore.InTxnRetry); err != nil { @@ -543,9 +538,6 @@ func (a *ExecStmt) handlePessimisticLockError(ctx context.Context, err error) (E // Rollback the statement change before retry it. a.Ctx.StmtRollback() a.Ctx.GetSessionVars().StmtCtx.ResetForRetry() - a.Ctx.GetSessionVars().StartTime = time.Now() - a.Ctx.GetSessionVars().DurationCompile = time.Duration(0) - a.Ctx.GetSessionVars().DurationParse = time.Duration(0) if err = e.Open(ctx); err != nil { return nil, err @@ -675,7 +667,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) { sessVars := a.Ctx.GetSessionVars() level := log.GetLevel() cfg := config.GetGlobalConfig() - costTime := time.Since(a.Ctx.GetSessionVars().StartTime) + costTime := time.Since(sessVars.StartTime) + sessVars.DurationParse threshold := time.Duration(atomic.LoadUint64(&cfg.Log.SlowThreshold)) * time.Millisecond if costTime < threshold && level > zapcore.DebugLevel { return @@ -684,10 +676,10 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) { var tableIDs, indexNames string if len(sessVars.StmtCtx.TableIDs) > 0 { - tableIDs = strings.Replace(fmt.Sprintf("%v", a.Ctx.GetSessionVars().StmtCtx.TableIDs), " ", ",", -1) + tableIDs = strings.Replace(fmt.Sprintf("%v", sessVars.StmtCtx.TableIDs), " ", ",", -1) } if len(sessVars.StmtCtx.IndexNames) > 0 { - indexNames = strings.Replace(fmt.Sprintf("%v", a.Ctx.GetSessionVars().StmtCtx.IndexNames), " ", ",", -1) + indexNames = strings.Replace(fmt.Sprintf("%v", sessVars.StmtCtx.IndexNames), " ", ",", -1) } execDetail := sessVars.StmtCtx.GetExecDetails() copTaskInfo := sessVars.StmtCtx.CopTasksDetails() @@ -699,8 +691,8 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) { SQL: sql.String(), Digest: digest, TimeTotal: costTime, - TimeParse: a.Ctx.GetSessionVars().DurationParse, - TimeCompile: a.Ctx.GetSessionVars().DurationCompile, + TimeParse: sessVars.DurationParse, + TimeCompile: sessVars.DurationCompile, IndexNames: indexNames, StatsInfos: statsInfos, CopTasks: copTaskInfo, @@ -728,7 +720,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) { domain.GetDomain(a.Ctx).LogSlowQuery(&domain.SlowQueryInfo{ SQL: sql.String(), Digest: digest, - Start: a.Ctx.GetSessionVars().StartTime, + Start: sessVars.StartTime, Duration: costTime, Detail: sessVars.StmtCtx.GetExecDetails(), Succ: succ, diff --git a/session/session.go b/session/session.go index 2c5b952e745e6..379563a99052d 100644 --- a/session/session.go +++ b/session/session.go @@ -610,9 +610,6 @@ func (s *session) retry(ctx context.Context, maxCnt uint) (err error) { for i, sr := range nh.history { st := sr.st s.sessionVars.StmtCtx = sr.stmtCtx - s.sessionVars.StartTime = time.Now() - s.sessionVars.DurationCompile = time.Duration(0) - s.sessionVars.DurationParse = time.Duration(0) s.sessionVars.StmtCtx.ResetForRetry() s.sessionVars.PreparedParams = s.sessionVars.PreparedParams[:0] schemaVersion, err = st.RebuildPlan(ctx) @@ -1028,8 +1025,7 @@ func (s *session) execute(ctx context.Context, sql string) (recordSets []sqlexec charsetInfo, collation := s.sessionVars.GetCharsetInfo() // Step1: Compile query string to abstract syntax trees(ASTs). - startTS := time.Now() - s.GetSessionVars().StartTime = startTS + parseStartTime := time.Now() stmtNodes, warns, err := s.ParseSQL(ctx, sql, charsetInfo, collation) if err != nil { s.rollbackOnError(ctx) @@ -1038,7 +1034,7 @@ func (s *session) execute(ctx context.Context, sql string) (recordSets []sqlexec zap.String("sql", sql)) return nil, util.SyntaxError(err) } - durParse := time.Since(startTS) + durParse := time.Since(parseStartTime) s.GetSessionVars().DurationParse = durParse isInternal := s.isInternal() if isInternal { @@ -1051,10 +1047,10 @@ func (s *session) execute(ctx context.Context, sql string) (recordSets []sqlexec compiler := executor.Compiler{Ctx: s} multiQuery := len(stmtNodes) > 1 for idx, stmtNode := range stmtNodes { + s.sessionVars.StartTime = time.Now() s.PrepareTxnCtx(ctx) // Step2: Transform abstract syntax tree to a physical plan(stored in executor.ExecStmt). - startTS = time.Now() // Some executions are done in compile stage, so we reset them before compile. if err := executor.ResetContextOfStmt(s, stmtNode); err != nil { return nil, err @@ -1078,7 +1074,7 @@ func (s *session) execute(ctx context.Context, sql string) (recordSets []sqlexec } s.handleInvalidBindRecord(ctx, stmtNode) } - durCompile := time.Since(startTS) + durCompile := time.Since(s.sessionVars.StartTime) s.GetSessionVars().DurationCompile = durCompile if isInternal { sessionExecuteCompileDurationInternal.Observe(durCompile.Seconds())