log: change slow log time format to compatible with pt-query-digest (#10290)

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
 }

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)

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

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

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{}