txn: seperate the prewrite and commit details information to make it …

…clear (#37158)

ref #34106

DEPS.bzl

@@ -3366,8 +3366,8 @@ def go_deps():
         name = "com_github_tikv_client_go_v2",
         build_file_proto_mode = "disable_global",
         importpath = "github.com/tikv/client-go/v2",
-        sum = "h1:WFR3seA8YtBhDn47YJSW1P1/lwBIXsk0vALnRVuaL/M=",
-        version = "v2.0.1-0.20220815094724-025596b7a20a",
+        sum = "h1:/nr7P8uzJQ7u3wPEBHCokrsVmuDvi/1x/zI/ydk5n8U=",
+        version = "v2.0.1-0.20220818084834-0d0ae0dcfb1f",
     )
     go_repository(
         name = "com_github_tikv_pd_client",

go.mod

@@ -79,7 +79,7 @@ require (
 	github.com/stretchr/testify v1.8.0
 	github.com/tdakkota/asciicheck v0.1.1
 	github.com/tiancaiamao/appdash v0.0.0-20181126055449-889f96f722a2
-	github.com/tikv/client-go/v2 v2.0.1-0.20220815094724-025596b7a20a
+	github.com/tikv/client-go/v2 v2.0.1-0.20220818084834-0d0ae0dcfb1f
 	github.com/tikv/pd/client v0.0.0-20220725055910-7187a7ab72db
 	github.com/timakin/bodyclose v0.0.0-20210704033933-f49887972144
 	github.com/twmb/murmur3 v1.1.3

go.sum

@@ -906,8 +906,8 @@ github.com/tenntenn/text/transform v0.0.0-20200319021203-7eef512accb3 h1:f+jULpR
 github.com/tenntenn/text/transform v0.0.0-20200319021203-7eef512accb3/go.mod h1:ON8b8w4BN/kE1EOhwT0o+d62W65a6aPw1nouo9LMgyY=
 github.com/tiancaiamao/appdash v0.0.0-20181126055449-889f96f722a2 h1:mbAskLJ0oJfDRtkanvQPiooDH8HvJ2FBh+iKT/OmiQQ=
 github.com/tiancaiamao/appdash v0.0.0-20181126055449-889f96f722a2/go.mod h1:2PfKggNGDuadAa0LElHrByyrz4JPZ9fFx6Gs7nx7ZZU=
-github.com/tikv/client-go/v2 v2.0.1-0.20220815094724-025596b7a20a h1:WFR3seA8YtBhDn47YJSW1P1/lwBIXsk0vALnRVuaL/M=
-github.com/tikv/client-go/v2 v2.0.1-0.20220815094724-025596b7a20a/go.mod h1:v3DEt8LS9olI6D6El17pYBWq7B28hw3NnDFTxQHDLpY=
+github.com/tikv/client-go/v2 v2.0.1-0.20220818084834-0d0ae0dcfb1f h1:/nr7P8uzJQ7u3wPEBHCokrsVmuDvi/1x/zI/ydk5n8U=
+github.com/tikv/client-go/v2 v2.0.1-0.20220818084834-0d0ae0dcfb1f/go.mod h1:v3DEt8LS9olI6D6El17pYBWq7B28hw3NnDFTxQHDLpY=
 github.com/tikv/pd/client v0.0.0-20220725055910-7187a7ab72db h1:r1eMh9Rny3hfWuBuxOnbsCRrR4FhthiNxLQ5rAUtaww=
 github.com/tikv/pd/client v0.0.0-20220725055910-7187a7ab72db/go.mod h1:ew8kS0yIcEaSetuuywkTLIUBR+sz3J5XvAYRae11qwc=
 github.com/timakin/bodyclose v0.0.0-20210704033933-f49887972144 h1:kl4KhGNsJIbDHS9/4U9yQo1UcPQM0kOMJHn29EoH/Ro=

util/execdetails/execdetails.go

@@ -86,8 +86,10 @@ const (
 	CommitBackoffTimeStr = "Commit_backoff_time"
 	// BackoffTypesStr means the backoff type.
 	BackoffTypesStr = "Backoff_types"
-	// SlowestCommitRPCDetailStr means the details of the slowest RPC during the transaction commit process.
-	SlowestCommitRPCDetailStr = "Slowest_commit_rpc_detail"
+	// SlowestPrewriteRPCDetailStr means the details of the slowest RPC during the transaction 2pc prewrite process.
+	SlowestPrewriteRPCDetailStr = "Slowest_prewrite_rpc_detail"
+	// CommitPrimaryRPCDetailStr means the details of the slowest RPC during the transaction 2pc commit process.
+	CommitPrimaryRPCDetailStr = "Commit_primary_rpc_detail"
 	// ResolveLockTimeStr means the time of resolving lock.
 	ResolveLockTimeStr = "Resolve_lock_time"
 	// LocalLatchWaitTimeStr means the time of waiting in local latch.
@@ -159,14 +161,23 @@ func (d ExecDetails) String() string {
 		if commitBackoffTime > 0 {
 			parts = append(parts, CommitBackoffTimeStr+": "+strconv.FormatFloat(time.Duration(commitBackoffTime).Seconds(), 'f', -1, 64))
 		}
-		if len(commitDetails.Mu.BackoffTypes) > 0 {
-			parts = append(parts, BackoffTypesStr+": "+fmt.Sprintf("%v", commitDetails.Mu.BackoffTypes))
+		if len(commitDetails.Mu.PrewriteBackoffTypes) > 0 {
+			parts = append(parts, "Prewrite_"+BackoffTypesStr+": "+fmt.Sprintf("%v", commitDetails.Mu.PrewriteBackoffTypes))
 		}
-		if commitDetails.Mu.SlowestReqTotalTime > 0 {
-			parts = append(parts, SlowestCommitRPCDetailStr+": {total:"+strconv.FormatFloat(commitDetails.Mu.SlowestReqTotalTime.Seconds(), 'f', 3, 64)+
-				"s, region_id: "+strconv.FormatUint(commitDetails.Mu.SlowestRegion, 10)+
-				", store: "+commitDetails.Mu.SlowestStoreAddr+
-				", "+commitDetails.Mu.SlowestExecDetails.String()+"}")
+		if len(commitDetails.Mu.CommitBackoffTypes) > 0 {
+			parts = append(parts, "Commit_"+BackoffTypesStr+": "+fmt.Sprintf("%v", commitDetails.Mu.CommitBackoffTypes))
+		}
+		if commitDetails.Mu.SlowestPrewrite.ReqTotalTime > 0 {
+			parts = append(parts, SlowestPrewriteRPCDetailStr+": {total:"+strconv.FormatFloat(commitDetails.Mu.SlowestPrewrite.ReqTotalTime.Seconds(), 'f', 3, 64)+
+				"s, region_id: "+strconv.FormatUint(commitDetails.Mu.SlowestPrewrite.Region, 10)+
+				", store: "+commitDetails.Mu.SlowestPrewrite.StoreAddr+
+				", "+commitDetails.Mu.SlowestPrewrite.ExecDetails.String()+"}")
+		}
+		if commitDetails.Mu.CommitPrimary.ReqTotalTime > 0 {
+			parts = append(parts, CommitPrimaryRPCDetailStr+": {total:"+strconv.FormatFloat(commitDetails.Mu.SlowestPrewrite.ReqTotalTime.Seconds(), 'f', 3, 64)+
+				"s, region_id: "+strconv.FormatUint(commitDetails.Mu.SlowestPrewrite.Region, 10)+
+				", store: "+commitDetails.Mu.SlowestPrewrite.StoreAddr+
+				", "+commitDetails.Mu.SlowestPrewrite.ExecDetails.String()+"}")
 		}
 		commitDetails.Mu.Unlock()
 		resolveLockTime := atomic.LoadInt64(&commitDetails.ResolveLock.ResolveLockTime)
@@ -263,8 +274,23 @@ func (d ExecDetails) ToZapFields() (fields []zap.Field) {
 		if commitBackoffTime > 0 {
 			fields = append(fields, zap.String("commit_backoff_time", fmt.Sprintf("%v", strconv.FormatFloat(time.Duration(commitBackoffTime).Seconds(), 'f', -1, 64)+"s")))
 		}
-		if len(commitDetails.Mu.BackoffTypes) > 0 {
-			fields = append(fields, zap.String("backoff_types", fmt.Sprintf("%v", commitDetails.Mu.BackoffTypes)))
+		if len(commitDetails.Mu.PrewriteBackoffTypes) > 0 {
+			fields = append(fields, zap.String("Prewrite_"+BackoffTypesStr, fmt.Sprintf("%v", commitDetails.Mu.PrewriteBackoffTypes)))
+		}
+		if len(commitDetails.Mu.CommitBackoffTypes) > 0 {
+			fields = append(fields, zap.String("Commit_"+BackoffTypesStr, fmt.Sprintf("%v", commitDetails.Mu.CommitBackoffTypes)))
+		}
+		if commitDetails.Mu.SlowestPrewrite.ReqTotalTime > 0 {
+			fields = append(fields, zap.String(SlowestPrewriteRPCDetailStr, "total:"+strconv.FormatFloat(commitDetails.Mu.SlowestPrewrite.ReqTotalTime.Seconds(), 'f', 3, 64)+
+				"s, region_id: "+strconv.FormatUint(commitDetails.Mu.SlowestPrewrite.Region, 10)+
+				", store: "+commitDetails.Mu.SlowestPrewrite.StoreAddr+
+				", "+commitDetails.Mu.SlowestPrewrite.ExecDetails.String()+"}"))
+		}
+		if commitDetails.Mu.CommitPrimary.ReqTotalTime > 0 {
+			fields = append(fields, zap.String(CommitPrimaryRPCDetailStr, "{total:"+strconv.FormatFloat(commitDetails.Mu.SlowestPrewrite.ReqTotalTime.Seconds(), 'f', 3, 64)+
+				"s, region_id: "+strconv.FormatUint(commitDetails.Mu.SlowestPrewrite.Region, 10)+
+				", store: "+commitDetails.Mu.SlowestPrewrite.StoreAddr+
+				", "+commitDetails.Mu.SlowestPrewrite.ExecDetails.String()+"}"))
 		}
 		commitDetails.Mu.Unlock()
 		resolveLockTime := atomic.LoadInt64(&commitDetails.ResolveLock.ResolveLockTime)
@@ -905,21 +931,36 @@ func (e *RuntimeStatsWithCommit) String() string {
 		if commitBackoffTime > 0 {
 			buf.WriteString(", backoff: {time: ")
 			buf.WriteString(FormatDuration(time.Duration(commitBackoffTime)))
-			if len(e.Commit.Mu.BackoffTypes) > 0 {
-				buf.WriteString(", type: ")
-				buf.WriteString(e.formatBackoff(e.Commit.Mu.BackoffTypes))
+			if len(e.Commit.Mu.PrewriteBackoffTypes) > 0 {
+				buf.WriteString(", prewrite type: ")
+				buf.WriteString(e.formatBackoff(e.Commit.Mu.PrewriteBackoffTypes))
 			}
+			if len(e.Commit.Mu.CommitBackoffTypes) > 0 {
+				buf.WriteString(", commit type: ")
+				buf.WriteString(e.formatBackoff(e.Commit.Mu.CommitBackoffTypes))
+			}
+			buf.WriteString("}")
+		}
+		if e.Commit.Mu.SlowestPrewrite.ReqTotalTime > 0 {
+			buf.WriteString(", slowest_prewrite_rpc: {total: ")
+			buf.WriteString(strconv.FormatFloat(e.Commit.Mu.SlowestPrewrite.ReqTotalTime.Seconds(), 'f', 3, 64))
+			buf.WriteString("s, region_id: ")
+			buf.WriteString(strconv.FormatUint(e.Commit.Mu.SlowestPrewrite.Region, 10))
+			buf.WriteString(", store: ")
+			buf.WriteString(e.Commit.Mu.SlowestPrewrite.StoreAddr)
+			buf.WriteString(", ")
+			buf.WriteString(e.Commit.Mu.SlowestPrewrite.ExecDetails.String())
 			buf.WriteString("}")
 		}
-		if e.Commit.Mu.SlowestReqTotalTime > 0 {
-			buf.WriteString(", slowest_commit_rpc: {total: ")
-			buf.WriteString(strconv.FormatFloat(e.Commit.Mu.SlowestReqTotalTime.Seconds(), 'f', 3, 64))
+		if e.Commit.Mu.CommitPrimary.ReqTotalTime > 0 {
+			buf.WriteString(", commit_primary_rpc: {total: ")
+			buf.WriteString(strconv.FormatFloat(e.Commit.Mu.CommitPrimary.ReqTotalTime.Seconds(), 'f', 3, 64))
 			buf.WriteString("s, region_id: ")
-			buf.WriteString(strconv.FormatUint(e.Commit.Mu.SlowestRegion, 10))
+			buf.WriteString(strconv.FormatUint(e.Commit.Mu.CommitPrimary.Region, 10))
 			buf.WriteString(", store: ")
-			buf.WriteString(e.Commit.Mu.SlowestStoreAddr)
+			buf.WriteString(e.Commit.Mu.CommitPrimary.StoreAddr)
 			buf.WriteString(", ")
-			buf.WriteString(e.Commit.Mu.SlowestExecDetails.String())
+			buf.WriteString(e.Commit.Mu.CommitPrimary.ExecDetails.String())
 			buf.WriteString("}")
 		}
 		e.Commit.Mu.Unlock()