From 405a5d009dcdf166cc0a27bc0bf784df049b9f32 Mon Sep 17 00:00:00 2001 From: Yuanjia Zhang Date: Wed, 10 Jun 2020 10:41:50 +0800 Subject: [PATCH] sessionctx: add optimization-time and wait-TS-time into the slow log (#17869) --- executor/adapter.go | 2 ++ executor/slow_query.go | 8 ++++++++ executor/slow_query_test.go | 2 +- infoschema/tables.go | 2 ++ infoschema/tables_test.go | 6 ++++-- planner/optimize.go | 3 +++ session/session.go | 3 +++ sessionctx/variable/session.go | 15 +++++++++++++++ sessionctx/variable/session_test.go | 4 ++++ 9 files changed, 42 insertions(+), 3 deletions(-) diff --git a/executor/adapter.go b/executor/adapter.go index bc92a4ec9268b..622c0ef9840bb 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -844,6 +844,8 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) { TimeTotal: costTime, TimeParse: sessVars.DurationParse, TimeCompile: sessVars.DurationCompile, + TimeOptimize: sessVars.DurationOptimization, + TimeWaitTS: sessVars.DurationWaitTS, IndexNames: indexNames, StatsInfos: statsInfos, CopTasks: copTaskInfo, diff --git a/executor/slow_query.go b/executor/slow_query.go index b348f583b96bb..f9c8f828424a1 100644 --- a/executor/slow_query.go +++ b/executor/slow_query.go @@ -309,6 +309,8 @@ type slowQueryTuple struct { rewriteTime float64 preprocSubqueries uint64 preprocSubQueryTime float64 + optimizeTime float64 + waitTSTime float64 preWriteTime float64 waitPrewriteBinlogTime float64 commitTime float64 @@ -390,6 +392,10 @@ func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string, st.parseTime, err = strconv.ParseFloat(value, 64) case variable.SlowLogCompileTimeStr: st.compileTime, err = strconv.ParseFloat(value, 64) + case variable.SlowLogOptimizeTimeStr: + st.optimizeTime, err = strconv.ParseFloat(value, 64) + case variable.SlowLogWaitTSTimeStr: + st.waitTSTime, err = strconv.ParseFloat(value, 64) case execdetails.PreWriteTimeStr: st.preWriteTime, err = strconv.ParseFloat(value, 64) case execdetails.WaitPrewriteBinlogTimeStr: @@ -496,6 +502,8 @@ func (st *slowQueryTuple) convertToDatumRow() []types.Datum { record = append(record, types.NewFloat64Datum(st.rewriteTime)) record = append(record, types.NewUintDatum(st.preprocSubqueries)) record = append(record, types.NewFloat64Datum(st.preprocSubQueryTime)) + record = append(record, types.NewFloat64Datum(st.optimizeTime)) + record = append(record, types.NewFloat64Datum(st.waitTSTime)) record = append(record, types.NewFloat64Datum(st.preWriteTime)) record = append(record, types.NewFloat64Datum(st.waitPrewriteBinlogTime)) record = append(record, types.NewFloat64Datum(st.commitTime)) diff --git a/executor/slow_query_test.go b/executor/slow_query_test.go index 5732c78fc70dd..fc5090ffd4d29 100644 --- a/executor/slow_query_test.go +++ b/executor/slow_query_test.go @@ -77,7 +77,7 @@ select * from t;` } recordString += str } - expectRecordString := "2019-04-28 15:24:04.309074,405888132465033227,,,0,0.216905,0,0,0,0,0,0,0,0,0,0,,0,0,0,0,0,0,0.38,0.021,0,0,0,1,637,0,,,1,42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772,t1:1,t2:2,0.1,0.2,0.03,127.0.0.1:20160,0.05,0.6,0.8,0.0.0.0:20160,70724,65536,0,1,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,update t set i = 1;,select * from t;" + expectRecordString := "2019-04-28 15:24:04.309074,405888132465033227,,,0,0.216905,0,0,0,0,0,0,0,0,0,0,0,0,,0,0,0,0,0,0,0.38,0.021,0,0,0,1,637,0,,,1,42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772,t1:1,t2:2,0.1,0.2,0.03,127.0.0.1:20160,0.05,0.6,0.8,0.0.0.0:20160,70724,65536,0,1,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,update t set i = 1;,select * from t;" c.Assert(expectRecordString, Equals, recordString) // fix sql contain '# ' bug diff --git a/infoschema/tables.go b/infoschema/tables.go index b4727638039a2..8233557ae92e7 100755 --- a/infoschema/tables.go +++ b/infoschema/tables.go @@ -717,6 +717,8 @@ var slowQueryCols = []columnInfo{ {name: variable.SlowLogRewriteTimeStr, tp: mysql.TypeDouble, size: 22}, {name: variable.SlowLogPreprocSubQueriesStr, tp: mysql.TypeLonglong, size: 20, flag: mysql.UnsignedFlag}, {name: variable.SlowLogPreProcSubQueryTimeStr, tp: mysql.TypeDouble, size: 22}, + {name: variable.SlowLogOptimizeTimeStr, tp: mysql.TypeDouble, size: 22}, + {name: variable.SlowLogWaitTSTimeStr, tp: mysql.TypeDouble, size: 22}, {name: execdetails.PreWriteTimeStr, tp: mysql.TypeDouble, size: 22}, {name: execdetails.WaitPrewriteBinlogTimeStr, tp: mysql.TypeDouble, size: 22}, {name: execdetails.CommitTimeStr, tp: mysql.TypeDouble, size: 22}, diff --git a/infoschema/tables_test.go b/infoschema/tables_test.go index f0c8705de6379..95560adbf9e1a 100644 --- a/infoschema/tables_test.go +++ b/infoschema/tables_test.go @@ -537,6 +537,8 @@ func prepareSlowLogfile(c *C, slowLogFileName string) { # Parse_time: 0.4 # Compile_time: 0.2 # Rewrite_time: 0.000000003 Preproc_subqueries: 2 Preproc_subqueries_time: 0.000000002 +# Optimize_time: 0.00000001 +# Wait_TS: 0.000000003 # LockKeys_time: 1.71 Request_count: 1 Prewrite_time: 0.19 Wait_prewrite_binlog_time: 0.21 Commit_time: 0.01 Commit_backoff_time: 0.18 Backoff_types: [txnLock] Resolve_lock_time: 0.03 Write_keys: 15 Write_size: 480 Prewrite_region: 1 Txn_retry: 8 # Cop_time: 0.3824278 Process_time: 0.161 Request_count: 1 Total_keys: 100001 Process_keys: 100000 # Wait_time: 0.101 @@ -621,10 +623,10 @@ func (s *testTableSuite) TestSlowQuery(c *C) { tk.MustExec("set time_zone = '+08:00';") re := tk.MustQuery("select * from information_schema.slow_query") re.Check(testutil.RowsWithSep("|", - "2019-02-12 19:33:56.571953|406315658548871171|root|127.0.0.1|6|4.895492|0.4|0.2|0.000000003|2|0.000000002|0.19|0.21|0.01|0|0.18|[txnLock]|0.03|0|15|480|1|8|0.3824278|0.161|0.101|0.092|1.71|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|0.1|0.2|0.03|127.0.0.1:20160|0.05|0.6|0.8|0.0.0.0:20160|70724|65536|1|1|abcd|60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4|update t set i = 2;|select * from t_slim;")) + "2019-02-12 19:33:56.571953|406315658548871171|root|127.0.0.1|6|4.895492|0.4|0.2|0.000000003|2|0.000000002|0.00000001|0.000000003|0.19|0.21|0.01|0|0.18|[txnLock]|0.03|0|15|480|1|8|0.3824278|0.161|0.101|0.092|1.71|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|0.1|0.2|0.03|127.0.0.1:20160|0.05|0.6|0.8|0.0.0.0:20160|70724|65536|1|1|abcd|60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4|update t set i = 2;|select * from t_slim;")) tk.MustExec("set time_zone = '+00:00';") re = tk.MustQuery("select * from information_schema.slow_query") - re.Check(testutil.RowsWithSep("|", "2019-02-12 11:33:56.571953|406315658548871171|root|127.0.0.1|6|4.895492|0.4|0.2|0.000000003|2|0.000000002|0.19|0.21|0.01|0|0.18|[txnLock]|0.03|0|15|480|1|8|0.3824278|0.161|0.101|0.092|1.71|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|0.1|0.2|0.03|127.0.0.1:20160|0.05|0.6|0.8|0.0.0.0:20160|70724|65536|1|1|abcd|60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4|update t set i = 2;|select * from t_slim;")) + re.Check(testutil.RowsWithSep("|", "2019-02-12 11:33:56.571953|406315658548871171|root|127.0.0.1|6|4.895492|0.4|0.2|0.000000003|2|0.000000002|0.00000001|0.000000003|0.19|0.21|0.01|0|0.18|[txnLock]|0.03|0|15|480|1|8|0.3824278|0.161|0.101|0.092|1.71|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|0.1|0.2|0.03|127.0.0.1:20160|0.05|0.6|0.8|0.0.0.0:20160|70724|65536|1|1|abcd|60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4|update t set i = 2;|select * from t_slim;")) // Test for long query. f, err := os.OpenFile(slowLogFileName, os.O_CREATE|os.O_WRONLY, 0644) diff --git a/planner/optimize.go b/planner/optimize.go index bf8684dfda7f2..8a0c1eb409250 100644 --- a/planner/optimize.go +++ b/planner/optimize.go @@ -196,7 +196,10 @@ func optimize(ctx context.Context, sctx sessionctx.Context, node ast.Node, is in finalPlan, cost, err := cascades.DefaultOptimizer.FindBestPlan(sctx, logic) return finalPlan, names, cost, err } + + beginOpt := time.Now() finalPlan, cost, err := plannercore.DoOptimize(ctx, sctx, builder.GetOptFlag(), logic) + sctx.GetSessionVars().DurationOptimization = time.Since(beginOpt) return finalPlan, names, cost, err } diff --git a/session/session.go b/session/session.go index edc6cc1c2b297..e66f329217090 100644 --- a/session/session.go +++ b/session/session.go @@ -1426,6 +1426,9 @@ func (s *session) Txn(active bool) (kv.Transaction, error) { return &s.txn, errors.AddStack(kv.ErrInvalidTxn) } if s.txn.pending() { + defer func(begin time.Time) { + s.sessionVars.DurationWaitTS = time.Since(begin) + }(time.Now()) // Transaction is lazy initialized. // PrepareTxnCtx is called to get a tso future, makes s.txn a pending txn, // If Txn() is called later, wait for the future to get a valid txn. diff --git a/sessionctx/variable/session.go b/sessionctx/variable/session.go index b32922932b12d..a057f5b65adea 100644 --- a/sessionctx/variable/session.go +++ b/sessionctx/variable/session.go @@ -564,6 +564,12 @@ type SessionVars struct { // RewritePhaseInfo records all information about the rewriting phase. RewritePhaseInfo + // DurationOptimization is the duration of optimizing a query. + DurationOptimization time.Duration + + // DurationWaitTS is the duration of waiting for a snapshot TS + DurationWaitTS time.Duration + // PrevStmt is used to store the previous executed statement in the current session. PrevStmt fmt.Stringer @@ -1527,6 +1533,10 @@ const ( SlowLogCompileTimeStr = "Compile_time" // SlowLogRewriteTimeStr is the rewrite time. SlowLogRewriteTimeStr = "Rewrite_time" + // SlowLogOptimizeTimeStr is the optimization time. + SlowLogOptimizeTimeStr = "Optimize_time" + // SlowLogWaitTSTimeStr is the time of waiting TS. + SlowLogWaitTSTimeStr = "Wait_TS" // SlowLogPreprocSubQueriesStr is the number of pre-processed sub-queries. SlowLogPreprocSubQueriesStr = "Preproc_subqueries" // SlowLogPreProcSubQueryTimeStr is the total time of pre-processing sub-queries. @@ -1598,6 +1608,8 @@ type SlowQueryLogItems struct { TimeTotal time.Duration TimeParse time.Duration TimeCompile time.Duration + TimeOptimize time.Duration + TimeWaitTS time.Duration IndexNames string StatsInfos map[string]uint64 CopTasks *stmtctx.CopTasksDetails @@ -1657,6 +1669,9 @@ func (s *SessionVars) SlowLogFormat(logItems *SlowQueryLogItems) string { } buf.WriteString("\n") + writeSlowLogItem(&buf, SlowLogOptimizeTimeStr, strconv.FormatFloat(logItems.TimeOptimize.Seconds(), 'f', -1, 64)) + writeSlowLogItem(&buf, SlowLogWaitTSTimeStr, strconv.FormatFloat(logItems.TimeWaitTS.Seconds(), 'f', -1, 64)) + if execDetailStr := logItems.ExecDetail.String(); len(execDetailStr) > 0 { buf.WriteString(SlowLogRowPrefixStr + execDetailStr + "\n") } diff --git a/sessionctx/variable/session_test.go b/sessionctx/variable/session_test.go index de97edab0296a..e8d9fff17a7aa 100644 --- a/sessionctx/variable/session_test.go +++ b/sessionctx/variable/session_test.go @@ -181,6 +181,8 @@ func (*testSessionSuite) TestSlowLogFormat(c *C) { # Parse_time: 0.00000001 # Compile_time: 0.00000001 # Rewrite_time: 0.000000003 Preproc_subqueries: 2 Preproc_subqueries_time: 0.000000002 +# Optimize_time: 0.00000001 +# Wait_TS: 0.000000003 # Process_time: 2 Wait_time: 60 Backoff_time: 0.001 Request_count: 2 Total_keys: 10000 Process_keys: 20001 # DB: test # Index_names: [t1:a,t2:b] @@ -209,6 +211,8 @@ select * from t;` TimeTotal: costTime, TimeParse: time.Duration(10), TimeCompile: time.Duration(10), + TimeOptimize: time.Duration(10), + TimeWaitTS: time.Duration(3), IndexNames: "[t1:a,t2:b]", StatsInfos: statsInfos, CopTasks: copTasks,