executer: add Cop_time in slow log (#16873)

distsql/select_result.go

@@ -130,10 +130,14 @@ func (r *selectResult) fetchResp(ctx context.Context) error {
 		for _, warning := range r.selectResp.Warnings {
 			sc.AppendWarning(terror.ClassTiKV.Synthesize(terror.ErrCode(warning.Code), warning.Msg))
 		}
-		r.updateCopRuntimeStats(resultSubset.GetExecDetails(), resultSubset.RespTime())
+		resultDetail := resultSubset.GetExecDetails()
+		r.updateCopRuntimeStats(resultDetail, resultSubset.RespTime())
 		r.feedback.Update(resultSubset.GetStartKey(), r.selectResp.OutputCounts)
 		r.partialCount++
-		sc.MergeExecDetails(resultSubset.GetExecDetails(), nil)
+		if resultDetail != nil {
+			resultDetail.CopTime = duration
+		}
+		sc.MergeExecDetails(resultDetail, nil)
 		if len(r.selectResp.Chunks) != 0 {
 			break
 		}

distsql/stream.go

@@ -73,7 +73,8 @@ func (r *streamResult) Next(ctx context.Context, chk *chunk.Chunk) error {
 func (r *streamResult) readDataFromResponse(ctx context.Context, resp kv.Response, result *tipb.Chunk) (bool, error) {
 	startTime := time.Now()
 	resultSubset, err := resp.Next(ctx)
-	r.fetchDuration += time.Since(startTime)
+	duration := time.Since(startTime)
+	r.fetchDuration += duration
 	if err != nil {
 		return false, err
 	}
@@ -105,7 +106,11 @@ func (r *streamResult) readDataFromResponse(ctx context.Context, resp kv.Respons
 	}
 	r.feedback.Update(resultSubset.GetStartKey(), stream.OutputCounts)
 	r.partialCount++
-	r.ctx.GetSessionVars().StmtCtx.MergeExecDetails(resultSubset.GetExecDetails(), nil)
+	resultDetail := resultSubset.GetExecDetails()
+	if resultDetail != nil {
+		resultDetail.CopTime = duration
+	}
+	r.ctx.GetSessionVars().StmtCtx.MergeExecDetails(resultDetail, nil)
 	return false, nil
 }
 

executor/slow_query.go

@@ -318,6 +318,7 @@ type slowQueryTuple struct {
 	writeSize              uint64
 	prewriteRegion         uint64
 	txnRetry               uint64
+	copTime                float64
 	processTime            float64
 	waitTime               float64
 	backOffTime            float64
@@ -407,6 +408,8 @@ func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string,
 		st.prewriteRegion, err = strconv.ParseUint(value, 10, 64)
 	case execdetails.TxnRetryStr:
 		st.txnRetry, err = strconv.ParseUint(value, 10, 64)
+	case execdetails.CopTimeStr:
+		st.copTime, err = strconv.ParseFloat(value, 64)
 	case execdetails.ProcessTimeStr:
 		st.processTime, err = strconv.ParseFloat(value, 64)
 	case execdetails.WaitTimeStr:
@@ -486,6 +489,7 @@ func (st *slowQueryTuple) convertToDatumRow() []types.Datum {
 	record = append(record, types.NewUintDatum(st.writeSize))
 	record = append(record, types.NewUintDatum(st.prewriteRegion))
 	record = append(record, types.NewUintDatum(st.txnRetry))
+	record = append(record, types.NewFloat64Datum(st.copTime))
 	record = append(record, types.NewFloat64Datum(st.processTime))
 	record = append(record, types.NewFloat64Datum(st.waitTime))
 	record = append(record, types.NewFloat64Datum(st.backOffTime))

executor/slow_query_test.go

@@ -47,7 +47,7 @@ func (s *testExecSuite) TestParseSlowLogFile(c *C) {
 		`# Time: 2019-04-28T15:24:04.309074+08:00
 # Txn_start_ts: 405888132465033227
 # Query_time: 0.216905
-# Process_time: 0.021 Request_count: 1 Total_keys: 637 Processed_keys: 436
+# Cop_time: 0.38 Process_time: 0.021 Request_count: 1 Total_keys: 637 Processed_keys: 436
 # Is_internal: true
 # Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772
 # Stats: t1:1,t2:2
@@ -75,7 +75,7 @@ select * from t;`
 		}
 		recordString += str
 	}
-	expectRecordString := "2019-04-28 15:24:04.309074,405888132465033227,,,0,0.216905,0,0,0,0,0,0,0,,0,0,0,0,0,0,0.021,0,0,0,1,637,0,,,1,42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772,t1:1,t2:2,0.1,0.2,0.03,127.0.0.1:20160,0.05,0.6,0.8,0.0.0.0:20160,70724,0,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,update t set i = 1;,select * from t;"
+	expectRecordString := "2019-04-28 15:24:04.309074,405888132465033227,,,0,0.216905,0,0,0,0,0,0,0,,0,0,0,0,0,0,0.38,0.021,0,0,0,1,637,0,,,1,42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772,t1:1,t2:2,0.1,0.2,0.03,127.0.0.1:20160,0.05,0.6,0.8,0.0.0.0:20160,70724,0,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,update t set i = 1;,select * from t;"
 	c.Assert(expectRecordString, Equals, recordString)
 
 	// fix sql contain '# ' bug

infoschema/tables.go

@@ -722,6 +722,7 @@ var slowQueryCols = []columnInfo{
 	{name: execdetails.WriteSizeStr, tp: mysql.TypeLonglong, size: 22},
 	{name: execdetails.PrewriteRegionStr, tp: mysql.TypeLonglong, size: 22},
 	{name: execdetails.TxnRetryStr, tp: mysql.TypeLonglong, size: 22},
+	{name: execdetails.CopTimeStr, tp: mysql.TypeDouble, size: 22},
 	{name: execdetails.ProcessTimeStr, tp: mysql.TypeDouble, size: 22},
 	{name: execdetails.WaitTimeStr, tp: mysql.TypeDouble, size: 22},
 	{name: execdetails.BackoffTimeStr, tp: mysql.TypeDouble, size: 22},

infoschema/tables_test.go

@@ -516,7 +516,7 @@ func prepareSlowLogfile(c *C, slowLogFileName string) {
 # Parse_time: 0.4
 # Compile_time: 0.2
 # LockKeys_time: 1.71 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
+# Cop_time: 0.3824278 Process_time: 0.161 Request_count: 1 Total_keys: 100001 Process_keys: 100000
 # Wait_time: 0.101
 # Backoff_time: 0.092
 # DB: test
@@ -597,10 +597,10 @@ func (s *testTableSuite) TestSlowQuery(c *C) {
 	tk.MustExec("set time_zone = '+08:00';")
 	re := tk.MustQuery("select * from information_schema.slow_query")
 	re.Check(testutil.RowsWithSep("|",
-		"2019-02-12 19:33:56.571953|406315658548871171|root|127.0.0.1|6|4.895492|0.4|0.2|0.19|0.21|0.01|0|0.18|[txnLock]|0.03|0|15|480|1|8|0.161|0.101|0.092|1.71|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|0.1|0.2|0.03|127.0.0.1:20160|0.05|0.6|0.8|0.0.0.0:20160|70724|1|abcd|60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4|update t set i = 2;|select * from t_slim;"))
+		"2019-02-12 19:33:56.571953|406315658548871171|root|127.0.0.1|6|4.895492|0.4|0.2|0.19|0.21|0.01|0|0.18|[txnLock]|0.03|0|15|480|1|8|0.3824278|0.161|0.101|0.092|1.71|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|0.1|0.2|0.03|127.0.0.1:20160|0.05|0.6|0.8|0.0.0.0:20160|70724|1|abcd|60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4|update t set i = 2;|select * from t_slim;"))
 	tk.MustExec("set time_zone = '+00:00';")
 	re = tk.MustQuery("select * from information_schema.slow_query")
-	re.Check(testutil.RowsWithSep("|", "2019-02-12 11:33:56.571953|406315658548871171|root|127.0.0.1|6|4.895492|0.4|0.2|0.19|0.21|0.01|0|0.18|[txnLock]|0.03|0|15|480|1|8|0.161|0.101|0.092|1.71|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|0.1|0.2|0.03|127.0.0.1:20160|0.05|0.6|0.8|0.0.0.0:20160|70724|1|abcd|60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4|update t set i = 2;|select * from t_slim;"))
+	re.Check(testutil.RowsWithSep("|", "2019-02-12 11:33:56.571953|406315658548871171|root|127.0.0.1|6|4.895492|0.4|0.2|0.19|0.21|0.01|0|0.18|[txnLock]|0.03|0|15|480|1|8|0.3824278|0.161|0.101|0.092|1.71|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|0.1|0.2|0.03|127.0.0.1:20160|0.05|0.6|0.8|0.0.0.0:20160|70724|1|abcd|60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4|update t set i = 2;|select * from t_slim;"))
 
 	// Test for long query.
 	f, err := os.OpenFile(slowLogFileName, os.O_CREATE|os.O_WRONLY, 0644)

sessionctx/stmtctx/stmtctx.go

@@ -458,6 +458,7 @@ func (sc *StatementContext) ResetForRetry() {
 func (sc *StatementContext) MergeExecDetails(details *execdetails.ExecDetails, commitDetails *execdetails.CommitDetails) {
 	sc.mu.Lock()
 	if details != nil {
+		sc.mu.execDetails.CopTime += details.CopTime
 		sc.mu.execDetails.ProcessTime += details.ProcessTime
 		sc.mu.execDetails.WaitTime += details.WaitTime
 		sc.mu.execDetails.BackoffTime += details.BackoffTime

util/execdetails/execdetails.go

@@ -34,6 +34,7 @@ var CommitDetailCtxKey = commitDetailCtxKeyType{}
 // ExecDetails contains execution detail information.
 type ExecDetails struct {
 	CalleeAddress    string
+	CopTime          time.Duration
 	ProcessTime      time.Duration
 	WaitTime         time.Duration
 	BackoffTime      time.Duration
@@ -66,6 +67,8 @@ type CommitDetails struct {
 }
 
 const (
+	// CopTimeStr represents the sum of cop-task time spend in TiDB distSQL.
+	CopTimeStr = "Cop_time"
 	// ProcessTimeStr represents the sum of process time of all the coprocessor tasks.
 	ProcessTimeStr = "Process_time"
 	// WaitTimeStr means the time of all coprocessor wait.
@@ -108,7 +111,10 @@ const (
 
 // String implements the fmt.Stringer interface.
 func (d ExecDetails) String() string {
-	parts := make([]string, 0, 6)
+	parts := make([]string, 0, 8)
+	if d.CopTime > 0 {
+		parts = append(parts, CopTimeStr+": "+strconv.FormatFloat(d.CopTime.Seconds(), 'f', -1, 64))
+	}
 	if d.ProcessTime > 0 {
 		parts = append(parts, ProcessTimeStr+": "+strconv.FormatFloat(d.ProcessTime.Seconds(), 'f', -1, 64))
 	}
@@ -180,6 +186,9 @@ func (d ExecDetails) String() string {
 // ToZapFields wraps the ExecDetails as zap.Fields.
 func (d ExecDetails) ToZapFields() (fields []zap.Field) {
 	fields = make([]zap.Field, 0, 16)
+	if d.CopTime > 0 {
+		fields = append(fields, zap.String(strings.ToLower(CopTimeStr), strconv.FormatFloat(d.CopTime.Seconds(), 'f', -1, 64)+"s"))
+	}
 	if d.ProcessTime > 0 {
 		fields = append(fields, zap.String(strings.ToLower(ProcessTimeStr), strconv.FormatFloat(d.ProcessTime.Seconds(), 'f', -1, 64)+"s"))
 	}

util/execdetails/execdetails_test.go

@@ -30,6 +30,7 @@ func TestT(t *testing.T) {
 
 func TestString(t *testing.T) {
 	detail := &ExecDetails{
+		CopTime:       time.Second + 3*time.Millisecond,
 		ProcessTime:   2*time.Second + 5*time.Millisecond,
 		WaitTime:      time.Second,
 		BackoffTime:   time.Second,
@@ -60,7 +61,7 @@ func TestString(t *testing.T) {
 			TxnRetry:          1,
 		},
 	}
-	expected := "Process_time: 2.005 Wait_time: 1 Backoff_time: 1 Request_count: 1 Total_keys: 100 Process_keys: 10 Prewrite_time: 1 Commit_time: 1 " +
+	expected := "Cop_time: 1.003 Process_time: 2.005 Wait_time: 1 Backoff_time: 1 Request_count: 1 Total_keys: 100 Process_keys: 10 Prewrite_time: 1 Commit_time: 1 " +
 		"Get_commit_ts_time: 1 Commit_backoff_time: 1 Backoff_types: [backoff1 backoff2] Resolve_lock_time: 1 Local_latch_wait_time: 1 Write_keys: 1 Write_size: 1 Prewrite_region: 1 Txn_retry: 1"
 	if str := detail.String(); str != expected {
 		t.Errorf("got:\n%s\nexpected:\n%s", str, expected)