executor: add lock keys duration metric (#14194)

pingcap · Dec 24, 2019 · 1a32e51 · 1a32e51
1 parent 2f3f57a
commit 1a32e51
Show file tree

Hide file tree

Showing 7 changed files with 40 additions and 16 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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 {