From 61c6c1635161b198f3441f0bfad33aeeb481e7e2 Mon Sep 17 00:00:00 2001 From: crazycs Date: Fri, 17 Apr 2020 21:50:28 +0800 Subject: [PATCH 1/3] cherry pick #16453 to release-4.0 Signed-off-by: sre-bot --- executor/adapter.go | 32 ++++++++++--- session/session.go | 110 ++++++++++++++++++++++++++++++++++++++++---- session/tidb.go | 7 +-- 3 files changed, 128 insertions(+), 21 deletions(-) diff --git a/executor/adapter.go b/executor/adapter.go index 0788031536cb5..c589ffb668223 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -148,12 +148,7 @@ func (a *recordSet) NewChunk() *chunk.Chunk { func (a *recordSet) Close() error { err := a.executor.Close() - // `LowSlowQuery` and `SummaryStmt` must be called before recording `PrevStmt`. - a.stmt.LogSlowQuery(a.txnStartTS, a.lastErr == nil, false) - a.stmt.SummaryStmt(a.lastErr == nil) - sessVars := a.stmt.Ctx.GetSessionVars() - pps := types.CloneRow(sessVars.PreparedParams) - sessVars.PrevStmt = FormatSQL(a.stmt.OriginText(), pps) + a.stmt.FinishExecuteStmt(a.txnStartTS, a.lastErr == nil, false) a.stmt.logAudit() // Detach the disk tracker from GlobalDiskUsageTracker after every execution if stmtCtx := a.stmt.Ctx.GetSessionVars().StmtCtx; stmtCtx != nil && stmtCtx.DiskTracker != nil { @@ -772,6 +767,31 @@ func FormatSQL(sql string, pps variable.PreparedParams) stringutil.StringerFunc } } +var ( + sessionExecuteRunDurationInternal = metrics.SessionExecuteRunDuration.WithLabelValues(metrics.LblInternal) + sessionExecuteRunDurationGeneral = metrics.SessionExecuteRunDuration.WithLabelValues(metrics.LblGeneral) +) + +// FinishExecuteStmt is used to record some information after `ExecStmt` execution finished: +// 1. record slow log if needed. +// 2. record summary statement. +// 3. record execute duration metric. +// 4. update the `PrevStmt` in session variable. +func (a *ExecStmt) FinishExecuteStmt(txnTS uint64, succ bool, hasMoreResults bool) { + // `LowSlowQuery` and `SummaryStmt` must be called before recording `PrevStmt`. + a.LogSlowQuery(txnTS, succ, hasMoreResults) + a.SummaryStmt(succ) + sessVars := a.Ctx.GetSessionVars() + pps := types.CloneRow(sessVars.PreparedParams) + sessVars.PrevStmt = FormatSQL(a.OriginText(), pps) + executeDuration := time.Since(sessVars.StartTime) - sessVars.DurationCompile + if sessVars.InRestrictedSQL { + sessionExecuteRunDurationInternal.Observe(executeDuration.Seconds()) + } else { + sessionExecuteRunDurationGeneral.Observe(executeDuration.Seconds()) + } +} + // LogSlowQuery is used to print the slow query in the log files. func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) { sessVars := a.Ctx.GetSessionVars() diff --git a/session/session.go b/session/session.go index 3e6cb905428da..8f76c581aeaa4 100644 --- a/session/session.go +++ b/session/session.go @@ -83,9 +83,6 @@ var ( transactionDurationGeneralCommit = metrics.TransactionDuration.WithLabelValues(metrics.LblGeneral, metrics.LblCommit) transactionDurationGeneralAbort = metrics.TransactionDuration.WithLabelValues(metrics.LblGeneral, metrics.LblAbort) - sessionExecuteRunDurationInternal = metrics.SessionExecuteRunDuration.WithLabelValues(metrics.LblInternal) - sessionExecuteRunDurationGeneral = metrics.SessionExecuteRunDuration.WithLabelValues(metrics.LblGeneral) - sessionExecuteCompileDurationInternal = metrics.SessionExecuteCompileDuration.WithLabelValues(metrics.LblInternal) sessionExecuteCompileDurationGeneral = metrics.SessionExecuteCompileDuration.WithLabelValues(metrics.LblGeneral) sessionExecuteParseDurationInternal = metrics.SessionExecuteParseDuration.WithLabelValues(metrics.LblInternal) @@ -1033,7 +1030,6 @@ func (s *session) SetProcessInfo(sql string, t time.Time, command byte, maxExecu func (s *session) executeStatement(ctx context.Context, connID uint64, stmtNode ast.StmtNode, stmt sqlexec.Statement, recordSets []sqlexec.RecordSet, inMulitQuery bool) ([]sqlexec.RecordSet, error) { logStmt(stmtNode, s.sessionVars) - startTime := time.Now() recordSet, err := runStmt(ctx, s, stmt) if err != nil { if !kv.ErrKeyExists.Equal(err) { @@ -1044,11 +1040,6 @@ func (s *session) executeStatement(ctx context.Context, connID uint64, stmtNode } return nil, err } - if s.isInternal() { - sessionExecuteRunDurationInternal.Observe(time.Since(startTime).Seconds()) - } else { - sessionExecuteRunDurationGeneral.Observe(time.Since(startTime).Seconds()) - } if inMulitQuery && recordSet == nil { recordSet = &multiQueryNoDelayRecordSet{ @@ -1088,6 +1079,96 @@ func (s *session) Execute(ctx context.Context, sql string) (recordSets []sqlexec return } +<<<<<<< HEAD +======= +// Parse parses a query string to raw ast.StmtNode. +func (s *session) Parse(ctx context.Context, sql string) ([]ast.StmtNode, error) { + charsetInfo, collation := s.sessionVars.GetCharsetInfo() + parseStartTime := time.Now() + stmts, warns, err := s.ParseSQL(ctx, sql, charsetInfo, collation) + if err != nil { + s.rollbackOnError(ctx) + + // Only print log message when this SQL is from the user. + // Mute the warning for internal SQLs. + if !s.sessionVars.InRestrictedSQL { + logutil.Logger(ctx).Warn("parse SQL failed", zap.Error(err), zap.String("SQL", sql)) + } + return nil, util.SyntaxError(err) + } + + durParse := time.Since(parseStartTime) + s.GetSessionVars().DurationParse = durParse + isInternal := s.isInternal() + if isInternal { + sessionExecuteParseDurationInternal.Observe(durParse.Seconds()) + } else { + sessionExecuteParseDurationGeneral.Observe(durParse.Seconds()) + } + for _, warn := range warns { + s.sessionVars.StmtCtx.AppendWarning(util.SyntaxWarn(warn)) + } + return stmts, nil +} + +func (s *session) ExecuteStmt(ctx context.Context, stmtNode ast.StmtNode) (sqlexec.RecordSet, error) { + if span := opentracing.SpanFromContext(ctx); span != nil && span.Tracer() != nil { + span1 := span.Tracer().StartSpan("session.ExecuteStmt", opentracing.ChildOf(span.Context())) + defer span1.Finish() + ctx = opentracing.ContextWithSpan(ctx, span1) + } + + s.PrepareTxnCtx(ctx) + err := s.loadCommonGlobalVariablesIfNeeded() + if err != nil { + return nil, err + } + + s.sessionVars.StartTime = 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 + } + + // Transform abstract syntax tree to a physical plan(stored in executor.ExecStmt). + compiler := executor.Compiler{Ctx: s} + stmt, err := compiler.Compile(ctx, stmtNode) + if err != nil { + s.rollbackOnError(ctx) + + // Only print log message when this SQL is from the user. + // Mute the warning for internal SQLs. + if !s.sessionVars.InRestrictedSQL { + logutil.Logger(ctx).Warn("compile SQL failed", zap.Error(err), zap.String("SQL", stmtNode.Text())) + } + return nil, err + } + durCompile := time.Since(s.sessionVars.StartTime) + s.GetSessionVars().DurationCompile = durCompile + if s.isInternal() { + sessionExecuteCompileDurationInternal.Observe(durCompile.Seconds()) + } else { + sessionExecuteCompileDurationGeneral.Observe(durCompile.Seconds()) + } + s.currentPlan = stmt.Plan + + // Execute the physical plan. + logStmt(stmtNode, s.sessionVars) + recordSet, err := runStmt(ctx, s, stmt) + if err != nil { + if !kv.ErrKeyExists.Equal(err) { + logutil.Logger(ctx).Warn("run statement failed", + zap.Int64("schemaVersion", s.sessionVars.TxnCtx.SchemaVersion), + zap.Error(err), + zap.String("session", s.String())) + } + return nil, err + } + return recordSet, nil +} + +>>>>>>> 7106b18... session: refine record execution duration metric (#16453) func (s *session) execute(ctx context.Context, sql string) (recordSets []sqlexec.RecordSet, err error) { s.PrepareTxnCtx(ctx) connID := s.sessionVars.ConnectionID @@ -1210,6 +1291,10 @@ func (s *session) CommonExec(ctx context.Context, if err != nil { return nil, err } +<<<<<<< HEAD +======= + sessionExecuteCompileDurationGeneral.Observe(time.Since(s.sessionVars.StartTime).Seconds()) +>>>>>>> 7106b18... session: refine record execution duration metric (#16453) logQuery(st.OriginText(), s.sessionVars) return runStmt(ctx, s, st) } @@ -1239,7 +1324,14 @@ func (s *session) CachedPlanExec(ctx context.Context, OutputNames: execPlan.OutputNames(), PsStmt: prepareStmt, } +<<<<<<< HEAD s.GetSessionVars().DurationCompile = time.Since(s.sessionVars.StartTime) +======= + compileDuration := time.Since(s.sessionVars.StartTime) + sessionExecuteCompileDurationGeneral.Observe(compileDuration.Seconds()) + s.GetSessionVars().DurationCompile = compileDuration + +>>>>>>> 7106b18... session: refine record execution duration metric (#16453) stmt.Text = prepared.Stmt.Text() stmtCtx.OriginalSQL = stmt.Text stmtCtx.InitSQLDigest(prepareStmt.NormalizedSQL, prepareStmt.SQLDigest) diff --git a/session/tidb.go b/session/tidb.go index 2e571549b5b8b..8e64ac197e680 100644 --- a/session/tidb.go +++ b/session/tidb.go @@ -36,7 +36,6 @@ 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" @@ -266,11 +265,7 @@ func runStmt(ctx context.Context, sctx sessionctx.Context, s sqlexec.Statement) // If it is not a select statement, we record its slow log here, // then it could include the transaction commit time. if rs == nil { - // `LowSlowQuery` and `SummaryStmt` must be called before recording `PrevStmt`. - s.(*executor.ExecStmt).LogSlowQuery(origTxnCtx.StartTS, err == nil, false) - s.(*executor.ExecStmt).SummaryStmt(err == nil) - pps := types.CloneRow(sessVars.PreparedParams) - sessVars.PrevStmt = executor.FormatSQL(s.OriginText(), pps) + s.(*executor.ExecStmt).FinishExecuteStmt(origTxnCtx.StartTS, err == nil, false) } }() From 3203b126f41aab7f58cbf3816144de3b81a62f28 Mon Sep 17 00:00:00 2001 From: crazycs520 Date: Wed, 20 May 2020 10:47:27 +0800 Subject: [PATCH 2/3] init Signed-off-by: crazycs520 --- executor/adapter.go | 32 +++---------- session/session.go | 110 ++++---------------------------------------- session/tidb.go | 7 ++- 3 files changed, 21 insertions(+), 128 deletions(-) diff --git a/executor/adapter.go b/executor/adapter.go index c589ffb668223..0788031536cb5 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -148,7 +148,12 @@ func (a *recordSet) NewChunk() *chunk.Chunk { func (a *recordSet) Close() error { err := a.executor.Close() - a.stmt.FinishExecuteStmt(a.txnStartTS, a.lastErr == nil, false) + // `LowSlowQuery` and `SummaryStmt` must be called before recording `PrevStmt`. + a.stmt.LogSlowQuery(a.txnStartTS, a.lastErr == nil, false) + a.stmt.SummaryStmt(a.lastErr == nil) + sessVars := a.stmt.Ctx.GetSessionVars() + pps := types.CloneRow(sessVars.PreparedParams) + sessVars.PrevStmt = FormatSQL(a.stmt.OriginText(), pps) a.stmt.logAudit() // Detach the disk tracker from GlobalDiskUsageTracker after every execution if stmtCtx := a.stmt.Ctx.GetSessionVars().StmtCtx; stmtCtx != nil && stmtCtx.DiskTracker != nil { @@ -767,31 +772,6 @@ func FormatSQL(sql string, pps variable.PreparedParams) stringutil.StringerFunc } } -var ( - sessionExecuteRunDurationInternal = metrics.SessionExecuteRunDuration.WithLabelValues(metrics.LblInternal) - sessionExecuteRunDurationGeneral = metrics.SessionExecuteRunDuration.WithLabelValues(metrics.LblGeneral) -) - -// FinishExecuteStmt is used to record some information after `ExecStmt` execution finished: -// 1. record slow log if needed. -// 2. record summary statement. -// 3. record execute duration metric. -// 4. update the `PrevStmt` in session variable. -func (a *ExecStmt) FinishExecuteStmt(txnTS uint64, succ bool, hasMoreResults bool) { - // `LowSlowQuery` and `SummaryStmt` must be called before recording `PrevStmt`. - a.LogSlowQuery(txnTS, succ, hasMoreResults) - a.SummaryStmt(succ) - sessVars := a.Ctx.GetSessionVars() - pps := types.CloneRow(sessVars.PreparedParams) - sessVars.PrevStmt = FormatSQL(a.OriginText(), pps) - executeDuration := time.Since(sessVars.StartTime) - sessVars.DurationCompile - if sessVars.InRestrictedSQL { - sessionExecuteRunDurationInternal.Observe(executeDuration.Seconds()) - } else { - sessionExecuteRunDurationGeneral.Observe(executeDuration.Seconds()) - } -} - // LogSlowQuery is used to print the slow query in the log files. func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) { sessVars := a.Ctx.GetSessionVars() diff --git a/session/session.go b/session/session.go index 8f76c581aeaa4..3e6cb905428da 100644 --- a/session/session.go +++ b/session/session.go @@ -83,6 +83,9 @@ var ( transactionDurationGeneralCommit = metrics.TransactionDuration.WithLabelValues(metrics.LblGeneral, metrics.LblCommit) transactionDurationGeneralAbort = metrics.TransactionDuration.WithLabelValues(metrics.LblGeneral, metrics.LblAbort) + sessionExecuteRunDurationInternal = metrics.SessionExecuteRunDuration.WithLabelValues(metrics.LblInternal) + sessionExecuteRunDurationGeneral = metrics.SessionExecuteRunDuration.WithLabelValues(metrics.LblGeneral) + sessionExecuteCompileDurationInternal = metrics.SessionExecuteCompileDuration.WithLabelValues(metrics.LblInternal) sessionExecuteCompileDurationGeneral = metrics.SessionExecuteCompileDuration.WithLabelValues(metrics.LblGeneral) sessionExecuteParseDurationInternal = metrics.SessionExecuteParseDuration.WithLabelValues(metrics.LblInternal) @@ -1030,6 +1033,7 @@ func (s *session) SetProcessInfo(sql string, t time.Time, command byte, maxExecu func (s *session) executeStatement(ctx context.Context, connID uint64, stmtNode ast.StmtNode, stmt sqlexec.Statement, recordSets []sqlexec.RecordSet, inMulitQuery bool) ([]sqlexec.RecordSet, error) { logStmt(stmtNode, s.sessionVars) + startTime := time.Now() recordSet, err := runStmt(ctx, s, stmt) if err != nil { if !kv.ErrKeyExists.Equal(err) { @@ -1040,6 +1044,11 @@ func (s *session) executeStatement(ctx context.Context, connID uint64, stmtNode } return nil, err } + if s.isInternal() { + sessionExecuteRunDurationInternal.Observe(time.Since(startTime).Seconds()) + } else { + sessionExecuteRunDurationGeneral.Observe(time.Since(startTime).Seconds()) + } if inMulitQuery && recordSet == nil { recordSet = &multiQueryNoDelayRecordSet{ @@ -1079,96 +1088,6 @@ func (s *session) Execute(ctx context.Context, sql string) (recordSets []sqlexec return } -<<<<<<< HEAD -======= -// Parse parses a query string to raw ast.StmtNode. -func (s *session) Parse(ctx context.Context, sql string) ([]ast.StmtNode, error) { - charsetInfo, collation := s.sessionVars.GetCharsetInfo() - parseStartTime := time.Now() - stmts, warns, err := s.ParseSQL(ctx, sql, charsetInfo, collation) - if err != nil { - s.rollbackOnError(ctx) - - // Only print log message when this SQL is from the user. - // Mute the warning for internal SQLs. - if !s.sessionVars.InRestrictedSQL { - logutil.Logger(ctx).Warn("parse SQL failed", zap.Error(err), zap.String("SQL", sql)) - } - return nil, util.SyntaxError(err) - } - - durParse := time.Since(parseStartTime) - s.GetSessionVars().DurationParse = durParse - isInternal := s.isInternal() - if isInternal { - sessionExecuteParseDurationInternal.Observe(durParse.Seconds()) - } else { - sessionExecuteParseDurationGeneral.Observe(durParse.Seconds()) - } - for _, warn := range warns { - s.sessionVars.StmtCtx.AppendWarning(util.SyntaxWarn(warn)) - } - return stmts, nil -} - -func (s *session) ExecuteStmt(ctx context.Context, stmtNode ast.StmtNode) (sqlexec.RecordSet, error) { - if span := opentracing.SpanFromContext(ctx); span != nil && span.Tracer() != nil { - span1 := span.Tracer().StartSpan("session.ExecuteStmt", opentracing.ChildOf(span.Context())) - defer span1.Finish() - ctx = opentracing.ContextWithSpan(ctx, span1) - } - - s.PrepareTxnCtx(ctx) - err := s.loadCommonGlobalVariablesIfNeeded() - if err != nil { - return nil, err - } - - s.sessionVars.StartTime = 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 - } - - // Transform abstract syntax tree to a physical plan(stored in executor.ExecStmt). - compiler := executor.Compiler{Ctx: s} - stmt, err := compiler.Compile(ctx, stmtNode) - if err != nil { - s.rollbackOnError(ctx) - - // Only print log message when this SQL is from the user. - // Mute the warning for internal SQLs. - if !s.sessionVars.InRestrictedSQL { - logutil.Logger(ctx).Warn("compile SQL failed", zap.Error(err), zap.String("SQL", stmtNode.Text())) - } - return nil, err - } - durCompile := time.Since(s.sessionVars.StartTime) - s.GetSessionVars().DurationCompile = durCompile - if s.isInternal() { - sessionExecuteCompileDurationInternal.Observe(durCompile.Seconds()) - } else { - sessionExecuteCompileDurationGeneral.Observe(durCompile.Seconds()) - } - s.currentPlan = stmt.Plan - - // Execute the physical plan. - logStmt(stmtNode, s.sessionVars) - recordSet, err := runStmt(ctx, s, stmt) - if err != nil { - if !kv.ErrKeyExists.Equal(err) { - logutil.Logger(ctx).Warn("run statement failed", - zap.Int64("schemaVersion", s.sessionVars.TxnCtx.SchemaVersion), - zap.Error(err), - zap.String("session", s.String())) - } - return nil, err - } - return recordSet, nil -} - ->>>>>>> 7106b18... session: refine record execution duration metric (#16453) func (s *session) execute(ctx context.Context, sql string) (recordSets []sqlexec.RecordSet, err error) { s.PrepareTxnCtx(ctx) connID := s.sessionVars.ConnectionID @@ -1291,10 +1210,6 @@ func (s *session) CommonExec(ctx context.Context, if err != nil { return nil, err } -<<<<<<< HEAD -======= - sessionExecuteCompileDurationGeneral.Observe(time.Since(s.sessionVars.StartTime).Seconds()) ->>>>>>> 7106b18... session: refine record execution duration metric (#16453) logQuery(st.OriginText(), s.sessionVars) return runStmt(ctx, s, st) } @@ -1324,14 +1239,7 @@ func (s *session) CachedPlanExec(ctx context.Context, OutputNames: execPlan.OutputNames(), PsStmt: prepareStmt, } -<<<<<<< HEAD s.GetSessionVars().DurationCompile = time.Since(s.sessionVars.StartTime) -======= - compileDuration := time.Since(s.sessionVars.StartTime) - sessionExecuteCompileDurationGeneral.Observe(compileDuration.Seconds()) - s.GetSessionVars().DurationCompile = compileDuration - ->>>>>>> 7106b18... session: refine record execution duration metric (#16453) stmt.Text = prepared.Stmt.Text() stmtCtx.OriginalSQL = stmt.Text stmtCtx.InitSQLDigest(prepareStmt.NormalizedSQL, prepareStmt.SQLDigest) diff --git a/session/tidb.go b/session/tidb.go index 8e64ac197e680..2e571549b5b8b 100644 --- a/session/tidb.go +++ b/session/tidb.go @@ -36,6 +36,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" @@ -265,7 +266,11 @@ func runStmt(ctx context.Context, sctx sessionctx.Context, s sqlexec.Statement) // If it is not a select statement, we record its slow log here, // then it could include the transaction commit time. if rs == nil { - s.(*executor.ExecStmt).FinishExecuteStmt(origTxnCtx.StartTS, err == nil, false) + // `LowSlowQuery` and `SummaryStmt` must be called before recording `PrevStmt`. + s.(*executor.ExecStmt).LogSlowQuery(origTxnCtx.StartTS, err == nil, false) + s.(*executor.ExecStmt).SummaryStmt(err == nil) + pps := types.CloneRow(sessVars.PreparedParams) + sessVars.PrevStmt = executor.FormatSQL(s.OriginText(), pps) } }() From f0ee3795a0e01bbe1fa7d84210a965c0702c31aa Mon Sep 17 00:00:00 2001 From: crazycs520 Date: Wed, 20 May 2020 11:05:23 +0800 Subject: [PATCH 3/3] session: refine record execution duration metric (#16453) --- executor/adapter.go | 32 ++++++++++++++++++++++++++------ session/session.go | 15 +++++---------- session/tidb.go | 7 +------ 3 files changed, 32 insertions(+), 22 deletions(-) diff --git a/executor/adapter.go b/executor/adapter.go index 2e4bea4c0b08c..934ed8793dedc 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -764,14 +764,14 @@ func FormatSQL(sql string, pps variable.PreparedParams) stringutil.StringerFunc } } +var ( + sessionExecuteRunDurationInternal = metrics.SessionExecuteRunDuration.WithLabelValues(metrics.LblInternal) + sessionExecuteRunDurationGeneral = metrics.SessionExecuteRunDuration.WithLabelValues(metrics.LblGeneral) +) + // CloseRecordSet will finish the execution of current statement and do some record work func (a *ExecStmt) CloseRecordSet(txnStartTS uint64, lastErr error) { - // `LowSlowQuery` and `SummaryStmt` must be called before recording `PrevStmt`. - a.LogSlowQuery(txnStartTS, lastErr == nil, false) - a.SummaryStmt(lastErr == nil) - sessVars := a.Ctx.GetSessionVars() - pps := types.CloneRow(sessVars.PreparedParams) - sessVars.PrevStmt = FormatSQL(a.OriginText(), pps) + a.FinishExecuteStmt(txnStartTS, lastErr == nil, false) a.logAudit() // Detach the disk tracker from GlobalDiskUsageTracker after every execution if stmtCtx := a.Ctx.GetSessionVars().StmtCtx; stmtCtx != nil && stmtCtx.DiskTracker != nil { @@ -779,6 +779,26 @@ func (a *ExecStmt) CloseRecordSet(txnStartTS uint64, lastErr error) { } } +// FinishExecuteStmt is used to record some information after `ExecStmt` execution finished: +// 1. record slow log if needed. +// 2. record summary statement. +// 3. record execute duration metric. +// 4. update the `PrevStmt` in session variable. +func (a *ExecStmt) FinishExecuteStmt(txnTS uint64, succ bool, hasMoreResults bool) { + // `LowSlowQuery` and `SummaryStmt` must be called before recording `PrevStmt`. + a.LogSlowQuery(txnTS, succ, hasMoreResults) + a.SummaryStmt(succ) + sessVars := a.Ctx.GetSessionVars() + pps := types.CloneRow(sessVars.PreparedParams) + sessVars.PrevStmt = FormatSQL(a.OriginText(), pps) + executeDuration := time.Since(sessVars.StartTime) - sessVars.DurationCompile + if sessVars.InRestrictedSQL { + sessionExecuteRunDurationInternal.Observe(executeDuration.Seconds()) + } else { + sessionExecuteRunDurationGeneral.Observe(executeDuration.Seconds()) + } +} + // LogSlowQuery is used to print the slow query in the log files. func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) { sessVars := a.Ctx.GetSessionVars() diff --git a/session/session.go b/session/session.go index 42ddb2729cd79..b5fd447acf490 100644 --- a/session/session.go +++ b/session/session.go @@ -83,9 +83,6 @@ var ( transactionDurationGeneralCommit = metrics.TransactionDuration.WithLabelValues(metrics.LblGeneral, metrics.LblCommit) transactionDurationGeneralAbort = metrics.TransactionDuration.WithLabelValues(metrics.LblGeneral, metrics.LblAbort) - sessionExecuteRunDurationInternal = metrics.SessionExecuteRunDuration.WithLabelValues(metrics.LblInternal) - sessionExecuteRunDurationGeneral = metrics.SessionExecuteRunDuration.WithLabelValues(metrics.LblGeneral) - sessionExecuteCompileDurationInternal = metrics.SessionExecuteCompileDuration.WithLabelValues(metrics.LblInternal) sessionExecuteCompileDurationGeneral = metrics.SessionExecuteCompileDuration.WithLabelValues(metrics.LblGeneral) sessionExecuteParseDurationInternal = metrics.SessionExecuteParseDuration.WithLabelValues(metrics.LblInternal) @@ -1037,7 +1034,6 @@ func (s *session) SetProcessInfo(sql string, t time.Time, command byte, maxExecu func (s *session) executeStatement(ctx context.Context, connID uint64, stmtNode ast.StmtNode, stmt sqlexec.Statement, recordSets []sqlexec.RecordSet, inMulitQuery bool) ([]sqlexec.RecordSet, error) { logStmt(stmtNode, s.sessionVars) - startTime := time.Now() recordSet, err := runStmt(ctx, s, stmt) if err != nil { if !kv.ErrKeyExists.Equal(err) { @@ -1048,11 +1044,6 @@ func (s *session) executeStatement(ctx context.Context, connID uint64, stmtNode } return nil, err } - if s.isInternal() { - sessionExecuteRunDurationInternal.Observe(time.Since(startTime).Seconds()) - } else { - sessionExecuteRunDurationGeneral.Observe(time.Since(startTime).Seconds()) - } if inMulitQuery && recordSet == nil { recordSet = &multiQueryNoDelayRecordSet{ @@ -1214,6 +1205,7 @@ func (s *session) CommonExec(ctx context.Context, if err != nil { return nil, err } + sessionExecuteCompileDurationGeneral.Observe(time.Since(s.sessionVars.StartTime).Seconds()) logQuery(st.OriginText(), s.sessionVars) return runStmt(ctx, s, st) } @@ -1243,7 +1235,10 @@ func (s *session) CachedPlanExec(ctx context.Context, OutputNames: execPlan.OutputNames(), PsStmt: prepareStmt, } - s.GetSessionVars().DurationCompile = time.Since(s.sessionVars.StartTime) + compileDuration := time.Since(s.sessionVars.StartTime) + sessionExecuteCompileDurationGeneral.Observe(compileDuration.Seconds()) + s.GetSessionVars().DurationCompile = compileDuration + stmt.Text = prepared.Stmt.Text() stmtCtx.OriginalSQL = stmt.Text stmtCtx.InitSQLDigest(prepareStmt.NormalizedSQL, prepareStmt.SQLDigest) diff --git a/session/tidb.go b/session/tidb.go index 2e571549b5b8b..8e64ac197e680 100644 --- a/session/tidb.go +++ b/session/tidb.go @@ -36,7 +36,6 @@ 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" @@ -266,11 +265,7 @@ func runStmt(ctx context.Context, sctx sessionctx.Context, s sqlexec.Statement) // If it is not a select statement, we record its slow log here, // then it could include the transaction commit time. if rs == nil { - // `LowSlowQuery` and `SummaryStmt` must be called before recording `PrevStmt`. - s.(*executor.ExecStmt).LogSlowQuery(origTxnCtx.StartTS, err == nil, false) - s.(*executor.ExecStmt).SummaryStmt(err == nil) - pps := types.CloneRow(sessVars.PreparedParams) - sessVars.PrevStmt = executor.FormatSQL(s.OriginText(), pps) + s.(*executor.ExecStmt).FinishExecuteStmt(origTxnCtx.StartTS, err == nil, false) } }()