From ebc8150fe1dc3d1c18257fb5d93c74b8bfe06873 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 cc07ea991a6c6..8a7974e35a081 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -907,6 +907,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 b4bd930127ab0..68a5cf84f3a42 100755 --- a/executor/slow_query.go +++ b/executor/slow_query.go @@ -457,6 +457,8 @@ type slowQueryTuple struct { rewriteTime float64 preprocSubqueries uint64 preprocSubQueryTime float64 + optimizeTime float64 + waitTSTime float64 preWriteTime float64 waitPrewriteBinlogTime float64 commitTime float64 @@ -563,6 +565,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: @@ -687,6 +693,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 64c63a08e5f94..09aaf9ad77e6e 100644 --- a/executor/slow_query_test.go +++ b/executor/slow_query_test.go @@ -130,7 +130,7 @@ select * from t;` } expectRecordString := `2019-04-28 15:24:04.309074,` + `405888132465033227,root,localhost,0,57,0.12,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,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,0,0,0,` + `Cop_backoff_regionMiss_total_times: 200 Cop_backoff_regionMiss_total_time: 0.2 Cop_backoff_regionMiss_max_time: 0.2 Cop_backoff_regionMiss_max_addr: 127.0.0.1 Cop_backoff_regionMiss_avg_time: 0.2 Cop_backoff_regionMiss_p90_time: 0.2 Cop_backoff_rpcPD_total_times: 200 Cop_backoff_rpcPD_total_time: 0.2 Cop_backoff_rpcPD_max_time: 0.2 Cop_backoff_rpcPD_max_addr: 127.0.0.1 Cop_backoff_rpcPD_avg_time: 0.2 Cop_backoff_rpcPD_p90_time: 0.2 Cop_backoff_rpcTiKV_total_times: 200 Cop_backoff_rpcTiKV_total_time: 0.2 Cop_backoff_rpcTiKV_max_time: 0.2 Cop_backoff_rpcTiKV_max_addr: 127.0.0.1 Cop_backoff_rpcTiKV_avg_time: 0.2 Cop_backoff_rpcTiKV_p90_time: 0.2,` + `0,0,1,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,` + diff --git a/infoschema/tables.go b/infoschema/tables.go index fb0336dd07ff4..e4dd6fa2f7165 100644 --- a/infoschema/tables.go +++ b/infoschema/tables.go @@ -728,6 +728,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 072cd1079ba92..6759efa55f8c1 100644 --- a/infoschema/tables_test.go +++ b/infoschema/tables_test.go @@ -552,6 +552,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 @@ -636,10 +638,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|localhost|6|57|0.12|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|0|0|0|0||0|1|1|abcd|60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4|update t set i = 2;|select * from t_slim;")) + "2019-02-12 19:33:56.571953|406315658548871171|root|localhost|6|57|0.12|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|0|0|0|0||0|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|localhost|6|57|0.12|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|0|0|0|0||0|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|localhost|6|57|0.12|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|0|0|0|0||0|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 35c5981d36eb7..09d2de310616a 100644 --- a/planner/optimize.go +++ b/planner/optimize.go @@ -248,7 +248,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 1a8bcc7b21b59..8ef1b1a6d740e 100644 --- a/session/session.go +++ b/session/session.go @@ -1526,6 +1526,9 @@ func (s *session) Txn(active bool) (kv.Transaction, error) { return &s.txn, errors.AddStack(kv.ErrInvalidTxn) } if s.txn.pending() && active { + 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 53e018bfd52e1..d9c1c44fcca9d 100644 --- a/sessionctx/variable/session.go +++ b/sessionctx/variable/session.go @@ -588,6 +588,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 @@ -1589,6 +1595,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. @@ -1674,6 +1684,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 @@ -1754,6 +1766,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 b58ab81a6b4d9..7ab9927005305 100644 --- a/sessionctx/variable/session_test.go +++ b/sessionctx/variable/session_test.go @@ -183,6 +183,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] @@ -214,6 +216,8 @@ func (*testSessionSuite) TestSlowLogFormat(c *C) { 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,