executor: add metric to trace tikvTxn LockKeys time consume (#14189)

kv/kv.go

@@ -194,10 +194,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
+	LockTimeWaited        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",
+		})
 )

store/tikv/2pc.go

@@ -767,6 +767,7 @@ func (action actionPessimisticLock) handleSingleBatch(c *twoPhaseCommitter, bo *
 					return ErrLockWaitTimeout
 				}
 			}
+			atomic.StoreInt32(&action.LockCtx.PessimisticLockWaited, 1)
 		}
 
 		// Handle the killed flag when waiting for the pessimistic lock.

store/tikv/txn.go

@@ -369,6 +369,15 @@ func (txn *tikvTxn) rollbackPessimisticLocks() error {
 // 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 > 0 {
+				lockCtx.LockTimeWaited = time.Since(lockCtx.WaitStartTime)
+				metrics.TiKVPessimisticLockKeysDuration.Observe(lockCtx.LockTimeWaited.Seconds())
+			}
+		}
+	}()
 	keys := make([][]byte, 0, len(keysInput))
 	txn.mu.Lock()
 	for _, key := range keysInput {
@@ -406,7 +415,7 @@ func (txn *tikvTxn) LockKeys(ctx context.Context, lockCtx *kv.LockCtx, keysInput
 		// If the number of keys greater than 1, it can be on different region,
 		// concurrently execute on multiple regions may lead to deadlock.
 		txn.committer.isFirstLock = len(txn.lockKeys) == 0 && len(keys) == 1
-		err := txn.committer.pessimisticLockKeys(bo, lockCtx, keys)
+		err = txn.committer.pessimisticLockKeys(bo, lockCtx, keys)
 		if lockCtx.Killed != nil {
 			// If the kill signal is received during waiting for pessimisticLock,
 			// pessimisticLockKeys would handle the error but it doesn't reset the flag.