From 1a32e51ecb7d5a0f9eca42175f64ae6f6eeb4ee2 Mon Sep 17 00:00:00 2001
From: cfzjywxk <lsswxr@163.com>
Date: Tue, 24 Dec 2019 20:03:39 +0800
Subject: [PATCH] executor: add lock keys duration metric (#14194)

---
 executor/adapter.go           |  7 +------
 executor/executor.go          | 10 ++++++----
 kv/kv.go                      | 10 ++++++----
 metrics/tikvclient.go         |  8 ++++++++
 sessionctx/stmtctx/stmtctx.go |  6 ++++--
 store/tikv/2pc.go             |  3 +++
 store/tikv/txn.go             | 12 ++++++++++++
 7 files changed, 40 insertions(+), 16 deletions(-)

diff --git a/executor/adapter.go b/executor/adapter.go
index ff303e9d27730..a617eafdccfeb 100644
--- a/executor/adapter.go
+++ b/executor/adapter.go
@@ -457,12 +457,7 @@ func (a *ExecStmt) handlePessimisticDML(ctx context.Context, e Executor) error {
 			return nil
 		}
 		seVars := sctx.GetSessionVars()
-		lockCtx := &kv.LockCtx{
-			Killed:        &seVars.Killed,
-			ForUpdateTS:   txnCtx.GetForUpdateTS(),
-			LockWaitTime:  seVars.LockWaitTimeout,
-			WaitStartTime: seVars.StmtCtx.GetLockWaitStartTime(),
-		}
+		lockCtx := newLockCtx(seVars, seVars.LockWaitTimeout)
 		err = txn.LockKeys(ctx, lockCtx, keys...)
 		if err == nil {
 			return nil
diff --git a/executor/executor.go b/executor/executor.go
index e9398d02aad18..74f3077687ce7 100644
--- a/executor/executor.go
+++ b/executor/executor.go
@@ -791,10 +791,12 @@ func (e *SelectLockExec) Next(ctx context.Context, req *chunk.Chunk) error {
 
 func newLockCtx(seVars *variable.SessionVars, lockWaitTime int64) *kv.LockCtx {
 	return &kv.LockCtx{
-		Killed:        &seVars.Killed,
-		ForUpdateTS:   seVars.TxnCtx.GetForUpdateTS(),
-		LockWaitTime:  lockWaitTime,
-		WaitStartTime: seVars.StmtCtx.GetLockWaitStartTime(),
+		Killed:                &seVars.Killed,
+		ForUpdateTS:           seVars.TxnCtx.GetForUpdateTS(),
+		LockWaitTime:          lockWaitTime,
+		WaitStartTime:         seVars.StmtCtx.GetLockWaitStartTime(),
+		PessimisticLockWaited: &seVars.StmtCtx.PessimisticLockWaited,
+		LockKeysDuration:      &seVars.StmtCtx.LockKeysDuration,
 	}
 }
 
diff --git a/kv/kv.go b/kv/kv.go
index 98c3d444c2dc1..2e862236ea64c 100644
--- a/kv/kv.go
+++ b/kv/kv.go
@@ -166,10 +166,12 @@ type Transaction interface {
 
 // LockCtx contains information for LockKeys method.
 type LockCtx struct {
-	Killed        *uint32
-	ForUpdateTS   uint64
-	LockWaitTime  int64
-	WaitStartTime time.Time
+	Killed                *uint32
+	ForUpdateTS           uint64
+	LockWaitTime          int64
+	WaitStartTime         time.Time
+	PessimisticLockWaited *int32
+	LockKeysDuration      *time.Duration
 }
 
 // Client is used to send request to KV layer.
diff --git a/metrics/tikvclient.go b/metrics/tikvclient.go
index f1e52ddde43ab..8c12c4fa384e3 100644
--- a/metrics/tikvclient.go
+++ b/metrics/tikvclient.go
@@ -232,4 +232,12 @@ var (
 			Help:      "Bucketed histogram of the txn_heartbeat request duration.",
 			Buckets:   prometheus.ExponentialBuckets(0.001, 2, 18), // 1ms ~ 292s
 		}, []string{LblType})
+	TiKVPessimisticLockKeysDuration = prometheus.NewHistogram(
+		prometheus.HistogramOpts{
+			Namespace: "tidb",
+			Subsystem: "tikvclient",
+			Name:      "pessimistic_lock_keys_duration",
+			Buckets:   prometheus.ExponentialBuckets(0.001, 2, 24), // 1ms ~ 16777s
+			Help:      "tidb txn pessimistic lock keys duration",
+		})
 )
diff --git a/sessionctx/stmtctx/stmtctx.go b/sessionctx/stmtctx/stmtctx.go
index 2139b81e1a6b7..17b220f3fa1e2 100644
--- a/sessionctx/stmtctx/stmtctx.go
+++ b/sessionctx/stmtctx/stmtctx.go
@@ -132,8 +132,10 @@ type StatementContext struct {
 		normalized string
 		digest     string
 	}
-	Tables            []TableEntry
-	lockWaitStartTime *time.Time // LockWaitStartTime stores the pessimistic lock wait start time
+	Tables                []TableEntry
+	lockWaitStartTime     *time.Time // LockWaitStartTime stores the pessimistic lock wait start time
+	PessimisticLockWaited int32
+	LockKeysDuration      time.Duration
 }
 
 // GetNowTsCached getter for nowTs, if not set get now time and cache it
diff --git a/store/tikv/2pc.go b/store/tikv/2pc.go
index 349b67c7b1b86..de6af63718f10 100644
--- a/store/tikv/2pc.go
+++ b/store/tikv/2pc.go
@@ -835,6 +835,9 @@ func (action actionPessimisticLock) handleSingleBatch(c *twoPhaseCommitter, bo *
 					return ErrLockWaitTimeout
 				}
 			}
+			if action.LockCtx.PessimisticLockWaited != nil {
+				atomic.StoreInt32(action.LockCtx.PessimisticLockWaited, 1)
+			}
 		}
 
 		// Handle the killed flag when waiting for the pessimistic lock.
diff --git a/store/tikv/txn.go b/store/tikv/txn.go
index 132a9fe9c2823..37d7b22a59648 100644
--- a/store/tikv/txn.go
+++ b/store/tikv/txn.go
@@ -356,6 +356,18 @@ func (txn *tikvTxn) rollbackPessimisticLocks() error {
 // LockKeys input param lockWaitTime in ms, except that kv.LockAlwaysWait(0) means always wait lock, kv.LockNowait(-1) means nowait lock
 func (txn *tikvTxn) LockKeys(ctx context.Context, lockCtx *kv.LockCtx, keysInput ...kv.Key) error {
 	// Exclude keys that are already locked.
+	var err error
+	defer func() {
+		if err == nil {
+			if lockCtx.PessimisticLockWaited != nil {
+				if atomic.LoadInt32(lockCtx.PessimisticLockWaited) > 0 {
+					timeWaited := time.Since(lockCtx.WaitStartTime)
+					metrics.TiKVPessimisticLockKeysDuration.Observe(timeWaited.Seconds())
+					*lockCtx.LockKeysDuration = timeWaited
+				}
+			}
+		}
+	}()
 	keys := make([][]byte, 0, len(keysInput))
 	txn.mu.Lock()
 	for _, key := range keysInput {