From 9557708866b09964d642a9a77903cb05cff79fd8 Mon Sep 17 00:00:00 2001 From: crazycs Date: Sun, 5 May 2019 12:50:28 +0800 Subject: [PATCH] log: change slow log time format to compatible with pt-query-digest (#10290) (#10323) --- infoschema/slow_log.go | 6 +++++- infoschema/slow_log_test.go | 32 +++++++++++++++++++++++++------- infoschema/tables_test.go | 2 +- sessionctx/variable/session.go | 2 +- util/logutil/log.go | 5 ++++- 5 files changed, 36 insertions(+), 11 deletions(-) diff --git a/infoschema/slow_log.go b/infoschema/slow_log.go index 6acf9fece222a..5e7d6457934c0 100644 --- a/infoschema/slow_log.go +++ b/infoschema/slow_log.go @@ -319,7 +319,11 @@ func (st *slowQueryTuple) convertToDatumRow() []types.Datum { func ParseTime(s string) (time.Time, error) { t, err := time.Parse(logutil.SlowLogTimeFormat, s) if err != nil { - err = errors.Errorf("string \"%v\" doesn't has a prefix that matches format \"%v\", err: %v", s, logutil.SlowLogTimeFormat, err) + // This is for compatibility. + t, err = time.Parse(logutil.OldSlowLogTimeFormat, s) + if err != nil { + err = errors.Errorf("string \"%v\" doesn't has a prefix that matches format \"%v\", err: %v", s, logutil.SlowLogTimeFormat, err) + } } return t, err } diff --git a/infoschema/slow_log_test.go b/infoschema/slow_log_test.go index cb16fcf291b1e..637864e1b028e 100644 --- a/infoschema/slow_log_test.go +++ b/infoschema/slow_log_test.go @@ -25,7 +25,7 @@ import ( func (s *testSuite) TestParseSlowLogFile(c *C) { slowLog := bytes.NewBufferString( - `# Time: 2019-01-24-22:32:29.313255 +0800 + `# 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 @@ -51,14 +51,14 @@ select * from t;`) } recordString += str } - expectRecordString := "2019-01-24 22:32:29.313255,405888132465033227,,0,0.216905,0.021,0,0,1,637,0,,,1,42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772,t1:1,t2:2,0.1,0.2,0.03,0.05,0.6,0.8,70724,select * from t;" + expectRecordString := "2019-04-28 15:24:04.309074,405888132465033227,,0,0.216905,0.021,0,0,1,637,0,,,1,42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772,t1:1,t2:2,0.1,0.2,0.03,0.05,0.6,0.8,70724,select * from t;" c.Assert(expectRecordString, Equals, recordString) // fix sql contain '# ' bug slowLog = bytes.NewBufferString( - `# Time: 2019-01-24-22:32:29.313255 +0800 + `# Time: 2019-04-28T15:24:04.309074+08:00 select a# from t; -# Time: 2019-01-24-22:32:29.313255 +0800 +# Time: 2019-01-24T22:32:29.313255+08:00 # Txn_start_ts: 405888132465033227 # Query_time: 0.216905 # Process_time: 0.021 Request_count: 1 Total_keys: 637 Processed_keys: 436 @@ -70,16 +70,34 @@ select * from t; scanner = bufio.NewScanner(slowLog) _, err = infoschema.ParseSlowLog(loc, scanner) c.Assert(err, IsNil) + + // test for time format compatibility. + slowLog = bytes.NewBufferString( + `# Time: 2019-04-28T15:24:04.309074+08:00 +select * from t; +# Time: 2019-04-24-19:41:21.716221 +0800 +select * from t; +`) + scanner = bufio.NewScanner(slowLog) + rows, err = infoschema.ParseSlowLog(loc, scanner) + c.Assert(err, IsNil) + c.Assert(len(rows) == 2, IsTrue) + t0Str, err := rows[0][0].ToString() + c.Assert(err, IsNil) + c.Assert(t0Str, Equals, "2019-04-28 15:24:04.309074") + t1Str, err := rows[1][0].ToString() + c.Assert(err, IsNil) + c.Assert(t1Str, Equals, "2019-04-24 19:41:21.716221") } func (s *testSuite) TestSlowLogParseTime(c *C) { - t1Str := "2019-01-24-22:32:29.313255 +0800" - t2Str := "2019-01-24-22:32:29.313255" + t1Str := "2019-01-24T22:32:29.313255+08:00" + t2Str := "2019-01-24T22:32:29.313255" t1, err := infoschema.ParseTime(t1Str) c.Assert(err, IsNil) loc, err := time.LoadLocation("Asia/Shanghai") c.Assert(err, IsNil) - t2, err := time.ParseInLocation("2006-01-02-15:04:05.999999999", t2Str, loc) + t2, err := time.ParseInLocation("2006-01-02T15:04:05.999999999", t2Str, loc) c.Assert(err, IsNil) c.Assert(t1.Unix(), Equals, t2.Unix()) t1Format := t1.In(loc).Format(logutil.SlowLogTimeFormat) diff --git a/infoschema/tables_test.go b/infoschema/tables_test.go index 1f57cdb29da39..7d82d50c807a0 100644 --- a/infoschema/tables_test.go +++ b/infoschema/tables_test.go @@ -296,7 +296,7 @@ func (s *testSuite) TestSlowQuery(c *C) { f, err := os.OpenFile(slowLogFileName, os.O_CREATE|os.O_WRONLY, 0644) c.Assert(err, IsNil) defer os.Remove(slowLogFileName) - _, err = f.Write([]byte(`# Time: 2019-02-12-19:33:56.571953 +0800 + _, err = f.Write([]byte(`# Time: 2019-02-12T19:33:56.571953+08:00 # Txn_start_ts: 406315658548871171 # User: root@127.0.0.1 # Conn_ID: 6 diff --git a/sessionctx/variable/session.go b/sessionctx/variable/session.go index 78616a1994efd..4d1203996a12a 100644 --- a/sessionctx/variable/session.go +++ b/sessionctx/variable/session.go @@ -804,7 +804,7 @@ const ( // SlowLogFormat uses for formatting slow log. // The slow log output is like below: -// # Time: 2019-02-12-19:33:56.571953 +0800 +// # Time: 2019-04-28T15:24:04.309074+08:00 // # Txn_start_ts: 406315658548871171 // # User: root@127.0.0.1 // # Conn_ID: 6 diff --git a/util/logutil/log.go b/util/logutil/log.go index 6fde2c4e1c91f..67086e009d84a 100644 --- a/util/logutil/log.go +++ b/util/logutil/log.go @@ -22,6 +22,7 @@ import ( "runtime" "sort" "strings" + "time" "github.com/pingcap/errors" zaplog "github.com/pingcap/log" @@ -208,7 +209,9 @@ func (f *textFormatter) Format(entry *log.Entry) ([]byte, error) { const ( // SlowLogTimeFormat is the time format for slow log. - SlowLogTimeFormat = "2006-01-02-15:04:05.999999999 -0700" + SlowLogTimeFormat = time.RFC3339Nano + // OldSlowLogTimeFormat is the first version of the the time format for slow log, This is use for compatibility. + OldSlowLogTimeFormat = "2006-01-02-15:04:05.999999999 -0700" ) type slowLogFormatter struct{}