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

*: add execution retry count in slow log and slow_query (#19487) #20494

Merged
merged 5 commits into from
Oct 19, 2020
Merged

*: add execution retry count in slow log and slow_query (#19487) #20494

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
2989e55
cherry pick #19487 to release-4.0
crazycs520 Aug 27, 2020
a352d12
fix conflict
crazycs520 Oct 19, 2020
9cf9a77
Merge branch 'release-4.0' into release-4.0-253d43fb519d
qw4990 Oct 19, 2020
b035d62
Merge branch 'release-4.0' into release-4.0-253d43fb519d
crazycs520 Oct 19, 2020
4e02d35
Merge branch 'release-4.0' into release-4.0-253d43fb519d
crazycs520 Oct 19, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
Binary file added cmd/explaintest/portgenerator
View file
Open in desktop
Binary file not shown.
1 change: 1 addition & 0 deletions executor/adapter.go
View file
Open in desktop
Expand Up @@ -895,6 +895,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) {
BackoffTotal: time.Duration(atomic.LoadInt64(&stmtDetail.BackoffDuration)),
WriteSQLRespTotal: stmtDetail.WriteSQLRespDuration,
RewriteInfo: sessVars.RewritePhaseInfo,
ExecRetryCount: a.retryCount,
}
if _, ok := a.StmtNode.(*ast.CommitStmt); ok {
slowItems.PrevStmt = sessVars.PrevStmt.String()
Expand Down
4 changes: 4 additions & 0 deletions executor/slow_query.go
View file
Open in desktop
Expand Up @@ -321,6 +321,7 @@ type slowQueryTuple struct {
user string
host string
connID uint64
execRetryCount uint64
queryTime float64
parseTime float64
compileTime float64
Expand Down Expand Up @@ -417,6 +418,8 @@ func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string,
}
case variable.SlowLogConnIDStr:
st.connID, err = strconv.ParseUint(value, 10, 64)
case variable.SlowLogExecRetryCount:
st.execRetryCount, err = strconv.ParseUint(value, 10, 64)
case variable.SlowLogQueryTimeStr:
st.queryTime, err = strconv.ParseFloat(value, 64)
case variable.SlowLogParseTimeStr:
Expand Down Expand Up @@ -523,6 +526,7 @@ func (st *slowQueryTuple) convertToDatumRow() []types.Datum {
record = append(record, types.NewStringDatum(st.user))
record = append(record, types.NewStringDatum(st.host))
record = append(record, types.NewUintDatum(st.connID))
record = append(record, types.NewUintDatum(st.execRetryCount))
record = append(record, types.NewFloat64Datum(st.queryTime))
record = append(record, types.NewFloat64Datum(st.parseTime))
record = append(record, types.NewFloat64Datum(st.compileTime))
Expand Down
3 changes: 2 additions & 1 deletion executor/slow_query_test.go
View file
Open in desktop
Expand Up @@ -47,6 +47,7 @@ func (s *testExecSuite) TestParseSlowLogFile(c *C) {
`# Time: 2019-04-28T15:24:04.309074+08:00
# Txn_start_ts: 405888132465033227
# User@Host: root[root] @ localhost [127.0.0.1]
# Exec_retry_count: 57
# Query_time: 0.216905
# Cop_time: 0.38 Process_time: 0.021 Request_count: 1 Total_keys: 637 Processed_keys: 436
# Is_internal: true
Expand Down Expand Up @@ -79,7 +80,7 @@ select * from t;`
}
recordString += str
}
expectRecordString := "2019-04-28 15:24:04.309074,405888132465033227,root,localhost,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,root,localhost,0,57,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;"
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
Expand Up @@ -718,6 +718,7 @@ var slowQueryCols = []columnInfo{
{name: variable.SlowLogUserStr, tp: mysql.TypeVarchar, size: 64},
{name: variable.SlowLogHostStr, tp: mysql.TypeVarchar, size: 64},
{name: variable.SlowLogConnIDStr, tp: mysql.TypeLonglong, size: 20, flag: mysql.UnsignedFlag},
{name: variable.SlowLogExecRetryCount, tp: mysql.TypeLonglong, size: 20, flag: mysql.UnsignedFlag},
{name: variable.SlowLogQueryTimeStr, tp: mysql.TypeDouble, size: 22},
{name: variable.SlowLogParseTimeStr, tp: mysql.TypeDouble, size: 22},
{name: variable.SlowLogCompileTimeStr, tp: mysql.TypeDouble, size: 22},
Expand Down
5 changes: 3 additions & 2 deletions infoschema/tables_test.go
View file
Open in desktop
Expand Up @@ -547,6 +547,7 @@ func prepareSlowLogfile(c *C, slowLogFileName string) {
# Txn_start_ts: 406315658548871171
# User@Host: root[root] @ localhost [127.0.0.1]
# Conn_ID: 6
# Exec_retry_count: 57
# Query_time: 4.895492
# Parse_time: 0.4
# Compile_time: 0.2
Expand Down Expand Up @@ -635,10 +636,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|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|localhost|6|57|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;"))
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|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|localhost|6|57|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;"))

// Test for long query.
f, err := os.OpenFile(slowLogFileName, os.O_CREATE|os.O_WRONLY, 0644)
Expand Down
6 changes: 6 additions & 0 deletions sessionctx/variable/session.go
View file
Open in desktop
Expand Up @@ -1610,6 +1610,8 @@ const (
SlowLogBackoffTotal = "Backoff_total"
// SlowLogWriteSQLRespTotal is the total time used to write response to client.
SlowLogWriteSQLRespTotal = "Write_sql_response_total"
// SlowLogExecRetryCount is the execution retry count.
SlowLogExecRetryCount = "Exec_retry_count"
)

// SlowQueryLogItems is a collection of items that should be included in the
Expand Down Expand Up @@ -1639,6 +1641,7 @@ type SlowQueryLogItems struct {
BackoffTotal time.Duration
WriteSQLRespTotal time.Duration
RewriteInfo RewritePhaseInfo
ExecRetryCount uint
}

// SlowLogFormat uses for formatting slow log.
Expand Down Expand Up @@ -1676,6 +1679,9 @@ func (s *SessionVars) SlowLogFormat(logItems *SlowQueryLogItems) string {
if s.ConnectionID != 0 {
writeSlowLogItem(&buf, SlowLogConnIDStr, strconv.FormatUint(s.ConnectionID, 10))
}
if logItems.ExecRetryCount > 0 {
writeSlowLogItem(&buf, SlowLogExecRetryCount, strconv.Itoa(int(logItems.ExecRetryCount)))
}
writeSlowLogItem(&buf, SlowLogQueryTimeStr, strconv.FormatFloat(logItems.TimeTotal.Seconds(), 'f', -1, 64))
writeSlowLogItem(&buf, SlowLogParseTimeStr, strconv.FormatFloat(logItems.TimeParse.Seconds(), 'f', -1, 64))
writeSlowLogItem(&buf, SlowLogCompileTimeStr, strconv.FormatFloat(logItems.TimeCompile.Seconds(), 'f', -1, 64))
Expand Down
2 changes: 2 additions & 0 deletions sessionctx/variable/session_test.go
View file
Open in desktop
Expand Up @@ -178,6 +178,7 @@ func (*testSessionSuite) TestSlowLogFormat(c *C) {
resultFields := `# Txn_start_ts: 406649736972468225
# User@Host: root[root] @ 192.168.0.1 [192.168.0.1]
# Conn_ID: 1
# Exec_retry_count: 3
# Query_time: 1
# Parse_time: 0.00000001
# Compile_time: 0.00000001
Expand Down Expand Up @@ -232,6 +233,7 @@ func (*testSessionSuite) TestSlowLogFormat(c *C) {
DurationPreprocessSubQuery: 2,
PreprocessSubQueries: 2,
},
ExecRetryCount: 3,
}
logString := seVar.SlowLogFormat(logItems)
c.Assert(logString, Equals, resultFields+"\n"+sql)
Expand Down