From 2dcf87302c2d4bfbf046d488aa258ddba8ef67eb Mon Sep 17 00:00:00 2001 From: crazycs Date: Tue, 30 Apr 2019 10:18:28 +0800 Subject: [PATCH] *: add more cop task and memory info to slow_query table (#10264) (#10317) --- executor/aggregate_test.go | 2 +- infoschema/slow_log.go | 101 +++++++++++++++++++++++++++++------- infoschema/slow_log_test.go | 5 +- infoschema/tables_test.go | 8 ++- 4 files changed, 93 insertions(+), 23 deletions(-) diff --git a/executor/aggregate_test.go b/executor/aggregate_test.go index 949c9ed9cfde6..f3a61e79888e2 100644 --- a/executor/aggregate_test.go +++ b/executor/aggregate_test.go @@ -239,7 +239,7 @@ func (s *testSuite) TestAggregation(c *C) { result = tk.MustQuery("select count(*) from information_schema.columns") // When adding new memory columns in information_schema, please update this variable. - columnCountOfAllInformationSchemaTables := "786" + columnCountOfAllInformationSchemaTables := "793" result.Check(testkit.Rows(columnCountOfAllInformationSchemaTables)) tk.MustExec("drop table if exists t1") diff --git a/infoschema/slow_log.go b/infoschema/slow_log.go index 4abd35a7f2de1..6acf9fece222a 100644 --- a/infoschema/slow_log.go +++ b/infoschema/slow_log.go @@ -48,6 +48,13 @@ var slowQueryCols = []columnInfo{ {variable.SlowLogIsInternalStr, mysql.TypeTiny, 1, 0, nil, nil}, {variable.SlowLogDigestStr, mysql.TypeVarchar, 64, 0, nil, nil}, {variable.SlowLogStatsInfoStr, mysql.TypeVarchar, 512, 0, nil, nil}, + {variable.SlowLogCopProcAvg, mysql.TypeDouble, 22, 0, nil, nil}, + {variable.SlowLogCopProcP90, mysql.TypeDouble, 22, 0, nil, nil}, + {variable.SlowLogCopProcMax, mysql.TypeDouble, 22, 0, nil, nil}, + {variable.SlowLogCopWaitAvg, mysql.TypeDouble, 22, 0, nil, nil}, + {variable.SlowLogCopWaitP90, mysql.TypeDouble, 22, 0, nil, nil}, + {variable.SlowLogCopWaitMax, mysql.TypeDouble, 22, 0, nil, nil}, + {variable.SlowLogMemMax, mysql.TypeLonglong, 20, 0, nil, nil}, {variable.SlowLogQuerySQLStr, mysql.TypeVarchar, 4096, 0, nil, nil}, } @@ -124,23 +131,30 @@ func ParseSlowLog(tz *time.Location, scanner *bufio.Scanner) ([][]types.Datum, e } type slowQueryTuple struct { - time time.Time - txnStartTs uint64 - user string - connID uint64 - queryTime float64 - processTime float64 - waitTime float64 - backOffTime float64 - requestCount uint64 - totalKeys uint64 - processKeys uint64 - db string - indexNames string - isInternal bool - digest string - statsInfo string - sql string + time time.Time + txnStartTs uint64 + user string + connID uint64 + queryTime float64 + processTime float64 + waitTime float64 + backOffTime float64 + requestCount uint64 + totalKeys uint64 + processKeys uint64 + db string + indexIDs string + isInternal bool + digest string + statsInfo string + avgProcessTime float64 + p90ProcessTime float64 + maxProcessTime float64 + avgWaitTime float64 + p90WaitTime float64 + maxWaitTime float64 + memMax int64 + sql string } func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string) error { @@ -213,13 +227,55 @@ func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string) case variable.SlowLogDBStr: st.db = value case variable.SlowLogIndexIDsStr: - st.indexNames = value + st.indexIDs = value case variable.SlowLogIsInternalStr: st.isInternal = value == "true" case variable.SlowLogDigestStr: st.digest = value case variable.SlowLogStatsInfoStr: st.statsInfo = value + case variable.SlowLogCopProcAvg: + num, err := strconv.ParseFloat(value, 64) + if err != nil { + return errors.AddStack(err) + } + st.avgProcessTime = num + case variable.SlowLogCopProcP90: + num, err := strconv.ParseFloat(value, 64) + if err != nil { + return errors.AddStack(err) + } + st.p90ProcessTime = num + case variable.SlowLogCopProcMax: + num, err := strconv.ParseFloat(value, 64) + if err != nil { + return errors.AddStack(err) + } + st.maxProcessTime = num + case variable.SlowLogCopWaitAvg: + num, err := strconv.ParseFloat(value, 64) + if err != nil { + return errors.AddStack(err) + } + st.avgWaitTime = num + case variable.SlowLogCopWaitP90: + num, err := strconv.ParseFloat(value, 64) + if err != nil { + return errors.AddStack(err) + } + st.p90WaitTime = num + case variable.SlowLogCopWaitMax: + num, err := strconv.ParseFloat(value, 64) + if err != nil { + return errors.AddStack(err) + } + st.maxWaitTime = num + case variable.SlowLogMemMax: + num, err := strconv.ParseInt(value, 10, 64) + if err != nil { + return errors.AddStack(err) + } + st.memMax = num case variable.SlowLogQuerySQLStr: st.sql = value } @@ -244,10 +300,17 @@ func (st *slowQueryTuple) convertToDatumRow() []types.Datum { record = append(record, types.NewUintDatum(st.totalKeys)) record = append(record, types.NewUintDatum(st.processKeys)) record = append(record, types.NewStringDatum(st.db)) - record = append(record, types.NewStringDatum(st.indexNames)) + record = append(record, types.NewStringDatum(st.indexIDs)) record = append(record, types.NewDatum(st.isInternal)) record = append(record, types.NewStringDatum(st.digest)) record = append(record, types.NewStringDatum(st.statsInfo)) + record = append(record, types.NewFloat64Datum(st.avgProcessTime)) + record = append(record, types.NewFloat64Datum(st.p90ProcessTime)) + record = append(record, types.NewFloat64Datum(st.maxProcessTime)) + record = append(record, types.NewFloat64Datum(st.avgWaitTime)) + record = append(record, types.NewFloat64Datum(st.p90WaitTime)) + record = append(record, types.NewFloat64Datum(st.maxWaitTime)) + record = append(record, types.NewIntDatum(st.memMax)) record = append(record, types.NewStringDatum(st.sql)) return record } diff --git a/infoschema/slow_log_test.go b/infoschema/slow_log_test.go index a619f4b532642..cb16fcf291b1e 100644 --- a/infoschema/slow_log_test.go +++ b/infoschema/slow_log_test.go @@ -32,6 +32,9 @@ func (s *testSuite) TestParseSlowLogFile(c *C) { # Is_internal: true # Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772 # Stats: t1:1,t2:2 +# Cop_proc_avg: 0.1 Cop_proc_p90: 0.2 Cop_proc_max: 0.03 +# Cop_wait_avg: 0.05 Cop_wait_p90: 0.6 Cop_wait_max: 0.8 +# Mem_max: 70724 select * from t;`) scanner := bufio.NewScanner(slowLog) loc, err := time.LoadLocation("Asia/Shanghai") @@ -48,7 +51,7 @@ 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,select * from t;" + 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;" c.Assert(expectRecordString, Equals, recordString) // fix sql contain '# ' bug diff --git a/infoschema/tables_test.go b/infoschema/tables_test.go index 52850ad8de630..1f57cdb29da39 100644 --- a/infoschema/tables_test.go +++ b/infoschema/tables_test.go @@ -308,6 +308,9 @@ func (s *testSuite) TestSlowQuery(c *C) { # Is_internal: false # Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772 # Stats: t1:1,t2:2 +# Cop_proc_avg: 0.1 Cop_proc_p90: 0.2 Cop_proc_max: 0.03 +# Cop_wait_avg: 0.05 Cop_wait_p90: 0.6 Cop_wait_max: 0.8 +# Mem_max: 70724 select * from t_slim;`)) c.Assert(f.Close(), IsNil) c.Assert(err, IsNil) @@ -315,8 +318,9 @@ select * from t_slim;`)) tk.MustExec(fmt.Sprintf("set @@tidb_slow_query_file='%v'", slowLogFileName)) tk.MustExec("set time_zone = '+08:00';") re := tk.MustQuery("select * from information_schema.slow_query") - re.Check(testutil.RowsWithSep("|", "2019-02-12 19:33:56.571953|406315658548871171|root@127.0.0.1|6|4.895492|0.161|0.101|0.092|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|select * from t_slim;")) + re.Check(testutil.RowsWithSep("|", + "2019-02-12 19:33:56.571953|406315658548871171|root@127.0.0.1|6|4.895492|0.161|0.101|0.092|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|0.1|0.2|0.03|0.05|0.6|0.8|70724|select * from t_slim;")) tk.MustExec("set time_zone = '+00:00';") re = tk.MustQuery("select * from information_schema.slow_query") - re.Check(testutil.RowsWithSep("|", "2019-02-12 11:33:56.571953|406315658548871171|root@127.0.0.1|6|4.895492|0.161|0.101|0.092|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|select * from t_slim;")) + re.Check(testutil.RowsWithSep("|", "2019-02-12 11:33:56.571953|406315658548871171|root@127.0.0.1|6|4.895492|0.161|0.101|0.092|1|100001|100000|test||0|42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772|t1:1,t2:2|0.1|0.2|0.03|0.05|0.6|0.8|70724|select * from t_slim;")) }