diff --git a/event/aggregator.go b/event/aggregator.go index 963ffcc..7e1b0ca 100644 --- a/event/aggregator.go +++ b/event/aggregator.go @@ -86,6 +86,18 @@ func (a *Aggregator) Finalize() Result { a.global.Finalize(a.rateLimit) a.global.UniqueQueries = uint(len(a.classes)) for _, class := range a.classes { + if class.LastThreadID != 0 { + a.global.LastThreadID = class.LastThreadID + } + + if !class.TsMin.IsZero() && class.TsMin.Before(a.global.TsMin) { + a.global.TsMin = class.TsMin + } + + if !class.TsMax.IsZero() && class.TsMax.After(a.global.TsMax) { + a.global.TsMax = class.TsMax + } + class.Finalize(a.rateLimit) class.UniqueQueries = 1 if class.Example != nil && class.Example.Ts != "" { diff --git a/event/aggregator_test.go b/event/aggregator_test.go index 6c960f6..b20a85e 100644 --- a/event/aggregator_test.go +++ b/event/aggregator_test.go @@ -27,7 +27,6 @@ import ( "strings" "testing" "time" - "github.com/percona/go-mysql/event" "github.com/percona/go-mysql/log" parser "github.com/percona/go-mysql/log/slow" @@ -148,10 +147,16 @@ func TestAddClassSlow001(t *testing.T) { for _, class := range expectEventResult.Class { global.AddClass(class) } + + var emptyTime time.Time + expectEventResult.Global.TsMin = emptyTime; + expectEventResult.Global.TsMax = emptyTime; + expectEventResult.Global.LastThreadID = 0; expectGlobalBytes, err := json.Marshal(expectEventResult.Global) if err != nil { t.Fatal(err) } + gotGlobalBytes, err := json.Marshal(global) if err != nil { t.Fatal(err) @@ -171,6 +176,7 @@ func TestAddClassSlow023(t *testing.T) { for _, class := range ordered(expectEventResult.Class) { global.AddClass(class) } + expectEventResult.Global.LastThreadID = 0; expectGlobalBytes, err := json.Marshal(expectEventResult.Global) if err != nil { t.Fatal(err) diff --git a/event/class.go b/event/class.go index 238b3af..b0768e3 100644 --- a/event/class.go +++ b/event/class.go @@ -18,6 +18,8 @@ package event import ( + "time" + "github.com/percona/go-mysql/log" ) @@ -33,16 +35,19 @@ const ( // This is only enforced by convention, so be careful not to mix events from // different classes. type Class struct { - Id string // 32-character hex checksum of fingerprint - Fingerprint string // canonical form of query: values replaced with "?" - Metrics *Metrics // statistics for each metric, e.g. max Query_time - TotalQueries uint // total number of queries in class - UniqueQueries uint // unique number of queries in class - Example *Example `json:",omitempty"` // sample query with max Query_time + ID string // 32-character hex checksum of fingerprint + Fingerprint string // canonical form of query: values replaced with "?" + TsMin time.Time // timestamp of first event + TsMax time.Time // timestamp of last event + Metrics *Metrics // statistics for each metric, e.g. max Query_time + TotalQueries uint // total number of queries in class + UniqueQueries uint // unique number of queries in class + Example *Example `json:",omitempty"` // sample query with max Query_time // -- - outliers uint - lastDb string - sample bool + LastThreadID uint64 // Thread_id of query + outliers uint + lastDb string + sample bool } // A Example is a real query and its database, timestamp, and Query_time. @@ -60,7 +65,7 @@ type Example struct { // If sample is true, the query with the greatest Query_time is saved. func NewClass(id, fingerprint string, sample bool) *Class { class := &Class{ - Id: id, + ID: id, Fingerprint: fingerprint, Metrics: NewMetrics(), TotalQueries: 0, @@ -80,6 +85,17 @@ func (c *Class) AddEvent(e *log.Event, outlier bool) { c.Metrics.AddEvent(e, outlier) + if e.ThreadID != 0 { + c.LastThreadID = e.ThreadID + } + + if !e.Ts.IsZero() { + if c.TsMin.IsZero() { + c.TsMin = e.Ts + } + c.TsMax = e.Ts + } + // Save last db seen for this query. This helps ensure the sample query // has a db. if e.Db != "" { diff --git a/event/testdata/mariadb102-with-explain.golden b/event/testdata/mariadb102-with-explain.golden index 842a5db..75a8f45 100644 --- a/event/testdata/mariadb102-with-explain.golden +++ b/event/testdata/mariadb102-with-explain.golden @@ -1,7 +1,9 @@ { "Global": { - "Id": "", + "ID": "", "Fingerprint": "", + "TsMin": "2018-02-14T16:18:07Z", + "TsMax": "2018-02-14T16:18:07Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -45,14 +47,6 @@ "Med": 1, "P95": 1, "Max": 1 - }, - "Thread_id": { - "Sum": 8, - "Min": 8, - "Avg": 8, - "Med": 8, - "P95": 8, - "Max": 8 } }, "BoolMetrics": { @@ -62,12 +56,15 @@ } }, "TotalQueries": 1, - "UniqueQueries": 1 + "UniqueQueries": 1, + "LastThreadID": 8 }, "Class": { "16219655761820A2": { - "Id": "16219655761820A2", + "ID": "16219655761820A2", "Fingerprint": "select ?", + "TsMin": "2018-02-14T16:18:07Z", + "TsMax": "2018-02-14T16:18:07Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -111,14 +108,6 @@ "Med": 1, "P95": 1, "Max": 1 - }, - "Thread_id": { - "Sum": 8, - "Min": 8, - "Avg": 8, - "Med": 8, - "P95": 8, - "Max": 8 } }, "BoolMetrics": { @@ -135,7 +124,8 @@ "Query": "SELECT 1", "Size": 8, "Ts": "2018-02-14 16:18:07" - } + }, + "LastThreadID": 8 } }, "RateLimit": 0, diff --git a/event/testdata/slow001-no-examples.golden b/event/testdata/slow001-no-examples.golden index 386b25c..9167316 100644 --- a/event/testdata/slow001-no-examples.golden +++ b/event/testdata/slow001-no-examples.golden @@ -1,7 +1,9 @@ { "Global": { - "Id": "", + "ID": "", "Fingerprint": "", + "TsMin": "2007-10-15T21:43:52Z", + "TsMax": "2007-10-15T21:45:10Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -41,12 +43,15 @@ } }, "TotalQueries": 2, - "UniqueQueries": 2 + "UniqueQueries": 2, + "LastThreadID": 0 }, "Class": { "3A99CC42AEDCCFCD": { - "Id": "3A99CC42AEDCCFCD", + "ID": "3A99CC42AEDCCFCD", "Fingerprint": "select sleep(?) from test.n", + "TsMin": "2007-10-15T21:45:10Z", + "TsMax": "2007-10-15T21:45:10Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -86,11 +91,14 @@ } }, "TotalQueries": 1, - "UniqueQueries": 1 + "UniqueQueries": 1, + "LastThreadID": 0 }, "7F7D57ACDD8A346E": { - "Id": "7F7D57ACDD8A346E", + "ID": "7F7D57ACDD8A346E", "Fingerprint": "select sleep(?) from n", + "TsMin": "2007-10-15T21:43:52Z", + "TsMax": "2007-10-15T21:43:52Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -130,7 +138,8 @@ } }, "TotalQueries": 1, - "UniqueQueries": 1 + "UniqueQueries": 1, + "LastThreadID": 0 } }, "RateLimit": 0, diff --git a/event/testdata/slow001.golden b/event/testdata/slow001.golden index 1d738c9..55c2355 100644 --- a/event/testdata/slow001.golden +++ b/event/testdata/slow001.golden @@ -1,7 +1,9 @@ { "Global": { - "Id": "", + "ID": "", "Fingerprint": "", + "TsMin": "2007-10-15T21:43:52Z", + "TsMax": "2007-10-15T21:45:10Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -41,12 +43,15 @@ } }, "TotalQueries": 2, - "UniqueQueries": 2 + "UniqueQueries": 2, + "LastThreadID": 0 }, "Class": { "3A99CC42AEDCCFCD": { - "Id": "3A99CC42AEDCCFCD", + "ID": "3A99CC42AEDCCFCD", "Fingerprint": "select sleep(?) from test.n", + "TsMin": "2007-10-15T21:45:10Z", + "TsMax": "2007-10-15T21:45:10Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -93,11 +98,14 @@ "Query": "select sleep(2) from test.n", "Size": 27, "Ts": "2007-10-15 21:45:10" - } + }, + "LastThreadID": 0 }, "7F7D57ACDD8A346E": { - "Id": "7F7D57ACDD8A346E", + "ID": "7F7D57ACDD8A346E", "Fingerprint": "select sleep(?) from n", + "TsMin": "2007-10-15T21:43:52Z", + "TsMax": "2007-10-15T21:43:52Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -144,7 +152,8 @@ "Query": "select sleep(2) from n", "Size": 22, "Ts": "2007-10-15 21:43:52" - } + }, + "LastThreadID": 0 } }, "RateLimit": 0, diff --git a/event/testdata/slow010.golden b/event/testdata/slow010.golden index b95695b..20b5ef7 100644 --- a/event/testdata/slow010.golden +++ b/event/testdata/slow010.golden @@ -1,7 +1,9 @@ { "Global": { - "Id": "", + "ID": "", "Fingerprint": "", + "TsMin": "2007-12-18T11:48:27Z", + "TsMax": "2007-12-18T11:48:27Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -33,12 +35,15 @@ } }, "TotalQueries": 36, - "UniqueQueries": 1 + "UniqueQueries": 1, + "LastThreadID": 0 }, "Class": { "CB5621E548E5497F": { - "Id": "CB5621E548E5497F", + "ID": "CB5621E548E5497F", "Fingerprint": "select c from t where id=?", + "TsMin": "2007-12-18T11:48:27Z", + "TsMax": "2007-12-18T11:48:27Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -77,7 +82,8 @@ "Query": "SELECT c FROM t WHERE id=1", "Size": 26, "Ts": "2007-12-18 11:48:27" - } + }, + "LastThreadID": 0 } }, "RateLimit": 0, diff --git a/event/testdata/slow018.golden b/event/testdata/slow018.golden index b631fef..edecfb2 100644 --- a/event/testdata/slow018.golden +++ b/event/testdata/slow018.golden @@ -1,7 +1,9 @@ { "Global": { - "Id": "", + "ID": "", "Fingerprint": "", + "TsMin": "0001-01-01T00:00:00Z", + "TsMax": "0001-01-01T00:00:00Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -72,12 +74,15 @@ } }, "TotalQueries": 4, - "UniqueQueries": 1 + "UniqueQueries": 1, + "LastThreadID": 0 }, "Class": { "B2414E722E8A89DD": { - "Id": "B2414E722E8A89DD", + "ID": "B2414E722E8A89DD", "Fingerprint": "select * from t where id in(?+)", + "TsMin": "0001-01-01T00:00:00Z", + "TsMax": "0001-01-01T00:00:00Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -154,7 +159,8 @@ "Db": "db1", "Query": "select * from t where id in (10000,20000,30000)", "Size": 47 - } + }, + "LastThreadID": 0 } }, "RateLimit": 0, diff --git a/event/testdata/slow020.golden b/event/testdata/slow020.golden index 4fdafe4..359e078 100644 --- a/event/testdata/slow020.golden +++ b/event/testdata/slow020.golden @@ -1,7 +1,9 @@ { "Global": { - "Id": "", + "ID": "", "Fingerprint": "", + "TsMin": "2007-10-15T21:43:52Z", + "TsMax": "2007-10-15T21:44:52Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -41,12 +43,15 @@ } }, "TotalQueries": 2, - "UniqueQueries": 2 + "UniqueQueries": 2, + "LastThreadID": 0 }, "Class": { "295ABC58C3FBD325": { - "Id": "295ABC58C3FBD325", + "ID": "295ABC58C3FBD325", "Fingerprint": "select sleep(?) from o", + "TsMin": "2007-10-15T21:44:52Z", + "TsMax": "2007-10-15T21:44:52Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -93,11 +98,14 @@ "Query": "select sleep(2) from o", "Size": 22, "Ts": "2007-10-15 21:44:52" - } + }, + "LastThreadID": 0 }, "7F7D57ACDD8A346E": { - "Id": "7F7D57ACDD8A346E", + "ID": "7F7D57ACDD8A346E", "Fingerprint": "select sleep(?) from n", + "TsMin": "2007-10-15T21:43:52Z", + "TsMax": "2007-10-15T21:43:52Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -144,7 +152,8 @@ "Query": "select sleep(2) from n", "Size": 22, "Ts": "2007-10-15 21:43:52" - } + }, + "LastThreadID": 0 } }, "RateLimit": 0, diff --git a/event/testdata/slow021.golden b/event/testdata/slow021.golden index 98ec5e0..636cd70 100644 --- a/event/testdata/slow021.golden +++ b/event/testdata/slow021.golden @@ -1,7 +1,9 @@ { "Global": { - "Id": "", + "ID": "", "Fingerprint": "", + "TsMin": "2007-10-15T21:43:52Z", + "TsMax": "2007-10-15T21:43:52Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -41,12 +43,15 @@ } }, "TotalQueries": 1, - "UniqueQueries": 1 + "UniqueQueries": 1, + "LastThreadID": 0 }, "Class": { "7F7D57ACDD8A346E": { - "Id": "7F7D57ACDD8A346E", + "ID": "7F7D57ACDD8A346E", "Fingerprint": "select sleep(?) from n", + "TsMin": "2007-10-15T21:43:52Z", + "TsMax": "2007-10-15T21:43:52Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -93,7 +98,8 @@ "Query": "select sleep(2) from n", "Size": 22, "Ts": "2007-10-15 21:43:52" - } + }, + "LastThreadID": 0 } }, "RateLimit": 0, diff --git a/event/testdata/slow022.golden b/event/testdata/slow022.golden index 98ec5e0..636cd70 100644 --- a/event/testdata/slow022.golden +++ b/event/testdata/slow022.golden @@ -1,7 +1,9 @@ { "Global": { - "Id": "", + "ID": "", "Fingerprint": "", + "TsMin": "2007-10-15T21:43:52Z", + "TsMax": "2007-10-15T21:43:52Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -41,12 +43,15 @@ } }, "TotalQueries": 1, - "UniqueQueries": 1 + "UniqueQueries": 1, + "LastThreadID": 0 }, "Class": { "7F7D57ACDD8A346E": { - "Id": "7F7D57ACDD8A346E", + "ID": "7F7D57ACDD8A346E", "Fingerprint": "select sleep(?) from n", + "TsMin": "2007-10-15T21:43:52Z", + "TsMax": "2007-10-15T21:43:52Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -93,7 +98,8 @@ "Query": "select sleep(2) from n", "Size": 22, "Ts": "2007-10-15 21:43:52" - } + }, + "LastThreadID": 0 } }, "RateLimit": 0, diff --git a/event/testdata/slow023.golden b/event/testdata/slow023.golden index 60375ab..12e085f 100644 --- a/event/testdata/slow023.golden +++ b/event/testdata/slow023.golden @@ -1,7 +1,9 @@ { "Global": { - "Id": "", + "ID": "", "Fingerprint": "", + "TsMin": "0001-01-01T00:00:00Z", + "TsMax": "0001-01-01T00:00:00Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -41,12 +43,15 @@ } }, "TotalQueries": 8, - "UniqueQueries": 8 + "UniqueQueries": 8, + "LastThreadID": 56601 }, "Class": { "54FB1194093381DB": { - "Id": "54FB1194093381DB", + "ID": "54FB1194093381DB", "Fingerprint": "set global slow_query_log=on", + "TsMin": "0001-01-01T00:00:00Z", + "TsMax": "0001-01-01T00:00:00Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -92,11 +97,14 @@ "Db": "", "Query": "SET GLOBAL slow_query_log=ON", "Size": 28 - } + }, + "LastThreadID": 56603 }, "6C099B0B73EA7633": { - "Id": "6C099B0B73EA7633", + "ID": "6C099B0B73EA7633", "Fingerprint": "use ?", + "TsMin": "0001-01-01T00:00:00Z", + "TsMax": "0001-01-01T00:00:00Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -142,11 +150,14 @@ "Db": "dbnameb", "Query": "use `dbnameb`", "Size": 13 - } + }, + "LastThreadID": 56458 }, "7C1934E82086DF57": { - "Id": "7C1934E82086DF57", + "ID": "7C1934E82086DF57", "Fingerprint": "set names utf8", + "TsMin": "0001-01-01T00:00:00Z", + "TsMax": "0001-01-01T00:00:00Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -192,11 +203,14 @@ "Db": "", "Query": "SET NAMES utf8", "Size": 14 - } + }, + "LastThreadID": 56604 }, "83497A0046FCD7A7": { - "Id": "83497A0046FCD7A7", + "ID": "83497A0046FCD7A7", "Fingerprint": "select field from table_a where some_other_field = ? limit ?", + "TsMin": "0001-01-01T00:00:00Z", + "TsMax": "0001-01-01T00:00:00Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -242,11 +256,14 @@ "Db": "dbnamea", "Query": "SELECT field FROM table_a WHERE some_other_field = 'yahoo' LIMIT 1", "Size": 66 - } + }, + "LastThreadID": 56601 }, "9FD5245EAE433B90": { - "Id": "9FD5245EAE433B90", + "ID": "9FD5245EAE433B90", "Fingerprint": "select another_field from table_c where a_third_field = ? and site_id = ?", + "TsMin": "0001-01-01T00:00:00Z", + "TsMax": "0001-01-01T00:00:00Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -292,11 +309,14 @@ "Db": "", "Query": "SELECT another_field FROM table_c WHERE a_third_field = 'tiruriru' AND site_id = 1", "Size": 82 - } + }, + "LastThreadID": 56601 }, "AC5C18B304F9DE87": { - "Id": "AC5C18B304F9DE87", + "ID": "AC5C18B304F9DE87", "Fingerprint": "select @@collation_database", + "TsMin": "0001-01-01T00:00:00Z", + "TsMax": "0001-01-01T00:00:00Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -342,11 +362,14 @@ "Db": "", "Query": "select @@collation_database", "Size": 27 - } + }, + "LastThreadID": 56458 }, "B98E038C9D12BDA1": { - "Id": "B98E038C9D12BDA1", + "ID": "B98E038C9D12BDA1", "Fingerprint": "select field from table_b where another_field = ? and site_id = ?", + "TsMin": "0001-01-01T00:00:00Z", + "TsMax": "0001-01-01T00:00:00Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -392,11 +415,14 @@ "Db": "", "Query": "SELECT field FROM table_b WHERE another_field = 'bazinga' AND site_id = 1", "Size": 73 - } + }, + "LastThreadID": 56601 }, "F0265D81808CE240": { - "Id": "F0265D81808CE240", + "ID": "F0265D81808CE240", "Fingerprint": "select @@session.sql_mode", + "TsMin": "0001-01-01T00:00:00Z", + "TsMax": "0001-01-01T00:00:00Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -442,7 +468,8 @@ "Db": "", "Query": "SELECT @@SESSION.sql_mode", "Size": 25 - } + }, + "LastThreadID": 56604 } }, "RateLimit": 0, diff --git a/event/testdata/slow025.golden b/event/testdata/slow025.golden index d2322ad..d2c2528 100644 --- a/event/testdata/slow025.golden +++ b/event/testdata/slow025.golden @@ -1,7 +1,9 @@ { "Global": { - "Id": "", + "ID": "", "Fingerprint": "", + "TsMin": "2007-10-15T00:00:01Z", + "TsMax": "2007-10-15T00:00:03Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -41,12 +43,15 @@ } }, "TotalQueries": 2001, - "UniqueQueries": 1 + "UniqueQueries": 1, + "LastThreadID": 0 }, "Class": { "FDE00DF974C61E9F": { - "Id": "FDE00DF974C61E9F", + "ID": "FDE00DF974C61E9F", "Fingerprint": "select c from t", + "TsMin": "2007-10-15T00:00:01Z", + "TsMax": "2007-10-15T00:00:03Z", "Metrics": { "TimeMetrics": { "Lock_time": { @@ -93,7 +98,8 @@ "Query": "select c from t", "Size": 15, "Ts": "2007-10-15 00:00:02" - } + }, + "LastThreadID": 0 } }, "RateLimit": 1000, diff --git a/log/log.go b/log/log.go index 97a6195..31827eb 100644 --- a/log/log.go +++ b/log/log.go @@ -39,6 +39,7 @@ type Event struct { User string Host string Db string + ThreadID uint64 // Thread_id of query TimeMetrics map[string]float64 // *_time and *_wait metrics NumberMetrics map[string]uint64 // most metrics BoolMetrics map[string]bool // yes/no metrics diff --git a/log/slow/parser.go b/log/slow/parser.go index 3c6e09c..ee694f9 100644 --- a/log/slow/parser.go +++ b/log/slow/parser.go @@ -37,6 +37,7 @@ var ( timeRe = regexp.MustCompile(`Time: (\S+\s{1,2}\S+)`) timeNewRe = regexp.MustCompile(`Time:\s+(\d{4}-\d{2}-\d{2}\S+)`) userRe = regexp.MustCompile(`User@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]`) + idRe = regexp.MustCompile(`(Id): +([0-9]*)`) schema = regexp.MustCompile(`Schema: +(.*?) +Last_errno:`) headerRe = regexp.MustCompile(`^#\s+[A-Z]`) metricsRe = regexp.MustCompile(`(\w+): (\S+|\z)`) @@ -239,12 +240,18 @@ func (p *SlowLogParser) parseHeader(line string) { if p.opt.Debug { l.Println("user") } + m := userRe.FindStringSubmatch(line) - if len(m) < 3 { - return + if len(m) >= 3 { + p.event.User = m[1] + p.event.Host = m[2] + } + + m1 := idRe.FindStringSubmatch(line) + if len(m1) >= 2 { + val, _ := strconv.ParseUint(m1[2], 10, 64) + p.event.ThreadID = val } - p.event.User = m[1] - p.event.Host = m[2] } else if strings.HasPrefix(line, "# admin") { p.parseAdmin(line) } else { @@ -277,6 +284,9 @@ func (p *SlowLogParser) parseHeader(line string) { } else if smv[1] == "Log_slow_rate_limit" { val, _ := strconv.ParseUint(smv[2], 10, 64) p.event.RateLimit = uint(val) + } else if smv[1] == "Thread_id" { + val, _ := strconv.ParseUint(smv[2], 10, 64) + p.event.ThreadID = val } else { // integer value val, _ := strconv.ParseUint(smv[2], 10, 64) diff --git a/log/slow/parser_test.go b/log/slow/parser_test.go index 6351b6f..049ea81 100644 --- a/log/slow/parser_test.go +++ b/log/slow/parser_test.go @@ -122,13 +122,13 @@ func TestParseSlowLog002(t *testing.T) { Host: "", Offset: 0, OffsetEnd: 337, + ThreadID: 10, TimeMetrics: map[string]float64{ "Query_time": 0.000012, "Lock_time": 0.000000, }, NumberMetrics: map[string]uint64{ "Merge_passes": 0, - "Thread_id": 10, "Rows_examined": 0, "Rows_sent": 0, }, @@ -152,13 +152,13 @@ func TestParseSlowLog002(t *testing.T) { Host: "", Offset: 337, OffsetEnd: 814, + ThreadID: 10, TimeMetrics: map[string]float64{ "Query_time": 0.726052, "Lock_time": 0.000091, }, NumberMetrics: map[string]uint64{ "Merge_passes": 0, - "Thread_id": 10, "Rows_examined": 62951, "Rows_sent": 0, }, @@ -180,6 +180,7 @@ VALUES ('', 'Exact')`, Host: "", Offset: 814, OffsetEnd: 1333, + ThreadID: 10, TimeMetrics: map[string]float64{ "InnoDB_queue_wait": 0.000000, "Lock_time": 0.000077, @@ -192,7 +193,6 @@ VALUES ('', 'Exact')`, "Merge_passes": 0, "InnoDB_pages_distinct": 24, "Rows_sent": 0, - "Thread_id": 10, "Rows_examined": 0, "InnoDB_IO_r_ops": 0, }, @@ -210,6 +210,7 @@ VALUES ('', 'Exact')`, Query: `UPDATE db4.vab3concept1upload SET vab3concept1id = '91848182522' WHERE vab3concept1upload='6994465'`, + ThreadID: 10, Admin: false, User: "[SQL_SLAVE]", Host: "", @@ -227,7 +228,6 @@ WHERE vab3concept1upload='6994465'`, "Merge_passes": 0, "InnoDB_pages_distinct": 11, "Rows_sent": 0, - "Thread_id": 10, "Rows_examined": 0, "InnoDB_IO_r_ops": 0, }, @@ -244,6 +244,7 @@ WHERE vab3concept1upload='6994465'`, { Query: `INSERT INTO db1.conch (word3, vid83) VALUES ('211', '18')`, + ThreadID: 10, Admin: false, User: "[SQL_SLAVE]", Host: "", @@ -261,7 +262,6 @@ VALUES ('211', '18')`, "Merge_passes": 0, "InnoDB_pages_distinct": 18, "Rows_sent": 0, - "Thread_id": 10, "Rows_examined": 0, "InnoDB_IO_r_ops": 0, }, @@ -278,6 +278,7 @@ VALUES ('211', '18')`, { Query: `UPDATE foo.bar SET biz = '91848182522'`, + ThreadID: 10, Admin: false, User: "[SQL_SLAVE]", Host: "", @@ -295,7 +296,6 @@ SET biz = '91848182522'`, "Merge_passes": 0, "InnoDB_pages_distinct": 18, "Rows_sent": 0, - "Thread_id": 10, "Rows_examined": 0, "InnoDB_IO_r_ops": 0, }, @@ -313,6 +313,7 @@ SET biz = '91848182522'`, Query: `UPDATE bizzle.bat SET boop='bop: 899' WHERE fillze='899'`, + ThreadID: 10, Admin: false, User: "[SQL_SLAVE]", Host: "", @@ -330,7 +331,6 @@ WHERE fillze='899'`, "Merge_passes": 0, "InnoDB_pages_distinct": 18, "Rows_sent": 0, - "Thread_id": 10, "Rows_examined": 0, "InnoDB_IO_r_ops": 0, }, @@ -347,6 +347,7 @@ WHERE fillze='899'`, { Query: `UPDATE foo.bar SET biz = '91848182522'`, + ThreadID: 10, Admin: false, User: "[SQL_SLAVE]", Host: "", @@ -364,7 +365,6 @@ SET biz = '91848182522'`, "Merge_passes": 0, "InnoDB_pages_distinct": 18, "Rows_sent": 0, - "Thread_id": 10, "Rows_examined": 0, "InnoDB_IO_r_ops": 0, }, @@ -387,6 +387,7 @@ func TestParserSlowLog003(t *testing.T) { got := parseSlowLog("slow003.log", opt) expect := []log.Event{ { + ThreadID: 10, Query: "BEGIN", Admin: false, Host: "", @@ -411,7 +412,6 @@ func TestParserSlowLog003(t *testing.T) { "Merge_passes": 0, "Rows_examined": 0, "Rows_sent": 0, - "Thread_id": 10, }, }, } @@ -455,6 +455,7 @@ func TestParserSlowLog005(t *testing.T) { got := parseSlowLog("slow005.log", opt) expect := []log.Event{ { + ThreadID: 10, Query: "foo\nbar\n\t\t\t0 AS counter\nbaz", Admin: false, Host: "", @@ -479,7 +480,6 @@ func TestParserSlowLog005(t *testing.T) { "Merge_passes": 0, "Rows_examined": 0, "Rows_sent": 0, - "Thread_id": 10, }, }, } @@ -492,6 +492,7 @@ func TestParserSlowLog006(t *testing.T) { got := parseSlowLog("slow006.log", opt) expect := []log.Event{ { + ThreadID: 10, Query: "SELECT col FROM foo_tbl", Db: "foo", Admin: false, @@ -517,10 +518,10 @@ func TestParserSlowLog006(t *testing.T) { "Merge_passes": 0, "Rows_examined": 0, "Rows_sent": 0, - "Thread_id": 10, }, }, { + ThreadID: 10, Query: "SELECT col FROM foo_tbl", Db: "foo", Admin: false, @@ -546,10 +547,10 @@ func TestParserSlowLog006(t *testing.T) { "Merge_passes": 0, "Rows_examined": 0, "Rows_sent": 0, - "Thread_id": 10, }, }, { + ThreadID: 20, Query: "SELECT col FROM bar_tbl", Db: "bar", Admin: false, @@ -575,10 +576,10 @@ func TestParserSlowLog006(t *testing.T) { "Merge_passes": 0, "Rows_examined": 0, "Rows_sent": 0, - "Thread_id": 20, }, }, { + ThreadID: 10, Query: "SELECT col FROM bar_tbl", Db: "bar", Admin: false, @@ -604,10 +605,10 @@ func TestParserSlowLog006(t *testing.T) { "Merge_passes": 0, "Rows_examined": 0, "Rows_sent": 0, - "Thread_id": 10, }, }, { + ThreadID: 20, Query: "SELECT col FROM bar_tbl", Db: "bar", Admin: false, @@ -633,10 +634,10 @@ func TestParserSlowLog006(t *testing.T) { "Merge_passes": 0, "Rows_examined": 0, "Rows_sent": 0, - "Thread_id": 20, }, }, { + ThreadID: 30, Query: "SELECT col FROM foo_tbl", Db: "foo", Admin: false, @@ -662,7 +663,6 @@ func TestParserSlowLog006(t *testing.T) { "Merge_passes": 0, "Rows_examined": 0, "Rows_sent": 0, - "Thread_id": 30, }, }, } @@ -681,6 +681,7 @@ func TestParserSlowLog007(t *testing.T) { Ts: time.Date(2007, 12, 18, 11, 48, 27, 0, time.UTC), User: "[SQL_SLAVE]", Offset: 0, + ThreadID: 3, OffsetEnd: 193, BoolMetrics: map[string]bool{}, TimeMetrics: map[string]float64{ @@ -690,7 +691,6 @@ func TestParserSlowLog007(t *testing.T) { NumberMetrics: map[string]uint64{ "Rows_examined": 0, "Rows_sent": 0, - "Thread_id": 3, }, }, } @@ -713,6 +713,7 @@ func TestParserSlowLog008(t *testing.T) { Host: "", User: "meow", Offset: 0, + ThreadID: 5, OffsetEnd: 220, BoolMetrics: map[string]bool{}, TimeMetrics: map[string]float64{ @@ -722,7 +723,6 @@ func TestParserSlowLog008(t *testing.T) { NumberMetrics: map[string]uint64{ "Rows_examined": 0, "Rows_sent": 0, - "Thread_id": 5, }, }, { @@ -731,6 +731,7 @@ func TestParserSlowLog008(t *testing.T) { Admin: false, Host: "", User: "meow", + ThreadID: 6, Offset: 220, OffsetEnd: 434, BoolMetrics: map[string]bool{}, @@ -741,7 +742,6 @@ func TestParserSlowLog008(t *testing.T) { NumberMetrics: map[string]uint64{ "Rows_examined": 0, "Rows_sent": 0, - "Thread_id": 6, }, }, { @@ -750,6 +750,7 @@ func TestParserSlowLog008(t *testing.T) { Admin: false, Host: "", User: "meow", + ThreadID: 6, Offset: 434, OffsetEnd: 656, BoolMetrics: map[string]bool{}, @@ -760,7 +761,6 @@ func TestParserSlowLog008(t *testing.T) { NumberMetrics: map[string]uint64{ "Rows_examined": 0, "Rows_sent": 0, - "Thread_id": 6, }, }, } @@ -776,6 +776,7 @@ func TestParserSlowLog009(t *testing.T) { got := parseSlowLog("slow009.log", opt) expect := []log.Event{ { + ThreadID: 47, Query: "Refresh", Db: "", Admin: true, @@ -794,7 +795,6 @@ func TestParserSlowLog009(t *testing.T) { "Rows_examined": 0, "Rows_read": 0, "Rows_sent": 0, - "Thread_id": 47, }, BoolMetrics: map[string]bool{ "QC_Hit": false, @@ -824,6 +824,7 @@ func TestParserSlowLog011(t *testing.T) { Ts: time.Date(2013, 11, 28, 1, 05, 31, 0, time.UTC), RateType: "query", RateLimit: 2, + ThreadID: 69194, TimeMetrics: map[string]float64{ "Query_time": 0.000228, "Lock_time": 0.000114, @@ -866,6 +867,7 @@ func TestParserSlowLog011(t *testing.T) { User: "user1", RateType: "query", RateLimit: 2, + ThreadID: 69195, TimeMetrics: map[string]float64{ "Query_time": 0.000237, "Lock_time": 0.000122, @@ -908,6 +910,7 @@ func TestParserSlowLog011(t *testing.T) { User: "user1", RateType: "query", RateLimit: 2, + ThreadID: 69195, TimeMetrics: map[string]float64{ "Query_time": 0.000165, "Lock_time": 0.000048, @@ -949,6 +952,7 @@ func TestParserSlowLog012(t *testing.T) { got := parseSlowLog("slow012.log", opt) expect := []log.Event{ { + ThreadID: 168, Query: "select * from mysql.user", Db: "", Host: "localhost", @@ -966,6 +970,7 @@ func TestParserSlowLog012(t *testing.T) { BoolMetrics: map[string]bool{}, }, { + ThreadID: 168, Query: "Quit", Admin: true, Db: "", @@ -984,6 +989,7 @@ func TestParserSlowLog012(t *testing.T) { BoolMetrics: map[string]bool{}, }, { + ThreadID: 169, Query: "SELECT @@max_allowed_packet", Db: "dev_pct", Host: "localhost", @@ -1010,6 +1016,7 @@ func TestParserSlowLog013(t *testing.T) { got := parseSlowLog("slow013.log", opt) expect := []log.Event{ { + ThreadID: 208333, Offset: 0, OffsetEnd: 353, Ts: time.Date(2014, 02, 24, 22, 39, 34, 0, time.UTC), @@ -1032,6 +1039,7 @@ func TestParserSlowLog013(t *testing.T) { BoolMetrics: map[string]bool{}, }, { + ThreadID: 208345, Offset: 353, OffsetEnd: 6138, Ts: time.Date(2014, 02, 24, 22, 39, 59, 0, time.UTC), @@ -1054,6 +1062,7 @@ func TestParserSlowLog013(t *testing.T) { BoolMetrics: map[string]bool{}, }, { + ThreadID: 50, Offset: 6138, OffsetEnd: 6666, Ts: time.Date(2014, 03, 11, 16, 07, 40, 0, time.UTC), @@ -1076,6 +1085,7 @@ func TestParserSlowLog013(t *testing.T) { BoolMetrics: map[string]bool{}, }, { + ThreadID: 45006, Offset: 6666, OffsetEnd: 7014, Ts: time.Date(2014, 03, 12, 20, 28, 40, 0, time.UTC), @@ -1098,6 +1108,7 @@ func TestParserSlowLog013(t *testing.T) { BoolMetrics: map[string]bool{}, }, { + ThreadID: 45321, Offset: 7014, OffsetEnd: 7370, Ts: time.Date(2014, 03, 12, 20, 29, 40, 0, time.UTC), @@ -1128,6 +1139,7 @@ func TestParserSlowLog014(t *testing.T) { got := parseSlowLog("slow014.log", opt) expect := []log.Event{ { + ThreadID: 103375137, Offset: 0, OffsetEnd: 690, Admin: false, @@ -1155,7 +1167,6 @@ func TestParserSlowLog014(t *testing.T) { "Rows_examined": 1, "Rows_read": 1, "Rows_sent": 1, - "Thread_id": 103375137, "Tmp_disk_tables": 0, "Tmp_table_sizes": 0, "Tmp_tables": 0, @@ -1174,6 +1185,7 @@ func TestParserSlowLog014(t *testing.T) { /** * Here it is: */ + ThreadID: 103375137, Offset: 690, OffsetEnd: 2104, Admin: false, @@ -1201,7 +1213,6 @@ func TestParserSlowLog014(t *testing.T) { "Rows_examined": 0, "Rows_read": 0, "Rows_sent": 0, - "Thread_id": 103375137, "Tmp_disk_tables": 0, "Tmp_table_sizes": 0, "Tmp_tables": 1, @@ -1217,6 +1228,7 @@ func TestParserSlowLog014(t *testing.T) { }, }, { + ThreadID: 103375137, Offset: 2104, OffsetEnd: 3163, Query: "SELECT COUNT(userfing.keyval) AS total\n\u0009\u0009\u0009FROM\n\u0009\u0009\u0009((### All Content ###\n\u0009\u0009\u0009\u0009\u0009SELECT f.nodeid AS keyval\n\u0009\u0009\u0009\u0009\u0009FROM node AS f\n\u0009\u0009\u0009\u0009\u0009INNER JOIN subscribed AS sd ON sd.did = f.nodeid AND sd.userid = 15965) UNION ALL (\n\u0009\u0009\u0009\u0009\u0009### Users ###\n\u0009\u0009\u0009\u0009\u0009SELECT f.userid AS keyval\n\u0009\u0009\u0009\u0009\u0009FROM user AS f\n\u0009\u0009\u0009\u0009\u0009INNER JOIN userlist AS ul ON ul.relationid = f.userid AND ul.userid = 15965\n\u0009\u0009\u0009\u0009\u0009WHERE ul.type = 'f' AND ul.aq = 'yes')\n) AS userfing", @@ -1243,7 +1255,6 @@ func TestParserSlowLog014(t *testing.T) { "Rows_examined": 0, "Rows_read": 0, "Rows_sent": 1, - "Thread_id": 103375137, "Tmp_disk_tables": 0, "Tmp_table_sizes": 0, "Tmp_tables": 2, @@ -1259,6 +1270,7 @@ func TestParserSlowLog014(t *testing.T) { }, }, { + ThreadID: 103375137, Offset: 3163, OffsetEnd: 4410, Query: "SELECT u.userid, u.name AS name, u.usergroupid AS usergroupid, IFNULL(u.lastactivity, u.joindate) as lastactivity,\n\u0009\u0009\u0009\u0009IFNULL((SELECT userid FROM userlist AS ul2 WHERE ul2.userid = 15965 AND ul2.relationid = u.userid AND ul2.type = 'f' AND ul2.aq = 'yes'), 0) as isFollowing,\n\u0009\u0009\u0009\u0009IFNULL((SELECT userid FROM userlist AS ul2 WHERE ul2.userid = 15965 AND ul2.relationid = u.userid AND ul2.type = 'f' AND ul2.aq = 'pending'), 0) as isPending\nFROM user AS u\n\u0009\u0009\u0009\u0009INNER JOIN userlist AS ul ON (u.userid = ul.userid AND ul.relationid = 15965)\n\n\u0009\u0009\u0009WHERE ul.type = 'f' AND ul.aq = 'yes'\nORDER BY name ASC\nLIMIT 0, 100", @@ -1285,7 +1297,6 @@ func TestParserSlowLog014(t *testing.T) { "Rows_examined": 0, "Rows_read": 0, "Rows_sent": 0, - "Thread_id": 103375137, "Tmp_disk_tables": 0, "Tmp_table_sizes": 0, "Tmp_tables": 1, @@ -1345,6 +1356,7 @@ func TestParseSlow016(t *testing.T) { got := parseSlowLog("slow016.log", log.Options{Debug: false}) expect := []log.Event{ { + ThreadID: 68181423, Query: `SHOW /*!50002 GLOBAL */ STATUS`, User: "pt_agent", Host: "localhost", @@ -1372,6 +1384,7 @@ func TestParseSlow017(t *testing.T) { got := parseSlowLog("slow017.log", opt) expect := []log.Event{ { + ThreadID: 68181423, Query: `SHOW /*!50002 GLOBAL */ STATUS`, User: "pt_agent", Host: "localhost", @@ -1398,6 +1411,7 @@ func TestParseSlow019(t *testing.T) { got := parseSlowLog("slow019.log", opt) expect := []log.Event{ { + ThreadID: 37911936, Query: `SELECT TABLE_SCHEMA, TABLE_NAME, ROWS_READ, ROWS_CHANGED, ROWS_CHANGED_X_INDEXES FROM INFORMATION_SCHEMA.TABLE_STATISTICS`, User: "percona-agent", Host: "localhost", @@ -1416,7 +1430,6 @@ func TestParseSlow019(t *testing.T) { "Rows_examined": 1473, "Rows_read": 1473, "Rows_sent": 1473, - "Thread_id": 37911936, "Tmp_disk_tables": 0, "Tmp_table_sizes": 0, "Tmp_tables": 1, @@ -1432,6 +1445,7 @@ func TestParseSlow019(t *testing.T) { }, }, { + ThreadID: 57434695, Query: `SELECT cid, data, created, expire, serialized FROM cache_field WHERE cid IN ('field_info:bundle_extra:user:user')`, User: "root", Host: "localhost", @@ -1451,7 +1465,6 @@ func TestParseSlow019(t *testing.T) { "Rows_examined": 0, "Rows_read": 0, "Rows_sent": 0, - "Thread_id": 57434695, "Tmp_disk_tables": 0, "Tmp_table_sizes": 0, "Tmp_tables": 0, @@ -1467,6 +1480,7 @@ func TestParseSlow019(t *testing.T) { }, }, { + ThreadID: 57434695, Query: "UPDATE captcha_sessions SET timestamp='1413583348', solution='1'\nWHERE (csid = '28439')", User: "root", Host: "localhost", @@ -1493,7 +1507,6 @@ func TestParseSlow019(t *testing.T) { "Rows_examined": 1, "Rows_read": 1, "Rows_sent": 0, - "Thread_id": 57434695, "Tmp_disk_tables": 0, "Tmp_table_sizes": 0, "Tmp_tables": 0, @@ -1509,6 +1522,7 @@ func TestParseSlow019(t *testing.T) { }, }, { + ThreadID: 37911936, Query: `SELECT TABLE_SCHEMA, TABLE_NAME, INDEX_NAME, ROWS_READ FROM INFORMATION_SCHEMA.INDEX_STATISTICS`, User: "percona-agent", Host: "localhost", @@ -1527,7 +1541,6 @@ func TestParseSlow019(t *testing.T) { "Rows_examined": 2146, "Rows_read": 2146, "Rows_sent": 2146, - "Thread_id": 37911936, "Tmp_disk_tables": 0, "Tmp_table_sizes": 0, "Tmp_tables": 1, @@ -1552,6 +1565,7 @@ func TestParseSlow023(t *testing.T) { expect := []log.Event{ // Slice 0 { + ThreadID: 56601, Offset: 176, OffsetEnd: 418, Admin: false, @@ -1573,6 +1587,7 @@ func TestParseSlow023(t *testing.T) { }, // Slice 1 { + ThreadID: 56604, Offset: 418, OffsetEnd: 595, Admin: false, @@ -1594,6 +1609,7 @@ func TestParseSlow023(t *testing.T) { }, // Slice 2 { + ThreadID: 56603, Offset: 595, OffsetEnd: 794, Admin: false, @@ -1615,6 +1631,7 @@ func TestParseSlow023(t *testing.T) { }, // Slice 3 { + ThreadID: 56604, Offset: 794, OffsetEnd: 982, Admin: false, @@ -1636,6 +1653,7 @@ func TestParseSlow023(t *testing.T) { }, // Slice 4 { + ThreadID: 56601, Offset: 982, OffsetEnd: 1218, Admin: false, @@ -1656,6 +1674,7 @@ func TestParseSlow023(t *testing.T) { }, // Slice 5 { + ThreadID: 56458, Offset: 1218, OffsetEnd: 1388, Admin: false, @@ -1677,6 +1696,7 @@ func TestParseSlow023(t *testing.T) { }, // Slice 6 { + ThreadID: 56458, Offset: 1388, OffsetEnd: 1572, Admin: false, @@ -1698,6 +1718,7 @@ func TestParseSlow023(t *testing.T) { }, // Slice 7 { + ThreadID: 56601, Offset: 1572, OffsetEnd: 1817, Admin: false, @@ -1821,6 +1842,7 @@ func TestParseSlowMariaDBWithExplain(t *testing.T) { got := parseSlowLog("mariadb102-with-explain.log", opt) expect := []log.Event{ { + ThreadID: 8, Offset: 205, OffsetEnd: 630, Ts: time.Date(2018, 02, 14, 16, 18, 07, 0, time.UTC), @@ -1837,7 +1859,6 @@ func TestParseSlowMariaDBWithExplain(t *testing.T) { "Rows_affected": 0, "Rows_examined": 0, "Rows_sent": 1, - "Thread_id": 8, }, BoolMetrics: map[string]bool{ "QC_hit": false, @@ -1861,6 +1882,7 @@ func TestParseSlow026(t *testing.T) { User: "test", Host: "", Db: "test", + ThreadID: 17, TimeMetrics: map[string]float64{ "Lock_time": 0, "Query_time": 1.000249,