store: fix timing of prewrite binlog in slow log (#15273)

go.sum

@@ -183,6 +183,7 @@ github.com/prometheus/procfs v0.0.0-20181005140218-185b4288413d h1:GoAlyOgbOEIFd
 github.com/prometheus/procfs v0.0.0-20181005140218-185b4288413d/go.mod h1:c3At6R/oaqEKCNdg8wHV1ftS6bRYblBhIjjI8uT2IGk=
 github.com/remyoudompheng/bigfft v0.0.0-20190512091148-babf20351dd7 h1:FUL3b97ZY2EPqg2NbXKuMHs5pXJB9hjj1fDHnF2vl28=
 github.com/remyoudompheng/bigfft v0.0.0-20190512091148-babf20351dd7/go.mod h1:qqbHyh8v60DhA7CoWK5oRCqLrMHRGoxYCSS9EjAz6Eo=
+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.18.10+incompatible h1:cy84jW6EVRPa5g9HAHrlbxMSIjBhDSX0OFYyMYminYs=
 github.com/shirou/gopsutil v2.18.10+incompatible/go.mod h1:5b4v6he4MtMOwMlS0TUMTu2PcXUg8+E1lC7eC3UO/RA=

infoschema/slow_log.go

@@ -44,7 +44,7 @@ var slowQueryCols = []columnInfo{
 	{variable.SlowLogParseTimeStr, mysql.TypeDouble, 22, 0, nil, nil},
 	{variable.SlowLogCompileTimeStr, mysql.TypeDouble, 22, 0, nil, nil},
 	{execdetails.PreWriteTimeStr, mysql.TypeDouble, 22, 0, nil, nil},
-	{execdetails.BinlogPrewriteTimeStr, mysql.TypeDouble, 22, 0, nil, nil},
+	{execdetails.WaitPrewriteBinlogTimeStr, mysql.TypeDouble, 22, 0, nil, nil},
 	{execdetails.CommitTimeStr, mysql.TypeDouble, 22, 0, nil, nil},
 	{execdetails.GetCommitTSTimeStr, mysql.TypeDouble, 22, 0, nil, nil},
 	{execdetails.CommitBackoffTimeStr, mysql.TypeDouble, 22, 0, nil, nil},
@@ -196,52 +196,52 @@ func getOneLine(reader *bufio.Reader) ([]byte, error) {
 }
 
 type slowQueryTuple struct {
-	time               time.Time
-	txnStartTs         uint64
-	user               string
-	host               string
-	connID             uint64
-	queryTime          float64
-	parseTime          float64
-	compileTime        float64
-	preWriteTime       float64
-	binlogPrewriteTime float64
-	commitTime         float64
-	getCommitTSTime    float64
-	commitBackoffTime  float64
-	backoffTypes       string
-	resolveLockTime    float64
-	localLatchWaitTime float64
-	writeKeys          uint64
-	writeSize          uint64
-	prewriteRegion     uint64
-	txnRetry           uint64
-	processTime        float64
-	waitTime           float64
-	backOffTime        float64
-	lockKeysTime       float64
-	requestCount       uint64
-	totalKeys          uint64
-	processKeys        uint64
-	db                 string
-	indexIDs           string
-	digest             string
-	statsInfo          string
-	avgProcessTime     float64
-	p90ProcessTime     float64
-	maxProcessTime     float64
-	maxProcessAddress  string
-	avgWaitTime        float64
-	p90WaitTime        float64
-	maxWaitTime        float64
-	maxWaitAddress     string
-	memMax             int64
-	prevStmt           string
-	sql                string
-	isInternal         bool
-	succ               bool
-	plan               string
-	planDigest         string
+	time                   time.Time
+	txnStartTs             uint64
+	user                   string
+	host                   string
+	connID                 uint64
+	queryTime              float64
+	parseTime              float64
+	compileTime            float64
+	preWriteTime           float64
+	waitPrewriteBinlogTime float64
+	commitTime             float64
+	getCommitTSTime        float64
+	commitBackoffTime      float64
+	backoffTypes           string
+	resolveLockTime        float64
+	localLatchWaitTime     float64
+	writeKeys              uint64
+	writeSize              uint64
+	prewriteRegion         uint64
+	txnRetry               uint64
+	processTime            float64
+	waitTime               float64
+	backOffTime            float64
+	lockKeysTime           float64
+	requestCount           uint64
+	totalKeys              uint64
+	processKeys            uint64
+	db                     string
+	indexIDs               string
+	digest                 string
+	statsInfo              string
+	avgProcessTime         float64
+	p90ProcessTime         float64
+	maxProcessTime         float64
+	maxProcessAddress      string
+	avgWaitTime            float64
+	p90WaitTime            float64
+	maxWaitTime            float64
+	maxWaitAddress         string
+	memMax                 int64
+	prevStmt               string
+	sql                    string
+	isInternal             bool
+	succ                   bool
+	plan                   string
+	planDigest             string
 }
 
 func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string, lineNum int) error {
@@ -275,8 +275,8 @@ func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string,
 		st.compileTime, err = strconv.ParseFloat(value, 64)
 	case execdetails.PreWriteTimeStr:
 		st.preWriteTime, err = strconv.ParseFloat(value, 64)
-	case execdetails.BinlogPrewriteTimeStr:
-		st.binlogPrewriteTime, err = strconv.ParseFloat(value, 64)
+	case execdetails.WaitPrewriteBinlogTimeStr:
+		st.waitPrewriteBinlogTime, err = strconv.ParseFloat(value, 64)
 	case execdetails.CommitTimeStr:
 		st.commitTime, err = strconv.ParseFloat(value, 64)
 	case execdetails.GetCommitTSTimeStr:
@@ -369,7 +369,7 @@ func (st *slowQueryTuple) convertToDatumRow() []types.Datum {
 	record = append(record, types.NewFloat64Datum(st.parseTime))
 	record = append(record, types.NewFloat64Datum(st.compileTime))
 	record = append(record, types.NewFloat64Datum(st.preWriteTime))
-	record = append(record, types.NewFloat64Datum(st.binlogPrewriteTime))
+	record = append(record, types.NewFloat64Datum(st.waitPrewriteBinlogTime))
 	record = append(record, types.NewFloat64Datum(st.commitTime))
 	record = append(record, types.NewFloat64Datum(st.getCommitTSTime))
 	record = append(record, types.NewFloat64Datum(st.commitBackoffTime))

infoschema/tables_test.go

@@ -313,7 +313,9 @@ type mockSessionManager struct {
 	processInfoMap map[uint64]*util.ProcessInfo
 }
 
-func (sm *mockSessionManager) ShowProcessList() map[uint64]*util.ProcessInfo { return sm.processInfoMap }
+func (sm *mockSessionManager) ShowProcessList() map[uint64]*util.ProcessInfo {
+	return sm.processInfoMap
+}
 
 func (sm *mockSessionManager) GetProcessInfo(id uint64) (*util.ProcessInfo, bool) {
 	rs, ok := sm.processInfoMap[id]
@@ -469,7 +471,7 @@ func (s *testTableSuite) TestSlowQuery(c *C) {
 # Query_time: 4.895492
 # Parse_time: 0.4
 # Compile_time: 0.2
-# Request_count: 1 Prewrite_time: 0.19 Binlog_prewrite_time: 0.21 Commit_time: 0.01 Commit_backoff_time: 0.18 Backoff_types: [txnLock] Resolve_lock_time: 0.03 Write_keys: 15 Write_size: 480 Prewrite_region: 1 Txn_retry: 8
+# Request_count: 1 Prewrite_time: 0.19 Wait_prewrite_binlog_time: 0.21 Commit_time: 0.01 Commit_backoff_time: 0.18 Backoff_types: [txnLock] Resolve_lock_time: 0.03 Write_keys: 15 Write_size: 480 Prewrite_region: 1 Txn_retry: 8
 # Process_time: 0.161 Request_count: 1 Total_keys: 100001 Process_keys: 100000
 # Wait_time: 0.101
 # Backoff_time: 0.092 LockKeys_time: 1.72

store/tikv/2pc.go

@@ -1119,7 +1119,6 @@ func (c *twoPhaseCommitter) execute(ctx context.Context) (err error) {
 		}
 	}()
 
-	binlogPrewriteStart := time.Now()
 	binlogChan := c.prewriteBinlog()
 	prewriteBo := NewBackoffer(ctx, prewriteMaxBackoff).WithVars(c.txn.vars)
 	start := time.Now()
@@ -1133,7 +1132,9 @@ func (c *twoPhaseCommitter) execute(ctx context.Context) (err error) {
 		commitDetail.Mu.Unlock()
 	}
 	if binlogChan != nil {
+		startWaitBinlog := time.Now()
 		binlogWriteResult := <-binlogChan
+		commitDetail.WaitPrewriteBinlogTime = time.Since(startWaitBinlog)
 		if binlogWriteResult != nil {
 			binlogSkipped = binlogWriteResult.Skipped()
 			binlogErr := binlogWriteResult.GetError()
@@ -1142,7 +1143,6 @@ func (c *twoPhaseCommitter) execute(ctx context.Context) (err error) {
 			}
 		}
 	}
-	commitDetail.BinlogPrewriteTime = time.Since(binlogPrewriteStart)
 	if err != nil {
 		logutil.Logger(ctx).Debug("2PC failed on prewrite",
 			zap.Error(err),

util/execdetails/execdetails.go

@@ -44,13 +44,13 @@ type ExecDetails struct {
 
 // CommitDetails contains commit detail information.
 type CommitDetails struct {
-	GetCommitTsTime    time.Duration
-	PrewriteTime       time.Duration
-	BinlogPrewriteTime time.Duration
-	CommitTime         time.Duration
-	LocalLatchTime     time.Duration
-	CommitBackoffTime  int64
-	Mu                 struct {
+	GetCommitTsTime        time.Duration
+	PrewriteTime           time.Duration
+	WaitPrewriteBinlogTime time.Duration
+	CommitTime             time.Duration
+	LocalLatchTime         time.Duration
+	CommitBackoffTime      int64
+	Mu                     struct {
 		sync.Mutex
 		BackoffTypes []fmt.Stringer
 	}
@@ -78,8 +78,8 @@ const (
 	ProcessKeysStr = "Process_keys"
 	// PreWriteTimeStr means the time of pre-write.
 	PreWriteTimeStr = "Prewrite_time"
-	// BinlogPrewriteTimeStr means the time of binlog prewrite
-	BinlogPrewriteTimeStr = "Binlog_prewrite_time"
+	// WaitPrewriteBinlogTimeStr means the time of waiting prewrite binlog finished when transaction committing.
+	WaitPrewriteBinlogTimeStr = "Wait_prewrite_binlog_time"
 	// CommitTimeStr means the time of commit.
 	CommitTimeStr = "Commit_time"
 	// GetCommitTSTimeStr means the time of getting commit ts.
@@ -131,8 +131,8 @@ func (d ExecDetails) String() string {
 		if commitDetails.PrewriteTime > 0 {
 			parts = append(parts, PreWriteTimeStr+": "+strconv.FormatFloat(commitDetails.PrewriteTime.Seconds(), 'f', -1, 64))
 		}
-		if commitDetails.BinlogPrewriteTime > 0 {
-			parts = append(parts, BinlogPrewriteTimeStr+": "+strconv.FormatFloat(commitDetails.BinlogPrewriteTime.Seconds(), 'f', -1, 64))
+		if commitDetails.WaitPrewriteBinlogTime > 0 {
+			parts = append(parts, WaitPrewriteBinlogTimeStr+": "+strconv.FormatFloat(commitDetails.WaitPrewriteBinlogTime.Seconds(), 'f', -1, 64))
 		}
 		if commitDetails.CommitTime > 0 {
 			parts = append(parts, CommitTimeStr+": "+strconv.FormatFloat(commitDetails.CommitTime.Seconds(), 'f', -1, 64))