Skip to content

Commit

Permalink
log: change slow log time format to compatible with pt-query-digest (#…
Browse files Browse the repository at this point in the history
  • Loading branch information
crazycs520 authored Apr 30, 2019
1 parent 7cc688c commit 36bb1ae
Show file tree
Hide file tree
Showing 5 changed files with 36 additions and 11 deletions.
6 changes: 5 additions & 1 deletion infoschema/slow_log.go
Original file line number Diff line number Diff line change
Expand Up @@ -330,7 +330,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
}
32 changes: 25 additions & 7 deletions infoschema/slow_log_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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,127.0.0.1:20160,0.05,0.6,0.8,0.0.0.0:20160,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,127.0.0.1:20160,0.05,0.6,0.8,0.0.0.0:20160,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
Expand All @@ -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)
Expand Down
2 changes: 1 addition & 1 deletion infoschema/tables_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -329,7 +329,7 @@ func (s *testTableSuite) 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
Expand Down
2 changes: 1 addition & 1 deletion sessionctx/variable/session.go
Original file line number Diff line number Diff line change
Expand Up @@ -945,7 +945,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
Expand Down
5 changes: 4 additions & 1 deletion util/logutil/log.go
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@ import (
"runtime"
"sort"
"strings"
"time"

"github.com/pingcap/errors"
zaplog "github.com/pingcap/log"
Expand Down Expand Up @@ -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{}
Expand Down

0 comments on commit 36bb1ae

Please sign in to comment.