From 68b9885fb1caceaf45b476e94764706d3a13ea44 Mon Sep 17 00:00:00 2001
From: cfzjywxk <lsswxr@163.com>
Date: Mon, 23 Dec 2019 19:00:06 +0800
Subject: [PATCH 1/2] add metric to trace tikvTxn LockKeys time consume

---
 kv/kv.go              | 10 ++++++----
 metrics/tikvclient.go |  8 ++++++++
 store/tikv/2pc.go     |  1 +
 store/tikv/txn.go     | 11 ++++++++++-
 4 files changed, 25 insertions(+), 5 deletions(-)

diff --git a/kv/kv.go b/kv/kv.go
index 0f3a75fa61425..72fbb57113625 100644
--- a/kv/kv.go
+++ b/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.
diff --git a/metrics/tikvclient.go b/metrics/tikvclient.go
index 6d4bc1d7ad0eb..2ba0b36b6333f 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, 30), // 1ms ~ 1073741s
+			Help:      "tidb txn pessimistic lock keys duration",
+		})
 )
diff --git a/store/tikv/2pc.go b/store/tikv/2pc.go
index 3431fe1b0d165..55ed70d573aa9 100644
--- a/store/tikv/2pc.go
+++ b/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.
diff --git a/store/tikv/txn.go b/store/tikv/txn.go
index 426a41f345b0a..4bd81721401af 100644
--- a/store/tikv/txn.go
+++ b/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.

From 8d2d814ddaf0b13b41c83ec516d6658e5ef997cc Mon Sep 17 00:00:00 2001
From: cfzjywxk <lsswxr@163.com>
Date: Mon, 23 Dec 2019 19:22:17 +0800
Subject: [PATCH 2/2] reduce bucket

---
 metrics/tikvclient.go | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/metrics/tikvclient.go b/metrics/tikvclient.go
index 2ba0b36b6333f..2b4303af44fdd 100644
--- a/metrics/tikvclient.go
+++ b/metrics/tikvclient.go
@@ -237,7 +237,7 @@ var (
 			Namespace: "tidb",
 			Subsystem: "tikvclient",
 			Name:      "pessimistic_lock_keys_duration",
-			Buckets:   prometheus.ExponentialBuckets(0.001, 2, 30), // 1ms ~ 1073741s
+			Buckets:   prometheus.ExponentialBuckets(0.001, 2, 24), // 1ms ~ 16777s
 			Help:      "tidb txn pessimistic lock keys duration",
 		})
 )