Anomalies are detected by jepsen bank-multitable

[zyguan]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

Run jepsen bank-multitable workload.

2. What did you expect to see? (Required)

The test passed.

3. What did you see instead (Required)

2022-06-15 02:57:48,249{GMT}	INFO	[jepsen test runner] jepsen.core: {:perf
 {:latency-graph {:valid? true},
  :rate-graph {:valid? true},
  :valid? true},
 :workload
 {:SI
  {:valid? false,
   :read-count 67467,
   :error-count 67205,
   :first-error
   {:type :wrong-total,
    :total 97,
    :op
    {:type :ok,
     :f :read,
     :process 4,
     :time 4918413049,
     :value {0 67, 1 1, 2 2, 3 9, 4 0, 5 9, 6 3, 7 6},
     :txn-info {:start_ts 433916802727936002},
     :index 605}},
   :errors
   {:wrong-total
    {:count 67205,
     :first
     {:type :wrong-total,
      :total 97,
      :op
      {:type :ok,
       :f :read,
       :process 4,
       :time 4918413049,
       :value {0 67, 1 1, 2 2, 3 9, 4 0, 5 9, 6 3, 7 6},
       :txn-info {:start_ts 433916802727936002},
       :index 605}},
     :worst
     {:type :wrong-total,
      :total 711,
      :op
      {:type :ok,
       :f :read,
       :process 7,
       :time 603931050740,
       :value {0 16, 1 50, 2 7, 3 217, 4 116, 5 133, 6 97, 7 75},
       :txn-info {:start_ts 433916959752192036},
       :index 269491}},
     :last
     {:type :wrong-total,
      :total 711,
      :op
      {:type :ok,
       :f :read,
       :process 14,
       :time 604210303347,
       :value {0 3, 1 39, 2 11, 3 224, 4 118, 5 132, 6 104, 7 80},
       :txn-info {:start_ts 433916959817728123},
       :index 269609}},
     :lowest
     {:type :wrong-total,
      :total 97,
      :op
      {:type :ok,
       :f :read,
       :process 4,
       :time 4918413049,
       :value {0 67, 1 1, 2 2, 3 9, 4 0, 5 9, 6 3, 7 6},
       :txn-info {:start_ts 433916802727936002},
       :index 605}},
     :highest
     {:type :wrong-total,
      :total 711,
      :op
      {:type :ok,
       :f :read,
       :process 7,
       :time 603931050740,
       :value {0 16, 1 50, 2 7, 3 217, 4 116, 5 133, 6 97, 7 75},
       :txn-info {:start_ts 433916959752192036},
       :index 269491}}}}},
  :plot {:valid? true},
  :valid? false},
 :valid? false}


Analysis invalid! (ﾉಥ益ಥ）ﾉ ┻━┻

4. What is your TiDB version? (Required)

master @ 395ccbe

[lcwangchao]

It is because some times the ts for lock and ts for read data are not the same. When we are executing select * from t1 for update and found write conflict the first time, it will update forUpdateTS and retry and then OnStmtRetry will be called, see:

tidb/sessiontxn/isolation/repeatable_read.go

Lines 134 to 148 in 255dc8c

	func (p *PessimisticRRTxnContextProvider) OnStmtRetry(ctx context.Context) (err error) {
	if err = p.baseTxnContextProvider.OnStmtRetry(ctx); err != nil {
	return err
	}
	txnCtxForUpdateTS := p.sctx.GetSessionVars().TxnCtx.GetForUpdateTS()
	// If TxnCtx.forUpdateTS is updated in OnStmtErrorForNextAction, we assign the value to the provider
	if txnCtxForUpdateTS > p.forUpdateTS {
	p.forUpdateTS = txnCtxForUpdateTS
	} else {
	p.forUpdateTS = 0
	}
	p.followingOperatorIsPointGetForUpdate = false

Line 142 will set p.forUpdateTS to a new value. After that, the executor will be rebuild, when rebuilding SelectLockPlan , it will update the forUpdateTS again:

tidb/executor/builder.go

Lines 654 to 662 in 255dc8c

	func (b *executorBuilder) buildSelectLock(v *plannercore.PhysicalLock) Executor {
	if !b.inSelectLockStmt {
	b.inSelectLockStmt = true
	defer func() { b.inSelectLockStmt = false }()
	}
	b.hasLock = true
	if b.err = b.updateForUpdateTSIfNeeded(v.Children()[0]); b.err != nil {
	return nil
	}

It will call updateForUpdateTSIfNeeded and then the TxnCtx.forUpdateTS will be updated, but this function will not update the provider's ts, so now they are different.

newLockCtx will using TxnCtx.forUpdateTS to do the lock .

tidb/executor/executor.go

Lines 1049 to 1050 in d3b79de

	func newLockCtx(seVars *variable.SessionVars, lockWaitTime int64, numKeys int) *tikvstore.LockCtx {
	lockCtx := tikvstore.NewLockCtx(seVars.TxnCtx.GetForUpdateTS(), lockWaitTime, seVars.StmtCtx.GetLockWaitStartTime())

However the executor will use provider's ts to read data, and providerTS < TxnCtx.forUpdateTS, so if there is a commit between them, the executor will lock success but read a stale value.