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.

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

* : statement summary should know the slow write is blocked on read lock lease #30166

Merged
merged 18 commits into from
Dec 1, 2021
Merged
Show file tree
Hide file tree
Changes from 8 commits
Commits
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
4 changes: 4 additions & 0 deletions executor/adapter.go
Original file line number Diff line number Diff line change
Expand Up @@ -1014,6 +1014,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) {
ResultRows: GetResultRowsCount(a.Ctx, a.Plan),
ExecRetryCount: a.retryCount,
IsExplicitTxn: sessVars.TxnCtx.IsExplicit,
IsWriteCacheTable: sessVars.StmtCtx.WaitLockLeaseTime > 0,
}
if a.retryCount > 0 {
slowItems.ExecRetryTime = costTime - sessVars.DurationParse - sessVars.DurationCompile - time.Since(a.retryStartTime)
Expand Down Expand Up @@ -1193,6 +1194,9 @@ func (a *ExecStmt) SummaryStmt(succ bool) {
if tikvExecDetailRaw != nil {
tikvExecDetail = *(tikvExecDetailRaw.(*util.ExecDetails))
}
if stmtCtx.WaitLockLeaseTime > 0 {
execDetail.BackoffSleep["waitLockLeaseForCacheTable"] = stmtCtx.WaitLockLeaseTime
}
stmtExecInfo := &stmtsummary.StmtExecInfo{
SchemaName: strings.ToLower(sessVars.CurrentDB),
OriginalSQL: sql,
Expand Down
2 changes: 1 addition & 1 deletion executor/slow_query.go
Original file line number Diff line number Diff line change
Expand Up @@ -738,7 +738,7 @@ func getColumnValueFactoryByName(sctx sessionctx.Context, colName string, column
return true, nil
}, nil
case variable.SlowLogPrepared, variable.SlowLogSucc, variable.SlowLogPlanFromCache, variable.SlowLogPlanFromBinding,
variable.SlowLogIsInternalStr, variable.SlowLogIsExplicitTxn:
variable.SlowLogIsInternalStr, variable.SlowLogIsExplicitTxn, variable.SlowLogIsWriteCacheTable:
return func(row []types.Datum, value string, tz *time.Location, checker *slowLogChecker) (valid bool, err error) {
v, err := strconv.ParseBool(value)
if err != nil {
Expand Down
4 changes: 2 additions & 2 deletions executor/slow_query_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -161,7 +161,7 @@ select * from t;`
`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,10,10,10,10,100,,,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,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,1,1,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,` +
`0,0,1,0,1,1,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,` +
`update t set i = 1;,select * from t;`
c.Assert(expectRecordString, Equals, recordString)

Expand All @@ -184,7 +184,7 @@ select * from t;`
`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,10,10,10,10,100,,,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,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,1,1,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,` +
`0,0,1,0,1,1,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,` +
`update t set i = 1;,select * from t;`
c.Assert(expectRecordString, Equals, recordString)

Expand Down
1 change: 1 addition & 0 deletions infoschema/tables.go
Original file line number Diff line number Diff line change
Expand Up @@ -869,6 +869,7 @@ var slowQueryCols = []columnInfo{
{name: variable.SlowLogPrepared, tp: mysql.TypeTiny, size: 1},
{name: variable.SlowLogSucc, tp: mysql.TypeTiny, size: 1},
{name: variable.SlowLogIsExplicitTxn, tp: mysql.TypeTiny, size: 1},
{name: variable.SlowLogIsWriteCacheTable, tp: mysql.TypeTiny, size: 1},
{name: variable.SlowLogPlanFromCache, tp: mysql.TypeTiny, size: 1},
{name: variable.SlowLogPlanFromBinding, tp: mysql.TypeTiny, size: 1},
{name: variable.SlowLogPlan, tp: mysql.TypeLongBlob, size: types.UnspecifiedLength},
Expand Down
8 changes: 4 additions & 4 deletions infoschema/tables_serial_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -556,13 +556,13 @@ func TestSlowQuery(t *testing.T) {
tk.MustExec(fmt.Sprintf("set @@tidb_slow_query_file='%v'", slowLogFileName))
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.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|100|10|10|10|100|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|10||0|1|0|1|0|abcd|60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4|update t set i = 2;|select * from t_slim;",
"2021-09-08|14:39:54.506967|427578666238083075|root|172.16.0.0|40507|0|0|25.571605962|0.002923536|0.006800973|0.002100764|0|0|0|0.000015801|25.542014572|0|0.002294647|0.000605473|12.483|[tikvRPC regionMiss tikvRPC regionMiss regionMiss]|0|0|624|172064|60|0|0|0|0|0|0|0|0|0|0|0|0|0|0|rtdb||0|124acb3a0bec903176baca5f9da00b4e7512a41c93b417923f26502edeb324cc||0|0|0||0|0|0||856544|0|86.635049185|0.015486658|100.054|0|0||0|1|0|0|0||||INSERT INTO ...;",
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.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|100|10|10|10|100|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|10||0|1|0|0|1|0|abcd|60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4|update t set i = 2;|select * from t_slim;",
"2021-09-08|14:39:54.506967|427578666238083075|root|172.16.0.0|40507|0|0|25.571605962|0.002923536|0.006800973|0.002100764|0|0|0|0.000015801|25.542014572|0|0.002294647|0.000605473|12.483|[tikvRPC regionMiss tikvRPC regionMiss regionMiss]|0|0|624|172064|60|0|0|0|0|0|0|0|0|0|0|0|0|0|0|rtdb||0|124acb3a0bec903176baca5f9da00b4e7512a41c93b417923f26502edeb324cc||0|0|0||0|0|0||856544|0|86.635049185|0.015486658|100.054|0|0||0|1|0|0|0|0||||INSERT INTO ...;",
))
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.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|100|10|10|10|100|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|10||0|1|0|1|0|abcd|60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4|update t set i = 2;|select * from t_slim;",
"2021-09-08|06:39:54.506967|427578666238083075|root|172.16.0.0|40507|0|0|25.571605962|0.002923536|0.006800973|0.002100764|0|0|0|0.000015801|25.542014572|0|0.002294647|0.000605473|12.483|[tikvRPC regionMiss tikvRPC regionMiss regionMiss]|0|0|624|172064|60|0|0|0|0|0|0|0|0|0|0|0|0|0|0|rtdb||0|124acb3a0bec903176baca5f9da00b4e7512a41c93b417923f26502edeb324cc||0|0|0||0|0|0||856544|0|86.635049185|0.015486658|100.054|0|0||0|1|0|0|0||||INSERT INTO ...;",
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|100|10|10|10|100|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|10||0|1|0|0|1|0|abcd|60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4|update t set i = 2;|select * from t_slim;",
"2021-09-08|06:39:54.506967|427578666238083075|root|172.16.0.0|40507|0|0|25.571605962|0.002923536|0.006800973|0.002100764|0|0|0|0.000015801|25.542014572|0|0.002294647|0.000605473|12.483|[tikvRPC regionMiss tikvRPC regionMiss regionMiss]|0|0|624|172064|60|0|0|0|0|0|0|0|0|0|0|0|0|0|0|rtdb||0|124acb3a0bec903176baca5f9da00b4e7512a41c93b417923f26502edeb324cc||0|0|0||0|0|0||856544|0|86.635049185|0.015486658|100.054|0|0||0|1|0|0|0|0||||INSERT INTO ...;",
))

// Test for long query.
Expand Down
3 changes: 3 additions & 0 deletions sessionctx/stmtctx/stmtctx.go
Original file line number Diff line number Diff line change
Expand Up @@ -201,6 +201,9 @@ type StatementContext struct {

// LogicalOptimizeTrace indicates the trace for optimize
LogicalOptimizeTrace *tracing.LogicalOptimizeTracer

// WaitLockLease is the duration of cached table read lease expiration time.
WaitLockLeaseTime time.Duration
}

// StmtHints are SessionVars related sql hints.
Expand Down
6 changes: 6 additions & 0 deletions sessionctx/variable/session.go
Original file line number Diff line number Diff line change
Expand Up @@ -2013,6 +2013,8 @@ const (
SlowLogResultRows = "Result_rows"
// SlowLogIsExplicitTxn is used to indicate whether this sql execute in explicit transaction or not.
SlowLogIsExplicitTxn = "IsExplicitTxn"
// SlowLogIsWriteCacheTable is used to indicate whether writing to the cache table need to wait for the read lock to expire.
SlowLogIsWriteCacheTable = "IsWriteCacheTable"
)

// SlowQueryLogItems is a collection of items that should be included in the
Expand Down Expand Up @@ -2049,6 +2051,7 @@ type SlowQueryLogItems struct {
ExecRetryTime time.Duration
ResultRows int64
IsExplicitTxn bool
IsWriteCacheTable bool
}

// SlowLogFormat uses for formatting slow log.
Expand Down Expand Up @@ -2214,6 +2217,9 @@ func (s *SessionVars) SlowLogFormat(logItems *SlowQueryLogItems) string {
writeSlowLogItem(&buf, SlowLogResultRows, strconv.FormatInt(logItems.ResultRows, 10))
writeSlowLogItem(&buf, SlowLogSucc, strconv.FormatBool(logItems.Succ))
writeSlowLogItem(&buf, SlowLogIsExplicitTxn, strconv.FormatBool(logItems.IsExplicitTxn))
if s.StmtCtx.WaitLockLeaseTime > 0 {
writeSlowLogItem(&buf, SlowLogIsWriteCacheTable, strconv.FormatBool(logItems.IsWriteCacheTable))
}
if len(logItems.Plan) != 0 {
writeSlowLogItem(&buf, SlowLogPlan, logItems.Plan)
}
Expand Down
11 changes: 7 additions & 4 deletions sessionctx/variable/session_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -155,6 +155,7 @@ func TestSlowLogFormat(t *testing.T) {
seVar.ConnectionID = 1
seVar.CurrentDB = "test"
seVar.InRestrictedSQL = true
seVar.StmtCtx.WaitLockLeaseTime = 1
txnTS := uint64(406649736972468225)
costTime := time.Second
execDetail := execdetails.ExecDetails{
Expand Down Expand Up @@ -235,7 +236,8 @@ func TestSlowLogFormat(t *testing.T) {
# Write_sql_response_total: 1
# Result_rows: 12345
# Succ: true
# IsExplicitTxn: true`
# IsExplicitTxn: true
# IsWriteCacheTable: true`
sql := "select * from t;"
_, digest := parser.NormalizeDigest(sql)
logItems := &variable.SlowQueryLogItems{
Expand Down Expand Up @@ -268,9 +270,10 @@ func TestSlowLogFormat(t *testing.T) {
DurationPreprocessSubQuery: 2,
PreprocessSubQueries: 2,
},
ExecRetryCount: 3,
ExecRetryTime: 5*time.Second + time.Millisecond*100,
IsExplicitTxn: true,
ExecRetryCount: 3,
ExecRetryTime: 5*time.Second + time.Millisecond*100,
IsExplicitTxn: true,
IsWriteCacheTable: true,
}
logString := seVar.SlowLogFormat(logItems)
require.Equal(t, resultFields+"\n"+sql, logString)
Expand Down
6 changes: 6 additions & 0 deletions table/tables/cache.go
Original file line number Diff line number Diff line change
Expand Up @@ -198,10 +198,12 @@ func (c *cachedTable) AddRecord(ctx sessionctx.Context, r []types.Datum, opts ..
return nil, err
}
now := txn.StartTS()
start := time.Now()
JayLZhou marked this conversation as resolved.
Show resolved Hide resolved
err = c.handle.LockForWrite(context.Background(), c.Meta().ID, now, leaseFromTS(now))
if err != nil {
return nil, errors.Trace(err)
}
ctx.GetSessionVars().StmtCtx.WaitLockLeaseTime += time.Since(start)
return c.TableCommon.AddRecord(ctx, r, opts...)
}

Expand All @@ -212,10 +214,12 @@ func (c *cachedTable) UpdateRecord(ctx context.Context, sctx sessionctx.Context,
return err
}
now := txn.StartTS()
start := time.Now()
err = c.handle.LockForWrite(ctx, c.Meta().ID, now, leaseFromTS(now))
if err != nil {
return errors.Trace(err)
}
sctx.GetSessionVars().StmtCtx.WaitLockLeaseTime += time.Since(start)
return c.TableCommon.UpdateRecord(ctx, sctx, h, oldData, newData, touched)
}

Expand All @@ -226,10 +230,12 @@ func (c *cachedTable) RemoveRecord(ctx sessionctx.Context, h kv.Handle, r []type
return err
}
now := txn.StartTS()
start := time.Now()
err = c.handle.LockForWrite(context.Background(), c.Meta().ID, now, leaseFromTS(now))
if err != nil {
return errors.Trace(err)
}
ctx.GetSessionVars().StmtCtx.WaitLockLeaseTime += time.Since(start)
return c.TableCommon.RemoveRecord(ctx, h, r)
}

Expand Down
22 changes: 22 additions & 0 deletions table/tables/cache_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -417,3 +417,25 @@ func TestRenewLease(t *testing.T) {
}
require.True(t, i < 20)
}

func TestCacheTableWriteOperatorWaitLockLease(t *testing.T) {
store, clean := testkit.CreateMockStore(t)
defer clean()
tk := testkit.NewTestKit(t, store)
tk.MustExec("use test")
se := tk.Session()
tk.MustExec("drop table if exists wait_tb1")
tk.MustExec("create table wait_tb1(id int)")
tk.MustExec("alter table wait_tb1 cache")
tk.MustExec("select *from wait_tb1")
var i int
for i = 0; i < 10; i++ {
time.Sleep(100 * time.Millisecond)
if tk.HasPlan("select *from wait_tb1", "UnionScan") {
break
}
}
require.True(t, i < 10)
tk.MustExec("insert into wait_tb1 values(1)")
require.True(t, se.GetSessionVars().StmtCtx.WaitLockLeaseTime > 0)
}
2 changes: 1 addition & 1 deletion util/stmtsummary/statement_summary.go
Original file line number Diff line number Diff line change
Expand Up @@ -360,7 +360,7 @@ type BindableStmt struct {
Collation string
}

// GetMoreThanOnceBindableStmt gets users' select/update/delete SQLs that occurred more than the specified count.
// GetMoreThanCntBindableStmt gets users' select/update/delete SQLs that occurred more than the specified count.
func (ssMap *stmtSummaryByDigestMap) GetMoreThanCntBindableStmt(cnt int64) []*BindableStmt {
ssMap.Lock()
values := ssMap.summaryMap.Values()
Expand Down