Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

*: do not start slow-log timer before parsing (#13846) #13898

Merged
merged 2 commits into from
Dec 10, 2019
Merged

*: do not start slow-log timer before parsing (#13846) #13898

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
ead5841
*: do not start slow-log timer before parsing (#13846)
jackysp Dec 4, 2019
3911d09
Merge branch 'release-3.0' into multi-query-3.0
sre-bot Dec 10, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion config/config_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
20 changes: 6 additions & 14 deletions executor/adapter.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand All @@ -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()
Expand All @@ -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,
Expand Down Expand Up @@ -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,
Expand Down
12 changes: 4 additions & 8 deletions session/session.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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)
Expand All @@ -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 {
Expand All @@ -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
Expand All @@ -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())
Expand Down