util: introduce tracing-based test toolkit

go.mod

@@ -29,6 +29,7 @@ require (
 	github.com/klauspost/compress v1.10.5 // indirect
 	github.com/klauspost/cpuid v1.2.1
 	github.com/kr/text v0.2.0 // indirect
+	github.com/maruel/panicparse v1.6.1
 	github.com/ngaut/pools v0.0.0-20180318154953-b7bc8c42aac7
 	github.com/ngaut/sync2 v0.0.0-20141008032647-7a24ed77b2ef
 	github.com/ngaut/unistore v0.0.0-20201217024625-f53801ce8d4f
@@ -56,13 +57,13 @@ require (
 	github.com/shirou/gopsutil v2.20.6+incompatible
 	github.com/sirupsen/logrus v1.6.0
 	github.com/soheilhy/cmux v0.1.4
-	github.com/stretchr/testify v1.6.1 // indirect
 	github.com/tiancaiamao/appdash v0.0.0-20181126055449-889f96f722a2
 	github.com/tikv/pd v1.1.0-beta.0.20201125070607-d4b90eee0c70
 	github.com/twmb/murmur3 v1.1.3
 	github.com/uber-go/atomic v1.4.0
 	github.com/uber/jaeger-client-go v2.22.1+incompatible
 	github.com/uber/jaeger-lib v2.4.0+incompatible // indirect
+	github.com/v2pro/plz v0.0.0-20200805122259-422184e41b6e
 	github.com/zhangjinpeng1987/raft v0.0.0-20200819064223-df31bb68a018 // indirect
 	go.etcd.io/etcd v0.5.0-alpha.5.0.20200824191128-ae9734ed278b
 	go.uber.org/atomic v1.7.0
@@ -78,7 +79,6 @@ require (
 	google.golang.org/grpc v1.27.1
 	gopkg.in/check.v1 v1.0.0-20200902074654-038fdea0a05b // indirect
 	gopkg.in/natefinch/lumberjack.v2 v2.0.0
-	gopkg.in/yaml.v2 v2.3.0 // indirect
 	honnef.co/go/tools v0.1.0 // indirect
 	sourcegraph.com/sourcegraph/appdash v0.0.0-20190731080439-ebfcffb1b5c0
 	sourcegraph.com/sourcegraph/appdash-data v0.0.0-20151005221446-73f23eafcf67

go.sum

@@ -347,6 +347,7 @@ github.com/google/go-cmp v0.2.0/go.mod h1:oXzfMopK8JAjlY9xF4vHSVASa0yLyX7SntLO5a
 github.com/google/go-cmp v0.3.0/go.mod h1:8QqcDgzrUqlUb/G2PQTWiueGozuR1884gddMywk6iLU=
 github.com/google/go-cmp v0.3.1/go.mod h1:8QqcDgzrUqlUb/G2PQTWiueGozuR1884gddMywk6iLU=
 github.com/google/go-cmp v0.4.0/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
+github.com/google/go-cmp v0.5.1/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
 github.com/google/go-cmp v0.5.2 h1:X2ev0eStA3AbceY54o37/0PQ/UWqKEiiO2dKL5OPaFM=
 github.com/google/go-cmp v0.5.2/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
 github.com/google/gofuzz v1.0.0/go.mod h1:dBl0BpW6vV/+mYPU4Po3pmUjxk6FQPldtuIdl/M65Eg=
@@ -443,6 +444,8 @@ github.com/json-iterator/go v1.1.6/go.mod h1:+SdeFBvtyEkXs7REEP0seUULqWtbJapLOCV
 github.com/json-iterator/go v1.1.7/go.mod h1:KdQUCv79m/52Kvf8AW2vK1V8akMuk1QjK/uOdHXbAo4=
 github.com/json-iterator/go v1.1.9 h1:9yzud/Ht36ygwatGx56VwCZtlI/2AD15T1X2sjSuGns=
 github.com/json-iterator/go v1.1.9/go.mod h1:KdQUCv79m/52Kvf8AW2vK1V8akMuk1QjK/uOdHXbAo4=
+github.com/json-iterator/go v1.1.10 h1:Kz6Cvnvv2wGdaG/V8yMvfkmNiXq9Ya2KUv4rouJJr68=
+github.com/json-iterator/go v1.1.10/go.mod h1:KdQUCv79m/52Kvf8AW2vK1V8akMuk1QjK/uOdHXbAo4=
 github.com/jstemmer/go-junit-report v0.0.0-20190106144839-af01ea7f8024/go.mod h1:6v2b51hI/fHJwM22ozAgKL4VKDeJcHhJFhtBdhmNjmU=
 github.com/jstemmer/go-junit-report v0.9.1 h1:6QPYqodiu3GuPL+7mfx+NwDdp2eTkp9IfEUpgAwUN0o=
 github.com/jstemmer/go-junit-report v0.9.1/go.mod h1:Brl9GWCQeLvo8nXZwPNNblvFj/XSXhF0NWZEnDohbsk=
@@ -499,12 +502,18 @@ github.com/mailru/easyjson v0.0.0-20190614124828-94de47d64c63/go.mod h1:C1wdFJiN
 github.com/mailru/easyjson v0.0.0-20190626092158-b2ccc519800e/go.mod h1:C1wdFJiN94OJF2b5HbByQZoLdCWB1Yqtg26g4irojpc=
 github.com/mailru/easyjson v0.7.1/go.mod h1:KAzv3t3aY1NaHWoQz1+4F1ccyAH66Jk7yos7ldAVICs=
 github.com/markbates/pkger v0.16.0/go.mod h1:0JoVlrol20BSywW79rN3kdFFsE5xYM+rSCQDXbLhiuI=
+github.com/maruel/panicparse v1.6.1 h1:803MjBzGcUgE1vYgg3UMNq3G1oyYeKkMu3t6hBS97x0=
+github.com/maruel/panicparse v1.6.1/go.mod h1:uoxI4w9gJL6XahaYPMq/z9uadrdr1SyHuQwV2q80Mm0=
+github.com/maruel/panicparse/v2 v2.1.1 h1:zUgy1SQ+Zi36oL/V+6cs/8OZjTio/41cjLVJ2hO5W9Q=
+github.com/maruel/panicparse/v2 v2.1.1/go.mod h1:AeTWdCE4lcq8OKsLb6cHSj1RWHVSnV9HBCk7sKLF4Jg=
 github.com/mattn/go-adodb v0.0.1/go.mod h1:jaSTRde4bohMuQgYQPxW3xRTPtX/cZKyxPrFVseJULo=
 github.com/mattn/go-colorable v0.0.9/go.mod h1:9vuHe8Xs5qXnSaW/c/ABM9alt+Vo+STaOChaDxuIBZU=
 github.com/mattn/go-colorable v0.1.2/go.mod h1:U0ppj6V5qS13XJ6of8GYAs25YV2eR4EVcfRqFIhoBtE=
 github.com/mattn/go-colorable v0.1.4/go.mod h1:U0ppj6V5qS13XJ6of8GYAs25YV2eR4EVcfRqFIhoBtE=
 github.com/mattn/go-colorable v0.1.6 h1:6Su7aK7lXmJ/U79bYtBjLNaha4Fs1Rg9plHpcH+vvnE=
 github.com/mattn/go-colorable v0.1.6/go.mod h1:u6P/XSegPjTcexA+o6vUJrdnUu04hMope9wVRipJSqc=
+github.com/mattn/go-colorable v0.1.7 h1:bQGKb3vps/j0E9GfJQ03JyhRuxsvdAanXlT9BTw3mdw=
+github.com/mattn/go-colorable v0.1.7/go.mod h1:u6P/XSegPjTcexA+o6vUJrdnUu04hMope9wVRipJSqc=
 github.com/mattn/go-isatty v0.0.4/go.mod h1:M+lRXTBqGeGNdLjl/ufCoiOlB5xdOkqRJdNxMWT7Zi4=
 github.com/mattn/go-isatty v0.0.7/go.mod h1:Iq45c/XA43vh69/j3iqttzPXn0bhXyGjM0Hdxcsrc5s=
 github.com/mattn/go-isatty v0.0.8/go.mod h1:Iq45c/XA43vh69/j3iqttzPXn0bhXyGjM0Hdxcsrc5s=
@@ -529,6 +538,8 @@ github.com/matttproud/golang_protobuf_extensions v1.0.1 h1:4hp9jkHxhMHkqkrB3Ix0j
 github.com/matttproud/golang_protobuf_extensions v1.0.1/go.mod h1:D8He9yQNgCq6Z5Ld7szi9bcBfOoFv/3dc6xSMkL2PC0=
 github.com/mgechev/dots v0.0.0-20190921121421-c36f7dcfbb81/go.mod h1:KQ7+USdGKfpPjXk4Ga+5XxQM4Lm4e3gAogrreFAYpOg=
 github.com/mgechev/revive v1.0.2/go.mod h1:rb0dQy1LVAxW9SWy5R3LPUjevzUbUS316U5MFySA2lo=
+github.com/mgutz/ansi v0.0.0-20200706080929-d51e80ef957d h1:5PJl274Y63IEHC+7izoQE9x6ikvDFZS2mDVS3drnohI=
+github.com/mgutz/ansi v0.0.0-20200706080929-d51e80ef957d/go.mod h1:01TrycV0kFyexm33Z7vhZRXopbI8J3TDReVlkTgMUxE=
 github.com/minio/minio-go v6.0.14+incompatible/go.mod h1:7guKYtitv8dktvNUGrhzmNlA5wrAABTQXCoesZdFQO8=
 github.com/mitchellh/go-homedir v1.1.0/go.mod h1:SfyaCUpYCn1Vlf4IUYiD9fPX4A5wJrkLzIz1N1q0pr0=
 github.com/mitchellh/go-wordwrap v0.0.0-20150314170334-ad45545899c7/go.mod h1:ZXFpozHsX6DPmq2I0TCekCxypsnAUbP2oI0UX1GXzOo=
@@ -720,6 +731,7 @@ github.com/prometheus/prom2json v1.3.0/go.mod h1:rMN7m0ApCowcoDlypBHlkNbp5eJQf/+
 github.com/prometheus/tsdb v0.7.1/go.mod h1:qhTCs0VvXwvX/y3TZrWD7rabWM+ijKTux40TwIPHuXU=
 github.com/r3labs/diff v0.0.0-20200627101315-aecd9dd05dd2/go.mod h1:7WjXasNzi0vJetRcB/RqNl5dlIsmXcTTLmF5IoH6Xig=
 github.com/rakyll/statik v0.1.6/go.mod h1:OEi9wJV/fMUAGx1eNjq75DKDsJVuEv1U0oYdX6GX8Zs=
+github.com/rakyll/statik v0.1.7/go.mod h1:AlZONWzMtEnMs7W4e/1LURLiI49pIMmp6V9Unghqrcc=
 github.com/rcrowley/go-metrics v0.0.0-20190826022208-cac0b30c2563/go.mod h1:bCqnVzQkZxMG4s8nGwiZ5l3QUCyqpo9Y+/ZMZ9VjZe4=
 github.com/relex/aini v1.2.0/go.mod h1:oFQyhvkzwi8GChiLukpBHkV2v142ls2L1MTeOSD2vic=
 github.com/remyoudompheng/bigfft v0.0.0-20170806203942-52369c62f446/go.mod h1:uYEyJGbgTkfkS4+E/PavXkNJcbFIpEtjt2B0KDQ5+9M=
@@ -739,6 +751,7 @@ github.com/satori/go.uuid v1.2.1-0.20181028125025-b2ce2384e17b/go.mod h1:dA0hQrY
 github.com/segmentio/kafka-go v0.1.0/go.mod h1:X6itGqS9L4jDletMsxZ7Dz+JFWxM6JHfPOCvTvk+EJo=
 github.com/segmentio/kafka-go v0.2.0/go.mod h1:X6itGqS9L4jDletMsxZ7Dz+JFWxM6JHfPOCvTvk+EJo=
 github.com/sergi/go-diff v1.0.0/go.mod h1:0CfEIISq7TuYL3j771MWULgwwjU+GofnZX9QAmXWZgo=
+github.com/sergi/go-diff v1.0.1-0.20180205163309-da645544ed44 h1:tB9NOR21++IjLyVx3/PCPhWMwqGNCMQEH96A6dMZ/gc=
 github.com/sergi/go-diff v1.0.1-0.20180205163309-da645544ed44/go.mod h1:0CfEIISq7TuYL3j771MWULgwwjU+GofnZX9QAmXWZgo=
 github.com/shirou/gopsutil v2.19.10+incompatible/go.mod h1:5b4v6he4MtMOwMlS0TUMTu2PcXUg8+E1lC7eC3UO/RA=
 github.com/shirou/gopsutil v2.20.3+incompatible/go.mod h1:5b4v6he4MtMOwMlS0TUMTu2PcXUg8+E1lC7eC3UO/RA=
@@ -864,6 +877,8 @@ github.com/urfave/cli v1.20.0/go.mod h1:70zkFmudgCuE/ngEzBv17Jvp/497gISqfk5gWijb
 github.com/urfave/cli v1.22.2/go.mod h1:Gos4lmkARVdJ6EkW0WaNv/tZAAMe9V7XWyB60NtXRu0=
 github.com/urfave/cli/v2 v2.1.1/go.mod h1:SE9GqnLQmjVa0iPEY0f1w3ygNIYcIJ0OKPMoW2caLfQ=
 github.com/urfave/negroni v0.3.0/go.mod h1:Meg73S6kFm/4PpbYdq35yYWoCZ9mS/YSx+lKnmiohz4=
+github.com/v2pro/plz v0.0.0-20200805122259-422184e41b6e h1:Vo4wf8YcHE9G7jD6eDG7au3nLGosOxm/DxQO7JR5dAk=
+github.com/v2pro/plz v0.0.0-20200805122259-422184e41b6e/go.mod h1:3gacX+hQo+xvl0vtLqCMufzxuNCwt4geAVOMt2LQYfE=
 github.com/valyala/bytebufferpool v1.0.0/go.mod h1:6bBcMArwyJ5K/AmCkWv1jt77kVWyCJ6HpOuEn7z0Csc=
 github.com/valyala/fasttemplate v1.0.1/go.mod h1:UQGH1tvbgY+Nz5t2n7tXsz52dQxojPUpymEIMZ47gx8=
 github.com/vertica/vertica-sql-go v0.1.6/go.mod h1:2LGtkNSdFF5CTJYeUA5qWfREuvYaql+51fNzmoD5W7c=
@@ -1078,6 +1093,7 @@ golang.org/x/sys v0.0.0-20200223170610-d5e6a3e2c0ae/go.mod h1:h1NjWce9XRLGQEsW7w
 golang.org/x/sys v0.0.0-20200323222414-85ca7c5b95cd/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20200413165638-669c56c373c4/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20200420163511-1957bb5e6d1f/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20200724161237-0e2f3a69832c/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20200819171115-d785dc25833f h1:KJuwZVtZBVzDmEDtB2zro9CXkD9O0dpCv4o2LHbQIAw=
 golang.org/x/sys v0.0.0-20200819171115-d785dc25833f/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=

store/tikv/1pc_test.go

@@ -20,6 +20,7 @@ import (
 	"github.com/pingcap/tidb/kv"
 	"github.com/pingcap/tidb/sessionctx"
 	"github.com/pingcap/tidb/store/tikv/oracle"
+	"github.com/pingcap/tidb/util/tracingtest"
 )
 
 func (s *testAsyncCommitCommon) begin1PC(c *C) *tikvTxn {
@@ -42,6 +43,62 @@ func (s *testOnePCSuite) SetUpTest(c *C) {
 	s.bo = NewBackofferWithVars(context.Background(), 5000, nil)
 }
 
+func (s *testOnePCSuite) Test1PCOnRegionSplit(c *C) {
+	k2, k1 := kv.Key("z"), kv.Key("a")
+	box := tracingtest.NewSandbox()
+
+	// check standard 1pc behavior firstly.
+	txn1 := s.begin1PC(c)
+	err := txn1.Set(k1, []byte{2})
+	c.Assert(err, IsNil)
+	err = txn1.Set(k2, []byte{2})
+	c.Assert(err, IsNil)
+	ctx1 := box.StartRoutine(context.WithValue(context.Background(), sessionctx.ConnID, uint64(1)), "txn1")
+	err = txn1.Commit(ctx1)
+	c.Assert(err, IsNil)
+	c.Assert(txn1.committer.isOnePC(), IsTrue)
+
+	// test split during 1pc handle.
+	txn2 := s.begin1PC(c)
+	err = txn2.Set(k1, []byte{1})
+	c.Assert(err, IsNil)
+	err = txn2.Set(k2, []byte{1})
+	c.Assert(err, IsNil)
+	ctx2 := box.StartRoutine(context.WithValue(context.Background(), sessionctx.ConnID, uint64(1)), "txn2")
+	tracingtest.EnableBreakpoint(ctx2, "beforeSendPrewrite")
+	done := make(chan struct{})
+	go func() {
+		defer func() {
+			done <- struct{}{}
+		}()
+		err = txn2.Commit(ctx2)
+		c.Assert(err, IsNil)
+	}()
+	tracingtest.EnsureWaitOnBreakpoint(ctx2, "beforeSendPrewrite")
+	c.Assert(txn2.committer.isOnePC(), IsTrue)
+
+	// split region before sending 1PC request.
+	region2 := s.cluster.AllocID()
+	newPeers := []uint64{s.cluster.AllocID(), s.cluster.AllocID()}
+	s.cluster.Split(s.initRegion, region2, []byte("m"), newPeers, newPeers[0])
+
+	// resume routine from breakpoint and want it can fallback to 2pc.
+	tracingtest.ContinueBreakpoint(ctx2, "beforeSendPrewrite")
+	<-done
+	c.Assert(txn2.committer.isOnePC(), IsFalse)
+
+	// assert 2 txn execution path: txn1 only send 1 prewrite no commit and txn2 resend 2 prewrite and need commit
+	c.Assert(box.CollectLogs(), tracingtest.LogsEquals, `[1] txn1: load region 2 from pd, due to cache-miss
+	[1] txn1: send Prewrite request to region 2 at store1
+	[2] txn2: send Prewrite request to region 2 at store1
+	[2] txn2: load region 4 from pd, due to cache-miss
+	[2] txn2: send Prewrite request to region 4 at store1
+	[2] txn2: send Prewrite request to region 2 at store1
+	[2] txn2: start get commit ts
+	[2] txn2: finish get commit ts
+	[2] txn2: send Commit request to region 2 at store1`)
+}
+
 func (s *testOnePCSuite) Test1PC(c *C) {
 	ctx := context.WithValue(context.Background(), sessionctx.ConnID, uint64(1))
 

store/tikv/2pc.go

@@ -25,6 +25,7 @@ import (
 	"time"
 	"unsafe"
 
+	"github.com/opentracing/opentracing-go"
 	"github.com/pingcap/errors"
 	"github.com/pingcap/failpoint"
 	pb "github.com/pingcap/kvproto/pkg/kvrpcpb"
@@ -43,6 +44,7 @@ import (
 	"github.com/pingcap/tidb/util/execdetails"
 	"github.com/pingcap/tidb/util/logutil"
 	"github.com/pingcap/tidb/util/rowcodec"
+	"github.com/pingcap/tidb/util/tracingtest"
 	"github.com/pingcap/tipb/go-binlog"
 	"github.com/prometheus/client_golang/prometheus"
 	zap "go.uber.org/zap"
@@ -742,6 +744,11 @@ func (c *twoPhaseCommitter) doActionOnGroupMutations(bo *Backoffer, action twoPh
 	if actionIsCommit && !actionCommit.retry && !c.isAsyncCommit() {
 		secondaryBo := NewBackofferWithVars(context.Background(), int(atomic.LoadUint64(&CommitMaxBackoff)), c.txn.vars)
 		go func() {
+			if span := opentracing.SpanFromContext(bo.ctx); span != nil && span.Tracer() != nil {
+				span1 := span.Tracer().StartSpan("twoPhaseCommitter.commitSecondaries", opentracing.ChildOf(span.Context()))
+				defer span1.Finish()
+				secondaryBo.ctx = opentracing.ContextWithSpan(secondaryBo.ctx, span1)
+			}
 			if c.connID > 0 {
 				failpoint.Inject("beforeCommitSecondaries", func(v failpoint.Value) {
 					if s, ok := v.(string); !ok {
@@ -755,14 +762,16 @@ func (c *twoPhaseCommitter) doActionOnGroupMutations(bo *Backoffer, action twoPh
 					}
 				})
 			}
-
+			tracingtest.CheckBreakpoint(bo.ctx, "beforeCommitSecondaries")
 			e := c.doActionOnBatches(secondaryBo, action, batchBuilder.allBatches())
 			if e != nil {
 				logutil.BgLogger().Debug("2PC async doActionOnBatches",
 					zap.Uint64("conn", c.connID),
 					zap.Stringer("action type", action),
 					zap.Error(e))
 				tikvSecondaryLockCleanupFailureCounterCommit.Inc()
+			} else {
+				logutil.Event(secondaryBo.ctx, "commit secondary keys success")
 			}
 		}()
 	} else {

store/tikv/2pc_test.go

@@ -37,6 +37,7 @@ import (
 	"github.com/pingcap/tidb/store/tikv/oracle"
 	"github.com/pingcap/tidb/store/tikv/tikvrpc"
 	"github.com/pingcap/tidb/tablecodec"
+	"github.com/pingcap/tidb/util/tracingtest"
 )
 
 type testCommitterSuite struct {
@@ -135,6 +136,61 @@ func randKV(keyLen, valLen int) (string, string) {
 	return string(k), string(v)
 }
 
+func (s *testCommitterSuite) TestCommitSecondarySlow(c *C) {
+	// split 3 keys into 3 regions
+	s.cluster.SplitKeys(kv.Key("d"), kv.Key("a"), 4)
+	k1, k2, k3 := kv.Key("a"), kv.Key("b"), kv.Key("c")
+
+	box := tracingtest.NewSandbox()
+	ctx1, ctx2 := box.StartRoutine(context.Background(), "txn1"), box.StartRoutine(context.Background(), "txn2")
+
+	// commit txn1 but let secondaries waiting in commit phase.
+	txn1 := s.begin(c)
+	err := txn1.Set(k1, []byte{1})
+	c.Assert(err, IsNil)
+	err = txn1.Set(k2, []byte{1})
+	c.Assert(err, IsNil)
+	tracingtest.EnableBreakpoint(ctx1, "beforeCommitSecondaries")
+	err = txn1.Commit(ctx1)
+	c.Assert(err, IsNil)
+	tracingtest.EnsureWaitOnBreakpoint(ctx1, "beforeCommitSecondaries")
+
+	// commit txn2 with overlap key, it will meet txn1's k2 and will resolve & prewrite & commit it.
+	txn2 := s.begin(c)
+	err = txn2.Set(k3, []byte{1})
+	c.Assert(err, IsNil)
+	err = txn2.Set(k2, []byte{2})
+	c.Assert(err, IsNil)
+	err = txn2.Commit(ctx2)
+	c.Assert(err, IsNil)
+
+	// make txn1 continue commit k2 and ensure background goroutine exit
+	gid := tracingtest.ContinueBreakpoint(ctx1, "beforeCommitSecondaries")
+	tracingtest.EnsureGoroutineFinished(gid)
+
+	// check trace log to ensure two txn works as desired
+	c.Assert(box.CollectLogs(), tracingtest.LogsEquals, `[1] txn1: load region 4 from pd, due to cache-miss
+	[1] txn1: load region 5 from pd, due to cache-miss
+	[1] txn1: send Prewrite request to region 5 at store1
+	[1] txn1: send Prewrite request to region 4 at store1
+	[1] txn1: start get commit ts
+	[1] txn1: finish get commit ts
+	[1] txn1: send Commit request to region 4 at store1
+	[1] txn1: send Commit request to region 5 at store1
+	[1] txn1: commit secondary keys success
+	[2] txn2: load region 6 from pd, due to cache-miss
+	[2] txn2: send Prewrite request to region 6 at store1
+	[2] txn2: send Prewrite request to region 5 at store1
+	[2] txn2: send CheckTxnStatus request to region 4 at store1
+	[2] txn2: send ResolveLock request to region 5 at store1
+	[2] txn2: send Prewrite request to region 5 at store1
+	[2] txn2: start get commit ts
+	[2] txn2: finish get commit ts
+	[2] txn2: send Commit request to region 5 at store1
+	[2] txn2: send Commit request to region 6 at store1
+	[2] txn2: commit secondary keys success`)
+}
+
 func (s *testCommitterSuite) TestDeleteYourWritesTTL(c *C) {
 	conf := *config.GetGlobalConfig()
 	oldConf := conf

store/tikv/async_commit_test.go

@@ -34,8 +34,9 @@ import (
 // testAsyncCommitCommon is used to put common parts that will be both used by
 // testAsyncCommitSuite and testAsyncCommitFailSuite.
 type testAsyncCommitCommon struct {
-	cluster cluster.Cluster
-	store   *tikvStore
+	cluster    cluster.Cluster
+	store      *tikvStore
+	initRegion uint64
 }
 
 func (s *testAsyncCommitCommon) setUpTest(c *C) {
@@ -46,7 +47,7 @@ func (s *testAsyncCommitCommon) setUpTest(c *C) {
 
 	client, pdClient, cluster, err := unistore.New("")
 	c.Assert(err, IsNil)
-	unistore.BootstrapWithSingleStore(cluster)
+	_, _, s.initRegion = unistore.BootstrapWithSingleStore(cluster)
 	s.cluster = cluster
 	store, err := NewTestTiKVStore(client, pdClient, nil, nil, 0)
 	c.Assert(err, IsNil)

store/tikv/prewrite.go

@@ -27,6 +27,7 @@ import (
 	"github.com/pingcap/tidb/metrics"
 	"github.com/pingcap/tidb/store/tikv/tikvrpc"
 	"github.com/pingcap/tidb/util/logutil"
+	"github.com/pingcap/tidb/util/tracingtest"
 	"github.com/prometheus/client_golang/prometheus"
 	"go.uber.org/zap"
 )
@@ -144,6 +145,7 @@ func (action actionPrewrite) handleSingleBatch(c *twoPhaseCommitter, bo *Backoff
 	}
 
 	req := c.buildPrewriteRequest(batch, txnSize)
+	tracingtest.CheckBreakpoint(bo.ctx, "beforeSendPrewrite")
 	for {
 		sender := NewRegionRequestSender(c.store.regionCache, c.store.client)
 		resp, err := sender.SendReq(bo, req, batch.region, readTimeoutShort)

util/tracingtest/docs.go

@@ -0,0 +1,47 @@
+// Copyright 2021 PingCAP, Inc.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+// Package tracingtest provide a simple tracing-based test toolkit.
+// with it, white-box-testcase writers can:
+//
+//  - add/continue breakpoints for routines to simulate different execution orders
+//  - ensure routines wait on special breakpoint or ensure it has finished without unstable `time.Sleep(n)`
+//  - enable/disable failpoint in routine level easily
+//  - collect and assert execution path pattern by tracing-log to ensure routine cover desired code-path.
+//
+// it's standing on the shoulders of giants, it combines failpoint, opentracing, panicparse...
+// it's not a substitute for failpoint, it bases on failpoint and wants to simulate execution flow easier
+// and support assert execution path just like assert explain result
+//
+// Terminology
+//
+//  - Sandbox: every test using tracingtest need create a Sandbox to manage and monitor test Routines.
+//  - Routine: one test can have one or many routines(i.e. different txn), it derived from Sandbox and be managed and monitored by Sandbox, routine's logic need use routine's `context.Context`
+//  - Breakpoint: one routine can set several breakpoints, and each breakpoint can be hit or continued individually and also support wait breakpoint be hit
+//
+// How to Use
+//
+// 1. create an `Sandbox` at first in test
+// 2. divide testcase to several routine and `StartRoutine` for each of them(e.g. one routine for one txn)
+// 3. add `CheckBreakpoint` to place that want to wait on
+// 4. `EnableBreakpoint` for special routine's `context.Context`
+// 5. do testcase and using right routine's `context.Context`
+// 6. check whether breakpoint has hit via `EnsureWaitOnBreakpoint`
+// 7. continue do testcase or `EnableBreakpoint` for another breakpoint if needed
+// 8. `ContinueBreakpoint` to resume waited routine
+// 9. use `EnsureGoroutineFinished` to ensure some goroutine has finished
+// 10. use `CollectLogs` to collect execution path info and do assert
+// 11. build TiDB-server with `make failpoint-enable` then run testcase
+//
+// see example testcase in: 2pc_test.go => TestCommitSecondarySlow
+package tracingtest