add lock keys duration metric

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

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,
 	}
 }
 

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.

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",
+		})
 )

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

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.

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 {