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

sessionctx: record if a query hits plan cache in slow log #17088

Merged
merged 5 commits into from
May 12, 2020
Merged

sessionctx: record if a query hits plan cache in slow log #17088

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
ac68a50
sessionctx: record if a query hits plan cache in slow log
eurekaka May 9, 2020
58715a5
Merge branch 'master' into slow_log
eurekaka May 11, 2020
aabf8de
add slow_query plan_from_cache
eurekaka May 9, 2020
4d48754
Merge branch 'master' into slow_log
crazycs520 May 12, 2020
d6bdda5
Merge branch 'master' into slow_log
sre-bot May 12, 2020
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
1 change: 1 addition & 0 deletions executor/adapter.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -843,6 +843,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) {
PlanDigest: planDigest,
Prepared: a.isPreparedStmt,
HasMoreResults: hasMoreResults,
PlanFromCache: sessVars.FoundInPlanCache,
Copy link
Contributor

@danmay319 danmay319 May 11, 2020 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

FoundInPlanCache indicates "if the current executing statement is from plan cache", while PrevFoundInPlanCache indicates "if the last executing statement is from plan cache". Currently, when we execute select last_plan_from_cache, the value of PrevFoundInPlanCache is shown as result. So I wonder which value is needed here.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LogSlowQuery is called before finishing execution of current query, so we should use FoundInPlanCache I think.

}
if _, ok := a.StmtNode.(*ast.CommitStmt); ok {
slowItems.PrevStmt = sessVars.PrevStmt.String()
Expand Down
8 changes: 8 additions & 0 deletions executor/slow_query.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -343,6 +343,7 @@ type slowQueryTuple struct {
sql string
isInternal bool
succ bool
planFromCache bool
plan string
planDigest string
}
Expand Down Expand Up @@ -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:
Expand Down Expand Up @@ -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))
Expand Down
3 changes: 2 additions & 1 deletion executor/slow_query_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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
Expand Down
1 change: 1 addition & 0 deletions infoschema/tables.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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},
Expand Down
5 changes: 3 additions & 2 deletions infoschema/tables_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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)
Expand Down
4 changes: 0 additions & 4 deletions planner/core/common_plans.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -358,10 +358,6 @@ REBUILD:
e.Plan = p
_, isTableDual := p.(*PhysicalTableDual)
if !isTableDual && prepared.UseCache {
err = e.setFoundInPlanCache(sctx, true)
Copy link
Contributor

@danmay319 danmay319 May 11, 2020 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It should have been removed by https://github.com/pingcap/tidb/pull/16594/files, wonder why it appears again. 🤦

if err != nil {
return err
}
cached := NewPSTMTPlanCacheValue(p, names, stmtCtx.TblInfo2UnionScan)
preparedStmt.NormalizedPlan, preparedStmt.PlanDigest = NormalizePlan(p)
stmtCtx.SetPlanDigest(preparedStmt.NormalizedPlan, preparedStmt.PlanDigest)
Expand Down
4 changes: 4 additions & 0 deletions sessionctx/variable/session.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -1518,6 +1520,7 @@ type SlowQueryLogItems struct {
MemMax int64
Succ bool
Prepared bool
PlanFromCache bool
HasMoreResults bool
PrevStmt string
Plan string
Expand Down Expand Up @@ -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 {
Expand Down
2 changes: 2 additions & 0 deletions sessionctx/variable/session_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;`
Expand All @@ -209,6 +210,7 @@ select * from t;`
ExecDetail: execDetail,
MemMax: memMax,
Prepared: true,
PlanFromCache: true,
HasMoreResults: true,
Succ: true,
})
Expand Down