diff --git a/distsql/select_result.go b/distsql/select_result.go index 991e53d8ca499..ab21ec00fc3e3 100644 --- a/distsql/select_result.go +++ b/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 } diff --git a/distsql/stream.go b/distsql/stream.go index f68487647775e..934eb28e16885 100644 --- a/distsql/stream.go +++ b/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 } diff --git a/executor/slow_query.go b/executor/slow_query.go index b579a5b245064..30ea85a432033 100644 --- a/executor/slow_query.go +++ b/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)) diff --git a/executor/slow_query_test.go b/executor/slow_query_test.go index 4e79b241a7925..daa05a46acd16 100644 --- a/executor/slow_query_test.go +++ b/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 diff --git a/infoschema/tables.go b/infoschema/tables.go index 4ea200576f3cb..b998f9293cb2f 100644 --- a/infoschema/tables.go +++ b/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}, diff --git a/infoschema/tables_test.go b/infoschema/tables_test.go index 774fe95371fb6..28eabb1503a27 100644 --- a/infoschema/tables_test.go +++ b/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) diff --git a/sessionctx/stmtctx/stmtctx.go b/sessionctx/stmtctx/stmtctx.go index fc9f2aac61a5b..98879a6401d17 100644 --- a/sessionctx/stmtctx/stmtctx.go +++ b/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 diff --git a/util/execdetails/execdetails.go b/util/execdetails/execdetails.go index 04db70a59113c..f126b9821a858 100644 --- a/util/execdetails/execdetails.go +++ b/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")) } diff --git a/util/execdetails/execdetails_test.go b/util/execdetails/execdetails_test.go index eff1b61784b7e..4805ee672c0df 100644 --- a/util/execdetails/execdetails_test.go +++ b/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)