From 1293cd942b5b199d33f685e61e3c9f809b6fbf27 Mon Sep 17 00:00:00 2001 From: TonsnakeLin Date: Mon, 12 Dec 2022 17:39:09 +0800 Subject: [PATCH 1/4] set wait_ts time correctly Signed-off-by: TonsnakeLin --- executor/executor.go | 1 + sessiontxn/isolation/readcommitted.go | 3 +++ sessiontxn/isolation/repeatable_read.go | 3 +++ sessiontxn/txn_rc_tso_optimize_test.go | 31 +++++++++++++++++++++++++ 4 files changed, 38 insertions(+) diff --git a/executor/executor.go b/executor/executor.go index cb96942e8f776..90622ce52e527 100644 --- a/executor/executor.go +++ b/executor/executor.go @@ -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 return } diff --git a/sessiontxn/isolation/readcommitted.go b/sessiontxn/isolation/readcommitted.go index 8752eb5b35e11..ca198fda6b9e7 100644 --- a/sessiontxn/isolation/readcommitted.go +++ b/sessiontxn/isolation/readcommitted.go @@ -16,6 +16,7 @@ package isolation import ( "context" + "time" "github.com/pingcap/errors" "github.com/pingcap/failpoint" @@ -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 diff --git a/sessiontxn/isolation/repeatable_read.go b/sessiontxn/isolation/repeatable_read.go index 18fa2ebd8608c..043998384951c 100644 --- a/sessiontxn/isolation/repeatable_read.go +++ b/sessiontxn/isolation/repeatable_read.go @@ -16,6 +16,7 @@ package isolation import ( "context" + "time" "github.com/pingcap/errors" "github.com/pingcap/failpoint" @@ -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) diff --git a/sessiontxn/txn_rc_tso_optimize_test.go b/sessiontxn/txn_rc_tso_optimize_test.go index 59bbf0de330bc..625adbd8bfd72 100644 --- a/sessiontxn/txn_rc_tso_optimize_test.go +++ b/sessiontxn/txn_rc_tso_optimize_test.go @@ -790,3 +790,34 @@ 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) + + // ctx := context.Background() + 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") + wait_ts1 := sctx.GetSessionVars().DurationWaitTS + fmt.Println("wait_ts1:", wait_ts1) + /* + tk.MustExec("update t1 set id3 = id3 + 10 where id1 = 1") + tk.MustExec("update t2 set id3 = id3 + 10 where id1 = 1") + tk.MustExec("update t2 set id3 = id3 + 10 where id1 > 3 and id1 < 6") + tk.MustExec("select id1+id2 as x from t1 where id1 = 9 for update") + + */ +} From 763f917f7080d7cc52cfa392dad05d1819a53123 Mon Sep 17 00:00:00 2001 From: TonsnakeLin Date: Mon, 12 Dec 2022 20:26:30 +0800 Subject: [PATCH 2/4] add test case Signed-off-by: TonsnakeLin --- sessiontxn/isolation/repeatable_read_test.go | 22 ++++++++++++++++++++ sessiontxn/txn_rc_tso_optimize_test.go | 16 +++++++------- 2 files changed, 30 insertions(+), 8 deletions(-) diff --git a/sessiontxn/isolation/repeatable_read_test.go b/sessiontxn/isolation/repeatable_read_test.go index da798f05c2152..618dd614da374 100644 --- a/sessiontxn/isolation/repeatable_read_test.go +++ b/sessiontxn/isolation/repeatable_read_test.go @@ -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") + wait_ts1 := se.GetSessionVars().DurationWaitTS + tk.MustExec("update t set v = v + 10 where id = 1") + wait_ts2 := se.GetSessionVars().DurationWaitTS + tk.MustExec("delete from t") + wait_ts3 := se.GetSessionVars().DurationWaitTS + tk.MustExec("commit") + require.NotEqual(t, wait_ts1, wait_ts2) + require.NotEqual(t, wait_ts1, wait_ts3) + require.NotEqual(t, wait_ts2, wait_ts3) +} diff --git a/sessiontxn/txn_rc_tso_optimize_test.go b/sessiontxn/txn_rc_tso_optimize_test.go index 625adbd8bfd72..ee14a2a9cde9f 100644 --- a/sessiontxn/txn_rc_tso_optimize_test.go +++ b/sessiontxn/txn_rc_tso_optimize_test.go @@ -812,12 +812,12 @@ func TestRcWaitTSInSlowLog(t *testing.T) { tk.MustExec("begin pessimistic") wait_ts1 := sctx.GetSessionVars().DurationWaitTS - fmt.Println("wait_ts1:", wait_ts1) - /* - tk.MustExec("update t1 set id3 = id3 + 10 where id1 = 1") - tk.MustExec("update t2 set id3 = id3 + 10 where id1 = 1") - tk.MustExec("update t2 set id3 = id3 + 10 where id1 > 3 and id1 < 6") - tk.MustExec("select id1+id2 as x from t1 where id1 = 9 for update") - - */ + tk.MustExec("update t1 set id3 = id3 + 10 where id1 = 1") + wait_ts2 := sctx.GetSessionVars().DurationWaitTS + tk.MustExec("update t1 set id3 = id3 + 10 where id1 > 3 and id1 < 6") + wait_ts3 := sctx.GetSessionVars().DurationWaitTS + tk.MustExec("commit") + require.NotEqual(t, wait_ts1, wait_ts2) + require.NotEqual(t, wait_ts1, wait_ts3) + require.NotEqual(t, wait_ts2, wait_ts3) } From 5a70352d0814f788a4dc68ef4be89e674712df94 Mon Sep 17 00:00:00 2001 From: TonsnakeLin Date: Tue, 13 Dec 2022 08:55:36 +0800 Subject: [PATCH 3/4] fix format Signed-off-by: TonsnakeLin --- sessiontxn/isolation/repeatable_read_test.go | 12 ++++++------ sessiontxn/txn_rc_tso_optimize_test.go | 12 ++++++------ 2 files changed, 12 insertions(+), 12 deletions(-) diff --git a/sessiontxn/isolation/repeatable_read_test.go b/sessiontxn/isolation/repeatable_read_test.go index 618dd614da374..085b64c34cc38 100644 --- a/sessiontxn/isolation/repeatable_read_test.go +++ b/sessiontxn/isolation/repeatable_read_test.go @@ -690,13 +690,13 @@ func TestRRWaitTSTimeInSlowLog(t *testing.T) { tk.MustExec("insert into t values (1, 1)") tk.MustExec("begin pessimistic") - wait_ts1 := se.GetSessionVars().DurationWaitTS + waitTS1 := se.GetSessionVars().DurationWaitTS tk.MustExec("update t set v = v + 10 where id = 1") - wait_ts2 := se.GetSessionVars().DurationWaitTS + waitTS2 := se.GetSessionVars().DurationWaitTS tk.MustExec("delete from t") - wait_ts3 := se.GetSessionVars().DurationWaitTS + waitTS3 := se.GetSessionVars().DurationWaitTS tk.MustExec("commit") - require.NotEqual(t, wait_ts1, wait_ts2) - require.NotEqual(t, wait_ts1, wait_ts3) - require.NotEqual(t, wait_ts2, wait_ts3) + require.NotEqual(t, waitTS1, waitTS2) + require.NotEqual(t, waitTS1, waitTS3) + require.NotEqual(t, waitTS2, waitTS3) } diff --git a/sessiontxn/txn_rc_tso_optimize_test.go b/sessiontxn/txn_rc_tso_optimize_test.go index ee14a2a9cde9f..f89a1c7ce9b97 100644 --- a/sessiontxn/txn_rc_tso_optimize_test.go +++ b/sessiontxn/txn_rc_tso_optimize_test.go @@ -811,13 +811,13 @@ func TestRcWaitTSInSlowLog(t *testing.T) { sctx.SetValue(sessiontxn.TsoRequestCount, 0) tk.MustExec("begin pessimistic") - wait_ts1 := sctx.GetSessionVars().DurationWaitTS + waitTs1 := sctx.GetSessionVars().DurationWaitTS tk.MustExec("update t1 set id3 = id3 + 10 where id1 = 1") - wait_ts2 := sctx.GetSessionVars().DurationWaitTS + waitTs2 := sctx.GetSessionVars().DurationWaitTS tk.MustExec("update t1 set id3 = id3 + 10 where id1 > 3 and id1 < 6") - wait_ts3 := sctx.GetSessionVars().DurationWaitTS + waitTs3 := sctx.GetSessionVars().DurationWaitTS tk.MustExec("commit") - require.NotEqual(t, wait_ts1, wait_ts2) - require.NotEqual(t, wait_ts1, wait_ts3) - require.NotEqual(t, wait_ts2, wait_ts3) + require.NotEqual(t, waitTs1, waitTs2) + require.NotEqual(t, waitTs1, waitTs2) + require.NotEqual(t, waitTs2, waitTs3) } From 1324e27d51795955ad55a122a1ffe0681de9b7d0 Mon Sep 17 00:00:00 2001 From: TonsnakeLin Date: Tue, 13 Dec 2022 13:34:35 +0800 Subject: [PATCH 4/4] remove unnecessary code Signed-off-by: TonsnakeLin --- sessiontxn/txn_rc_tso_optimize_test.go | 2 -- 1 file changed, 2 deletions(-) diff --git a/sessiontxn/txn_rc_tso_optimize_test.go b/sessiontxn/txn_rc_tso_optimize_test.go index f89a1c7ce9b97..f321d40340496 100644 --- a/sessiontxn/txn_rc_tso_optimize_test.go +++ b/sessiontxn/txn_rc_tso_optimize_test.go @@ -793,8 +793,6 @@ func TestConflictErrorsUseRcWriteCheckTs(t *testing.T) { func TestRcWaitTSInSlowLog(t *testing.T) { store := testkit.CreateMockStore(t) - - // ctx := context.Background() tk := testkit.NewTestKit(t, store) tk.MustExec("set global transaction_isolation = 'READ-COMMITTED'")