diff --git a/executor/adapter.go b/executor/adapter.go index 23ca0d41083cc..a70638da715b6 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -843,6 +843,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) { PlanDigest: planDigest, Prepared: a.isPreparedStmt, HasMoreResults: hasMoreResults, + PlanFromCache: sessVars.FoundInPlanCache, } if _, ok := a.StmtNode.(*ast.CommitStmt); ok { slowItems.PrevStmt = sessVars.PrevStmt.String() diff --git a/executor/slow_query.go b/executor/slow_query.go index 30ea85a432033..44a6b541ca359 100644 --- a/executor/slow_query.go +++ b/executor/slow_query.go @@ -343,6 +343,7 @@ type slowQueryTuple struct { sql string isInternal bool succ bool + planFromCache bool plan string planDigest string } @@ -454,6 +455,8 @@ func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string, st.memMax, err = strconv.ParseInt(value, 10, 64) case variable.SlowLogSucc: st.succ, err = strconv.ParseBool(value) + case variable.SlowLogPlanFromCache: + st.planFromCache, err = strconv.ParseBool(value) case variable.SlowLogPlan: st.plan = value case variable.SlowLogPlanDigest: @@ -516,6 +519,11 @@ func (st *slowQueryTuple) convertToDatumRow() []types.Datum { } else { record = append(record, types.NewIntDatum(0)) } + if st.planFromCache { + record = append(record, types.NewIntDatum(1)) + } else { + record = append(record, types.NewIntDatum(0)) + } record = append(record, types.NewStringDatum(parsePlan(st.plan))) record = append(record, types.NewStringDatum(st.planDigest)) record = append(record, types.NewStringDatum(st.prevStmt)) diff --git a/executor/slow_query_test.go b/executor/slow_query_test.go index daa05a46acd16..489b74098d2e3 100644 --- a/executor/slow_query_test.go +++ b/executor/slow_query_test.go @@ -54,6 +54,7 @@ func (s *testExecSuite) TestParseSlowLogFile(c *C) { # Cop_proc_avg: 0.1 Cop_proc_p90: 0.2 Cop_proc_max: 0.03 Cop_proc_addr: 127.0.0.1:20160 # Cop_wait_avg: 0.05 Cop_wait_p90: 0.6 Cop_wait_max: 0.8 Cop_wait_addr: 0.0.0.0:20160 # Mem_max: 70724 +# Plan_from_cache: true # Succ: false # Plan_digest: 60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4 # Prev_stmt: update t set i = 1; @@ -75,7 +76,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.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,0,,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.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,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 2419feb8a6937..a142ba10fa448 100644 --- a/infoschema/tables.go +++ b/infoschema/tables.go @@ -746,6 +746,7 @@ var slowQueryCols = []columnInfo{ {name: variable.SlowLogCopWaitAddr, tp: mysql.TypeVarchar, size: 64}, {name: variable.SlowLogMemMax, tp: mysql.TypeLonglong, size: 20}, {name: variable.SlowLogSucc, tp: mysql.TypeTiny, size: 1}, + {name: variable.SlowLogPlanFromCache, tp: mysql.TypeTiny, size: 1}, {name: variable.SlowLogPlan, tp: mysql.TypeLongBlob, size: types.UnspecifiedLength}, {name: variable.SlowLogPlanDigest, tp: mysql.TypeVarchar, size: 128}, {name: variable.SlowLogPrevStmt, tp: mysql.TypeLongBlob, size: types.UnspecifiedLength}, diff --git a/infoschema/tables_test.go b/infoschema/tables_test.go index 5775ecd4597cf..762f1d4b6d989 100644 --- a/infoschema/tables_test.go +++ b/infoschema/tables_test.go @@ -532,6 +532,7 @@ func prepareSlowLogfile(c *C, slowLogFileName string) { # Cop_proc_avg: 0.1 Cop_proc_p90: 0.2 Cop_proc_max: 0.03 Cop_proc_addr: 127.0.0.1:20160 # Cop_wait_avg: 0.05 Cop_wait_p90: 0.6 Cop_wait_max: 0.8 Cop_wait_addr: 0.0.0.0:20160 # Mem_max: 70724 +# Plan_from_cache: true # Succ: true # Plan: abcd # Plan_digest: 60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4 @@ -603,10 +604,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.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|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.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|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.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|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.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|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/core/common_plans.go b/planner/core/common_plans.go index 45669a6a6345d..dfc896e9b18e3 100644 --- a/planner/core/common_plans.go +++ b/planner/core/common_plans.go @@ -358,10 +358,6 @@ REBUILD: e.Plan = p _, isTableDual := p.(*PhysicalTableDual) if !isTableDual && prepared.UseCache { - err = e.setFoundInPlanCache(sctx, true) - if err != nil { - return err - } cached := NewPSTMTPlanCacheValue(p, names, stmtCtx.TblInfo2UnionScan) preparedStmt.NormalizedPlan, preparedStmt.PlanDigest = NormalizePlan(p) stmtCtx.SetPlanDigest(preparedStmt.NormalizedPlan, preparedStmt.PlanDigest) diff --git a/sessionctx/variable/session.go b/sessionctx/variable/session.go index f5089da1be372..975f6dd0e7b25 100644 --- a/sessionctx/variable/session.go +++ b/sessionctx/variable/session.go @@ -1484,6 +1484,8 @@ const ( SlowLogMemMax = "Mem_max" // SlowLogPrepared is used to indicate whether this sql execute in prepare. SlowLogPrepared = "Prepared" + // SlowLogPlanFromCache is used to indicate whether this plan is from plan cache. + SlowLogPlanFromCache = "Plan_from_cache" // SlowLogHasMoreResults is used to indicate whether this sql has more following results. SlowLogHasMoreResults = "Has_more_results" // SlowLogSucc is used to indicate whether this sql execute successfully. @@ -1518,6 +1520,7 @@ type SlowQueryLogItems struct { MemMax int64 Succ bool Prepared bool + PlanFromCache bool HasMoreResults bool PrevStmt string Plan string @@ -1647,6 +1650,7 @@ func (s *SessionVars) SlowLogFormat(logItems *SlowQueryLogItems) string { } writeSlowLogItem(&buf, SlowLogPrepared, strconv.FormatBool(logItems.Prepared)) + writeSlowLogItem(&buf, SlowLogPlanFromCache, strconv.FormatBool(logItems.PlanFromCache)) writeSlowLogItem(&buf, SlowLogHasMoreResults, strconv.FormatBool(logItems.HasMoreResults)) writeSlowLogItem(&buf, SlowLogSucc, strconv.FormatBool(logItems.Succ)) if len(logItems.Plan) != 0 { diff --git a/sessionctx/variable/session_test.go b/sessionctx/variable/session_test.go index 8e5136bebf995..198dbdd1de0f3 100644 --- a/sessionctx/variable/session_test.go +++ b/sessionctx/variable/session_test.go @@ -191,6 +191,7 @@ func (*testSessionSuite) TestSlowLogFormat(c *C) { # 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 # Mem_max: 2333 # Prepared: true +# Plan_from_cache: true # Has_more_results: true # Succ: true select * from t;` @@ -209,6 +210,7 @@ select * from t;` ExecDetail: execDetail, MemMax: memMax, Prepared: true, + PlanFromCache: true, HasMoreResults: true, Succ: true, })