From 916d5efe4ed32de14ab1fc93683cbeb9d1dee484 Mon Sep 17 00:00:00 2001 From: cfzjywxk Date: Wed, 18 Dec 2019 17:15:09 +0800 Subject: [PATCH] add binlog prewrite time to record binlog prewrite time consume --- infoschema/slow_log.go | 5 +++++ infoschema/slow_log_test.go | 2 +- infoschema/tables_test.go | 6 +++--- store/tikv/2pc.go | 2 ++ util/execdetails/execdetails.go | 18 ++++++++++++------ 5 files changed, 23 insertions(+), 10 deletions(-) diff --git a/infoschema/slow_log.go b/infoschema/slow_log.go index 9b14c1ca30e51..b9ee4a9dad388 100644 --- a/infoschema/slow_log.go +++ b/infoschema/slow_log.go @@ -44,6 +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.CommitTimeStr, mysql.TypeDouble, 22, 0, nil, nil}, {execdetails.GetCommitTSTimeStr, mysql.TypeDouble, 22, 0, nil, nil}, {execdetails.CommitBackoffTimeStr, mysql.TypeDouble, 22, 0, nil, nil}, @@ -202,6 +203,7 @@ type slowQueryTuple struct { parseTime float64 compileTime float64 preWriteTime float64 + binlogPrewriteTime float64 commitTime float64 getCommitTSTime float64 commitBackoffTime float64 @@ -269,6 +271,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.CommitTimeStr: st.commitTime, err = strconv.ParseFloat(value, 64) case execdetails.GetCommitTSTimeStr: @@ -357,6 +361,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.commitTime)) record = append(record, types.NewFloat64Datum(st.getCommitTSTime)) record = append(record, types.NewFloat64Datum(st.commitBackoffTime)) diff --git a/infoschema/slow_log_test.go b/infoschema/slow_log_test.go index ccc0e6e693941..d37b81f8328b9 100644 --- a/infoschema/slow_log_test.go +++ b/infoschema/slow_log_test.go @@ -55,7 +55,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.021,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,,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.021,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,,update t set i = 1;,select * from t;" c.Assert(expectRecordString, Equals, recordString) // fix sql contain '# ' bug diff --git a/infoschema/tables_test.go b/infoschema/tables_test.go index 1b278b4b84bed..95f3b398567f4 100644 --- a/infoschema/tables_test.go +++ b/infoschema/tables_test.go @@ -466,7 +466,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 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 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 # Process_time: 0.161 Request_count: 1 Total_keys: 100001 Process_keys: 100000 # Wait_time: 0.101 # Backoff_time: 0.092 @@ -488,10 +488,10 @@ select * from t_slim;`)) 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.01|0|0.18|[txnLock]|0.03|0|15|480|1|8|0.161|0.101|0.092|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|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.161|0.101|0.092|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|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.01|0|0.18|[txnLock]|0.03|0|15|480|1|8|0.161|0.101|0.092|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|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.161|0.101|0.092|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|update t set i = 2;|select * from t_slim;")) // Test for long query. _, err = f.Write([]byte(` diff --git a/store/tikv/2pc.go b/store/tikv/2pc.go index fff7fbed84c43..e9ead63607dbd 100644 --- a/store/tikv/2pc.go +++ b/store/tikv/2pc.go @@ -1115,6 +1115,7 @@ 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() @@ -1137,6 +1138,7 @@ 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), diff --git a/util/execdetails/execdetails.go b/util/execdetails/execdetails.go index d69de4a600b33..0f044ef138f76 100644 --- a/util/execdetails/execdetails.go +++ b/util/execdetails/execdetails.go @@ -43,12 +43,13 @@ type ExecDetails struct { // CommitDetails contains commit detail information. type CommitDetails struct { - GetCommitTsTime time.Duration - PrewriteTime time.Duration - CommitTime time.Duration - LocalLatchTime time.Duration - CommitBackoffTime int64 - Mu struct { + GetCommitTsTime time.Duration + PrewriteTime time.Duration + BinlogPrewriteTime time.Duration + CommitTime time.Duration + LocalLatchTime time.Duration + CommitBackoffTime int64 + Mu struct { sync.Mutex BackoffTypes []fmt.Stringer } @@ -74,6 +75,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" // CommitTimeStr means the time of commit. CommitTimeStr = "Commit_time" // GetCommitTSTimeStr means the time of getting commit ts. @@ -122,6 +125,9 @@ 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.CommitTime > 0 { parts = append(parts, CommitTimeStr+": "+strconv.FormatFloat(commitDetails.CommitTime.Seconds(), 'f', -1, 64)) }