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

close #39713
pingcap · Dec 13, 2022 · 1e7c6dd · 1e7c6dd
1 parent 4b3a442
commit 1e7c6dd
Show file tree

Hide file tree

Showing 5 changed files with 58 additions and 0 deletions.
diff --git 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
@@ -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
@@ -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/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")
+	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)
+}
diff --git a/sessiontxn/txn_rc_tso_optimize_test.go b/sessiontxn/txn_rc_tso_optimize_test.go
@@ -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)
+}