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

Author: crazycs520

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