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

SlowLog: Update Wait_TS field in slow log for every sql #39843

Merged
merged 7 commits into from
Dec 13, 2022
Merged

SlowLog: Update Wait_TS field in slow log for every sql #39843

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
1293cd9
set wait_ts time correctly
TonsnakeLin Dec 12, 2022
763f917
add test case
TonsnakeLin Dec 12, 2022
5a70352
fix format
TonsnakeLin Dec 13, 2022
1324e27
remove unnecessary code
TonsnakeLin Dec 13, 2022
37ebf08
Merge branch 'master' of https://github.com/pingcap/tidb into wait-ts…
TonsnakeLin Dec 13, 2022
ed108d7
Merge branch 'master' into wait-ts-update
ti-chi-bot Dec 13, 2022
f03cc98
Merge branch 'master' into wait-ts-update
ti-chi-bot Dec 13, 2022
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/executor.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2167,6 +2167,7 @@ func ResetContextOfStmt(ctx sessionctx.Context, s ast.StmtNode) (err error) {
vars.ClearStmtVars()
vars.PrevFoundInBinding = vars.FoundInBinding
vars.FoundInBinding = false
vars.DurationWaitTS = 0
Copy link
Contributor

Choose a reason for hiding this comment

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

Where is it used for slow log generation or information filling?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

https://github.com/pingcap/tidb/blob/master/executor/adapter.go#L1504
Do you worry about the retry operation which will only keep the last wait_ts time? In fact, most of diagnostic fields keep the value of last time when doing retry.

return
}

Expand Down
3 changes: 3 additions & 0 deletions sessiontxn/isolation/readcommitted.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@ package isolation

import (
"context"
"time"

"github.com/pingcap/errors"
"github.com/pingcap/failpoint"
Expand Down Expand Up @@ -186,9 +187,11 @@ func (p *PessimisticRCTxnContextProvider) getStmtTS() (ts uint64, err error) {
}

p.prepareStmtTS()
start := time.Now()
if ts, err = p.stmtTSFuture.Wait(); err != nil {
return 0, err
}
p.sctx.GetSessionVars().DurationWaitTS += time.Since(start)

txn.SetOption(kv.SnapshotTS, ts)
p.stmtTS = ts
Expand Down
3 changes: 3 additions & 0 deletions sessiontxn/isolation/repeatable_read.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@ package isolation

import (
"context"
"time"

"github.com/pingcap/errors"
"github.com/pingcap/failpoint"
Expand Down Expand Up @@ -83,9 +84,11 @@ func (p *PessimisticRRTxnContextProvider) getForUpdateTs() (ts uint64, err error
txnCtx := p.sctx.GetSessionVars().TxnCtx
futureTS := newOracleFuture(p.ctx, p.sctx, txnCtx.TxnScope)

start := time.Now()
if ts, err = futureTS.Wait(); err != nil {
return 0, err
}
p.sctx.GetSessionVars().DurationWaitTS += time.Since(start)

txnCtx.SetForUpdateTS(ts)
txn.SetOption(kv.SnapshotTS, ts)
Expand Down
22 changes: 22 additions & 0 deletions sessiontxn/isolation/repeatable_read_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -678,3 +678,25 @@ func initializeRepeatableReadProvider(t *testing.T, tk *testkit.TestKit, active
require.NoError(t, tk.Session().PrepareTxnCtx(context.TODO()))
return assert.CheckAndGetProvider(t)
}

func TestRRWaitTSTimeInSlowLog(t *testing.T) {
store := testkit.CreateMockStore(t)

tk := testkit.NewTestKit(t, store)
se := tk.Session()

tk.MustExec("use test")
tk.MustExec("create table t (id int primary key, v int)")
tk.MustExec("insert into t values (1, 1)")

tk.MustExec("begin pessimistic")
waitTS1 := se.GetSessionVars().DurationWaitTS
tk.MustExec("update t set v = v + 10 where id = 1")
waitTS2 := se.GetSessionVars().DurationWaitTS
tk.MustExec("delete from t")
waitTS3 := se.GetSessionVars().DurationWaitTS
tk.MustExec("commit")
require.NotEqual(t, waitTS1, waitTS2)
require.NotEqual(t, waitTS1, waitTS3)
require.NotEqual(t, waitTS2, waitTS3)
}
29 changes: 29 additions & 0 deletions sessiontxn/txn_rc_tso_optimize_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -790,3 +790,32 @@ func TestConflictErrorsUseRcWriteCheckTs(t *testing.T) {

require.NoError(t, failpoint.Disable("github.com/pingcap/tidb/executor/assertPessimisticLockErr"))
}

func TestRcWaitTSInSlowLog(t *testing.T) {
store := testkit.CreateMockStore(t)
tk := testkit.NewTestKit(t, store)

tk.MustExec("set global transaction_isolation = 'READ-COMMITTED'")
tk.RefreshSession()
sctx := tk.Session()

tk.MustExec("use test")
tk.MustExec("drop table if exists t1")
tk.MustExec("create table t1(id1 int, id2 int, id3 int, PRIMARY KEY(id1), UNIQUE KEY udx_id2 (id2))")
tk.MustExec("insert into t1 values (1, 1, 1), (2, 2, 2), (3, 3, 3)")

res := tk.MustQuery("show variables like 'transaction_isolation'")
require.Equal(t, "READ-COMMITTED", res.Rows()[0][1])
sctx.SetValue(sessiontxn.TsoRequestCount, 0)

tk.MustExec("begin pessimistic")
waitTs1 := sctx.GetSessionVars().DurationWaitTS
tk.MustExec("update t1 set id3 = id3 + 10 where id1 = 1")
waitTs2 := sctx.GetSessionVars().DurationWaitTS
tk.MustExec("update t1 set id3 = id3 + 10 where id1 > 3 and id1 < 6")
waitTs3 := sctx.GetSessionVars().DurationWaitTS
tk.MustExec("commit")
require.NotEqual(t, waitTs1, waitTs2)
require.NotEqual(t, waitTs1, waitTs2)
require.NotEqual(t, waitTs2, waitTs3)
}