From a9eae6e4ba4c0ced9c454ee95f038abee4b1e361 Mon Sep 17 00:00:00 2001 From: crazycs Date: Tue, 29 Oct 2024 01:12:30 +0800 Subject: [PATCH 1/3] This is an automated cherry-pick of #56356 Signed-off-by: ti-chi-bot --- executor/slow_query.go | 78 ++-- executor/slow_query_test.go | 153 ++++++++ infoschema/cluster_tables_test.go | 2 +- pkg/executor/cluster_table_test.go | 356 +++++++++++++++++++ planner/core/memtable_predicate_extractor.go | 13 +- 5 files changed, 573 insertions(+), 29 deletions(-) create mode 100644 pkg/executor/cluster_table_test.go diff --git a/executor/slow_query.go b/executor/slow_query.go index 9900ed61a41ee..a93dfb73b673d 100644 --- a/executor/slow_query.go +++ b/executor/slow_query.go @@ -923,18 +923,6 @@ func (e *slowQueryRetriever) getAllFiles(ctx context.Context, sctx sessionctx.Co e.stats.totalFileNum = totalFileNum }() } - if e.extractor == nil || !e.extractor.Enable { - totalFileNum = 1 - //nolint: gosec - file, err := os.Open(logFilePath) - if err != nil { - if os.IsNotExist(err) { - return nil, nil - } - return nil, err - } - return []logFile{{file: file}}, nil - } var logFiles []logFile logDir := filepath.Dir(logFilePath) ext := filepath.Ext(logFilePath) @@ -978,17 +966,20 @@ func (e *slowQueryRetriever) getAllFiles(ctx context.Context, sctx sessionctx.Co return handleErr(err) } start := types.NewTime(types.FromGoTime(fileStartTime), mysql.TypeDatetime, types.MaxFsp) - notInAllTimeRanges := true - for _, tr := range e.checker.timeRanges { - if start.Compare(tr.endTime) <= 0 { - notInAllTimeRanges = false - break + if e.checker.enableTimeCheck { + notInAllTimeRanges := true + for _, tr := range e.checker.timeRanges { + if start.Compare(tr.endTime) <= 0 { + notInAllTimeRanges = false + break + } + } + if notInAllTimeRanges { + return nil } - } - if notInAllTimeRanges { - return nil } +<<<<<<< HEAD:executor/slow_query.go // Get the file end time. fileEndTime, err := e.getFileEndTime(ctx, file) if err != nil { @@ -1000,6 +991,28 @@ func (e *slowQueryRetriever) getAllFiles(ctx context.Context, sctx sessionctx.Co if !(start.Compare(tr.endTime) > 0 || end.Compare(tr.startTime) < 0) { inTimeRanges = true break +======= + // If we want to get the end time from a compressed file, + // we need uncompress the whole file which is very slow and consume a lot of memory. + if !compressed { + // Get the file end time. + fileEndTime, err := e.getFileEndTime(ctx, file) + if err != nil { + return handleErr(err) + } + if e.checker.enableTimeCheck { + end := types.NewTime(types.FromGoTime(fileEndTime), mysql.TypeDatetime, types.MaxFsp) + inTimeRanges := false + for _, tr := range e.checker.timeRanges { + if !(start.Compare(tr.endTime) > 0 || end.Compare(tr.startTime) < 0) { + inTimeRanges = true + break + } + } + if !inTimeRanges { + return nil + } +>>>>>>> 484c1ae88ee (executor: fix issue that query slow_query table return wrong result (#56356)):pkg/executor/slow_query.go } } if !inTimeRanges { @@ -1027,7 +1040,32 @@ func (e *slowQueryRetriever) getAllFiles(ctx context.Context, sctx sessionctx.Co slices.SortFunc(logFiles, func(i, j logFile) int { return cmp.Compare(i.start.UnixNano(), j.start.UnixNano()) }) +<<<<<<< HEAD:executor/slow_query.go return logFiles, err +======= + // Assume no time range overlap in log files and remove unnecessary log files for compressed files. + var ret []logFile + for i, file := range logFiles { + if i == len(logFiles)-1 || !file.compressed || !e.checker.enableTimeCheck { + ret = append(ret, file) + continue + } + start := types.NewTime(types.FromGoTime(logFiles[i].start), mysql.TypeDatetime, types.MaxFsp) + // use next file.start as endTime + end := types.NewTime(types.FromGoTime(logFiles[i+1].start), mysql.TypeDatetime, types.MaxFsp) + inTimeRanges := false + for _, tr := range e.checker.timeRanges { + if !(start.Compare(tr.endTime) > 0 || end.Compare(tr.startTime) < 0) { + inTimeRanges = true + break + } + } + if inTimeRanges { + ret = append(ret, file) + } + } + return ret, err +>>>>>>> 484c1ae88ee (executor: fix issue that query slow_query table return wrong result (#56356)):pkg/executor/slow_query.go } func (e *slowQueryRetriever) getFileStartTime(ctx context.Context, file *os.File) (time.Time, error) { diff --git a/executor/slow_query_test.go b/executor/slow_query_test.go index 389cd06afde3a..8bd95d0e31a77 100644 --- a/executor/slow_query_test.go +++ b/executor/slow_query_test.go @@ -360,9 +360,162 @@ select 7;` config.UpdateGlobal(func(conf *config.Config) { conf.Log.SlowQueryFile = fileName3 }) +<<<<<<< HEAD:executor/slow_query_test.go fileNames := []string{fileName0, fileName1, fileName2, fileName3} prepareLogs(t, logData, fileNames) defer func() { +======= + for k := 0; k < 2; k++ { + // k = 0 for normal files + // k = 1 for compressed files + var fileNames []string + if k == 0 { + fileNames = []string{fileName0, fileName1, fileName2, fileName3} + } else { + fileNames = []string{fileName0 + ".gz", fileName1 + ".gz", fileName2 + ".gz", fileName3} + } + prepareLogs(t, logData, fileNames) + + cases := []struct { + startTime string + endTime string + files []string + querys []string + }{ + { + startTime: "2020-02-15T18:00:00.000000+08:00", + endTime: "2020-02-17T20:00:00.000000+08:00", + files: []string{fileName1, fileName2, fileName3}, + querys: []string{ + "select 1;", + "select 2;", + "select 3;", + "select 4;", + "select 5;", + "select 6;", + }, + }, + { + startTime: "2020-02-15T18:00:02.000000+08:00", + endTime: "2020-02-16T20:00:00.000000+08:00", + files: []string{fileName1, fileName2, fileName3}, + querys: []string{ + "select 2;", + "select 3;", + "select 4;", + "select 5;", + }, + }, + { + startTime: "2020-02-16T18:00:03.000000+08:00", + endTime: "2020-02-16T18:59:00.000000+08:00", + files: []string{fileName2}, + querys: []string{ + "select 4;", + }, + }, + { + startTime: "2020-02-16T18:00:03.000000+08:00", + endTime: "2020-02-16T20:00:00.000000+08:00", + files: []string{fileName2, fileName3}, + querys: []string{ + "select 4;", + "select 5;", + }, + }, + { + startTime: "2020-02-16T19:00:00.000000+08:00", + endTime: "2020-02-17T17:00:00.000000+08:00", + files: []string{fileName3}, + querys: []string{ + "select 5;", + }, + }, + { + startTime: "2010-01-01T00:00:00.000000+08:00", + endTime: "2010-01-01T01:00:00.000000+08:00", + files: []string{}, + }, + { + startTime: "2020-03-01T00:00:00.000000+08:00", + endTime: "2010-03-01T01:00:00.000000+08:00", + files: []string{}, + }, + { + startTime: "", + endTime: "", + files: []string{fileName1, fileName2, fileName3}, + querys: []string{ + "select 1;", + "select 2;", + "select 3;", + "select 4;", + "select 5;", + "select 6;", + "select 7;", + }, + }, + { + startTime: "2020-04-15T18:00:05.299063744+08:00", + endTime: "2020-04-15T18:00:05.299063744+08:00", + files: []string{fileName3}, + querys: []string{ + "select 7;", + }, + }, + } + + loc, err := time.LoadLocation("Asia/Shanghai") + require.NoError(t, err) + sctx := mock.NewContext() + sctx.ResetSessionAndStmtTimeZone(loc) + sctx.GetSessionVars().SlowQueryFile = fileName3 + for i, cas := range cases { + extractor := &plannercore.SlowQueryExtractor{Enable: len(cas.startTime) > 0 && len(cas.endTime) > 0} + if extractor.Enable { + startTime, err := ParseTime(cas.startTime) + require.NoError(t, err) + endTime, err := ParseTime(cas.endTime) + require.NoError(t, err) + extractor.TimeRanges = []*plannercore.TimeRange{{StartTime: startTime, EndTime: endTime}} + } + retriever, err := newSlowQueryRetriever() + require.NoError(t, err) + retriever.extractor = extractor + err = retriever.initialize(context.Background(), sctx) + require.NoError(t, err) + comment := fmt.Sprintf("compressed: %v, case id: %v", k, i) + if len(retriever.files) > 0 { + var reader *bufio.Reader + reader, err := retriever.getNextReader() + require.NoError(t, err, comment) + rows, err := parseLog(retriever, sctx, reader) + require.NoError(t, err, comment) + require.Equal(t, len(rows), len(cas.querys), comment) + for i, row := range rows { + require.Equal(t, row[len(row)-1].GetString(), cas.querys[i], comment) + } + } + + if k == 0 { + require.Equal(t, len(retriever.files), len(cas.files), comment) + for i, file := range retriever.files { + require.Equal(t, file.file.Name(), cas.files[i], comment) + } + } else { + // for compressed file, sometimes it will contains one more file. + require.True(t, (len(retriever.files) == len(cas.files)) || (len(retriever.files) == len(cas.files)+1), comment) + var fileNames []string + for _, file := range retriever.files { + fileNames = append(fileNames, strings.TrimSuffix(file.file.Name(), ".gz")) + } + for _, file := range cas.files { + require.Contains(t, fileNames, file, comment) + } + } + require.NoError(t, retriever.close()) + } +>>>>>>> 484c1ae88ee (executor: fix issue that query slow_query table return wrong result (#56356)):pkg/executor/slow_query_test.go removeFiles(fileNames) }() diff --git a/infoschema/cluster_tables_test.go b/infoschema/cluster_tables_test.go index f9f1f0c6c1f75..38681d7da7d77 100644 --- a/infoschema/cluster_tables_test.go +++ b/infoschema/cluster_tables_test.go @@ -245,7 +245,7 @@ func TestSelectClusterTable(t *testing.T) { tk.MustQuery("select query_time, conn_id from `CLUSTER_SLOW_QUERY` order by time limit 1").Check(testkit.Rows("4.895492 6")) tk.MustQuery("select count(*) from `CLUSTER_SLOW_QUERY` group by digest").Check(testkit.Rows("1", "1")) tk.MustQuery("select digest, count(*) from `CLUSTER_SLOW_QUERY` group by digest order by digest").Check(testkit.Rows("124acb3a0bec903176baca5f9da00b4e7512a41c93b417923f26502edeb324cc 1", "42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772 1")) - tk.MustQuery(`select length(query) as l,time from information_schema.cluster_slow_query where time > "2019-02-12 19:33:56" order by abs(l) desc limit 10;`).Check(testkit.Rows("21 2019-02-12 19:33:56.571953")) + tk.MustQuery(`select length(query) as l,time from information_schema.cluster_slow_query where time > "2019-02-12 19:33:56" order by abs(l) desc limit 10;`).Check(testkit.Rows("21 2019-02-12 19:33:56.571953", "16 2021-09-08 14:39:54.506967")) tk.MustQuery("select count(*) from `CLUSTER_SLOW_QUERY` where time > now() group by digest").Check(testkit.Rows()) re := tk.MustQuery("select * from `CLUSTER_statements_summary`") require.NotNil(t, re) diff --git a/pkg/executor/cluster_table_test.go b/pkg/executor/cluster_table_test.go new file mode 100644 index 0000000000000..62acd59b4bac5 --- /dev/null +++ b/pkg/executor/cluster_table_test.go @@ -0,0 +1,356 @@ +// Copyright 2022 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package executor_test + +import ( + "compress/gzip" + "context" + "fmt" + "net" + "os" + "strings" + "testing" + "time" + + "github.com/pingcap/tidb/pkg/config" + "github.com/pingcap/tidb/pkg/domain" + "github.com/pingcap/tidb/pkg/expression" + "github.com/pingcap/tidb/pkg/parser" + "github.com/pingcap/tidb/pkg/parser/auth" + "github.com/pingcap/tidb/pkg/parser/mysql" + "github.com/pingcap/tidb/pkg/server" + "github.com/pingcap/tidb/pkg/testkit" + "github.com/pingcap/tidb/pkg/util" + "github.com/stretchr/testify/require" + "google.golang.org/grpc" +) + +func createRPCServer(t *testing.T, dom *domain.Domain) *grpc.Server { + sm := &testkit.MockSessionManager{} + sm.PS = append(sm.PS, &util.ProcessInfo{ + ID: 1, + User: "root", + Host: "127.0.0.1", + Command: mysql.ComQuery, + }) + + lis, err := net.Listen("tcp", "127.0.0.1:0") + require.NoError(t, err) + + srv := server.NewRPCServer(config.GetGlobalConfig(), dom, sm) + port := lis.Addr().(*net.TCPAddr).Port + go func() { + err = srv.Serve(lis) + require.NoError(t, err) + }() + + config.UpdateGlobal(func(conf *config.Config) { + conf.Status.StatusPort = uint(port) + }) + + return srv +} + +func TestClusterTableSlowQuery(t *testing.T) { + store, dom := testkit.CreateMockStoreAndDomain(t) + srv := createRPCServer(t, dom) + defer srv.Stop() + + logData0 := "" + logData1 := ` +# Time: 2020-02-15T18:00:01.000000+08:00 +select 1; +# Time: 2020-02-15T19:00:05.000000+08:00 +select 2;` + logData2 := ` +# Time: 2020-02-16T18:00:01.000000+08:00 +select 3; +# Time: 2020-02-16T18:00:05.000000+08:00 +select 4;` + logData3 := ` +# Time: 2020-02-16T19:00:00.000000+08:00 +select 5; +# Time: 2020-02-17T18:00:05.000000+08:00 +select 6;` + logData4 := ` +# Time: 2020-05-14T19:03:54.314615176+08:00 +select 7;` + logData := []string{logData0, logData1, logData2, logData3, logData4} + + fileName0 := "tidb-slow-query-2020-02-14T19-04-05.01.log" + fileName1 := "tidb-slow-query-2020-02-15T19-04-05.01.log" + fileName2 := "tidb-slow-query-2020-02-16T19-04-05.01.log" + fileName3 := "tidb-slow-query-2020-02-17T18-00-05.01.log" + fileName4 := "tidb-slow-query.log" + fileNames := []string{fileName0, fileName1, fileName2, fileName3, fileName4} + defer config.RestoreFunc()() + config.UpdateGlobal(func(conf *config.Config) { + conf.Log.SlowQueryFile = fileName4 + }) + + prepareLogs(t, logData, fileNames) + defer func() { + removeFiles(t, fileNames) + }() + tk := testkit.NewTestKit(t, store) + loc, err := time.LoadLocation("Asia/Shanghai") + require.NoError(t, err) + tk.Session().GetSessionVars().TimeZone = loc + tk.MustExec("use information_schema") + cases := []struct { + prepareSQL string + sql string + result []string + }{ + { + sql: "select count(*),min(time),max(time) from %s where time > '2019-01-26 21:51:00' and time < now()", + result: []string{"7|2020-02-15 18:00:01.000000|2020-05-14 19:03:54.314615"}, + }, + { + sql: "select count(*),min(time),max(time) from %s where time > '2020-02-15 19:00:00' and time < '2020-02-16 18:00:02'", + result: []string{"2|2020-02-15 19:00:05.000000|2020-02-16 18:00:01.000000"}, + }, + { + sql: "select count(*),min(time),max(time) from %s where time > '2020-02-16 18:00:02' and time < '2020-02-17 17:00:00'", + result: []string{"2|2020-02-16 18:00:05.000000|2020-02-16 19:00:00.000000"}, + }, + { + sql: "select count(*),min(time),max(time) from %s where time > '2020-02-16 18:00:02' and time < '2020-02-17 20:00:00'", + result: []string{"3|2020-02-16 18:00:05.000000|2020-02-17 18:00:05.000000"}, + }, + { + sql: "select count(*),min(time),max(time) from %s", + result: []string{"7|2020-02-15 18:00:01.000000|2020-05-14 19:03:54.314615"}, + }, + { + sql: "select count(*),min(time),max(time) from %s where time > '2020-02-16 20:00:00'", + result: []string{"2|2020-02-17 18:00:05.000000|2020-05-14 19:03:54.314615"}, + }, + { + sql: "select count(*) from %s where time > '2020-02-17 20:00:00'", + result: []string{"1"}, + }, + { + sql: "select count(*) from %s where time > '1980-01-11 00:00:00'", + result: []string{"7"}, + }, + { + sql: "select count(*) from %s where time < '2024-01-01 00:00:00'", + result: []string{"7"}, + }, + { + sql: "select query from %s where time > '2019-01-26 21:51:00' and time < now()", + result: []string{"select 1;", "select 2;", "select 3;", "select 4;", "select 5;", "select 6;", "select 7;"}, + }, + // Test for different timezone. + { + prepareSQL: "set @@time_zone = '+00:00'", + sql: "select time from %s where time = '2020-02-17 10:00:05.000000'", + result: []string{"2020-02-17 10:00:05.000000"}, + }, + { + prepareSQL: "set @@time_zone = '+02:00'", + sql: "select time from %s where time = '2020-02-17 12:00:05.000000'", + result: []string{"2020-02-17 12:00:05.000000"}, + }, + // Test for issue 17224 + { + prepareSQL: "set @@time_zone = '+08:00'", + sql: "select time from %s where time = '2020-05-14 19:03:54.314615'", + result: []string{"2020-05-14 19:03:54.314615"}, + }, + } + for _, cas := range cases { + if len(cas.prepareSQL) > 0 { + tk.MustExec(cas.prepareSQL) + } + sql := fmt.Sprintf(cas.sql, "slow_query") + tk.MustQuery(sql).Check(testkit.RowsWithSep("|", cas.result...)) + sql = fmt.Sprintf(cas.sql, "cluster_slow_query") + tk.MustQuery(sql).Check(testkit.RowsWithSep("|", cas.result...)) + } +} + +func TestIssue20236(t *testing.T) { + store, dom := testkit.CreateMockStoreAndDomain(t) + srv := createRPCServer(t, dom) + defer srv.Stop() + + logData0 := "" + logData1 := ` +# Time: 2020-02-15T18:00:01.000000+08:00 +select 1; +# Time: 2020-02-15T19:00:05.000000+08:00 +select 2; +# Time: 2020-02-15T20:00:05.000000+08:00` + logData2 := `select 3; +# Time: 2020-02-16T18:00:01.000000+08:00 +select 4; +# Time: 2020-02-16T18:00:05.000000+08:00 +select 5;` + logData3 := ` +# Time: 2020-02-16T19:00:00.000000+08:00 +select 6; +# Time: 2020-02-17T18:00:05.000000+08:00 +select 7; +# Time: 2020-02-17T19:00:00.000000+08:00` + logData4 := `select 8; +# Time: 2020-02-17T20:00:00.000000+08:00 +select 9 +# Time: 2020-05-14T19:03:54.314615176+08:00 +select 10;` + logData := []string{logData0, logData1, logData2, logData3, logData4} + + fileName0 := "tidb-slow-20236-2020-02-14T19-04-05.01.log" + fileName1 := "tidb-slow-20236-2020-02-15T19-04-05.01.log" + fileName2 := "tidb-slow-20236-2020-02-16T19-04-05.01.log" + fileName3 := "tidb-slow-20236-2020-02-17T18-00-05.01.log" + fileName4 := "tidb-slow-20236.log" + defer config.RestoreFunc()() + config.UpdateGlobal(func(conf *config.Config) { + conf.Log.SlowQueryFile = fileName4 + }) + for k := 0; k < 2; k++ { + // k = 0 for normal files + // k = 1 for compressed files + var fileNames []string + if k == 0 { + fileNames = []string{fileName0, fileName1, fileName2, fileName3, fileName4} + } else { + fileNames = []string{fileName0 + ".gz", fileName1 + ".gz", fileName2 + ".gz", fileName3 + ".gz", fileName4} + } + prepareLogs(t, logData, fileNames) + tk := testkit.NewTestKit(t, store) + loc, err := time.LoadLocation("Asia/Shanghai") + require.NoError(t, err) + tk.Session().GetSessionVars().TimeZone = loc + tk.MustExec("use information_schema") + cases := []struct { + prepareSQL string + sql string + result []string + }{ + { + prepareSQL: "set @@time_zone = '+08:00'", + sql: "select time from cluster_slow_query where time > '2020-02-17 12:00:05.000000' and time < '2020-05-14 20:00:00.000000'", + result: []string{"2020-02-17 18:00:05.000000", "2020-02-17 19:00:00.000000", "2020-05-14 19:03:54.314615"}, + }, + { + prepareSQL: "set @@time_zone = '+08:00'", + sql: "select time from cluster_slow_query where time > '2020-02-17 12:00:05.000000' and time < '2020-05-14 20:00:00.000000' order by time desc", + result: []string{"2020-05-14 19:03:54.314615", "2020-02-17 19:00:00.000000", "2020-02-17 18:00:05.000000"}, + }, + { + prepareSQL: "set @@time_zone = '+08:00'", + sql: "select time from cluster_slow_query where (time > '2020-02-15 18:00:00' and time < '2020-02-15 20:00:00') or (time > '2020-02-17 18:00:00' and time < '2020-05-14 20:00:00') order by time", + result: []string{"2020-02-15 18:00:01.000000", "2020-02-15 19:00:05.000000", "2020-02-17 18:00:05.000000", "2020-02-17 19:00:00.000000", "2020-05-14 19:03:54.314615"}, + }, + { + prepareSQL: "set @@time_zone = '+08:00'", + sql: "select time from cluster_slow_query where (time > '2020-02-15 18:00:00' and time < '2020-02-15 20:00:00') or (time > '2020-02-17 18:00:00' and time < '2020-05-14 20:00:00') order by time desc", + result: []string{"2020-05-14 19:03:54.314615", "2020-02-17 19:00:00.000000", "2020-02-17 18:00:05.000000", "2020-02-15 19:00:05.000000", "2020-02-15 18:00:01.000000"}, + }, + { + prepareSQL: "set @@time_zone = '+08:00'", + sql: "select count(*) from cluster_slow_query where time > '2020-02-15 18:00:00.000000' and time < '2020-05-14 20:00:00.000000' order by time desc", + result: []string{"9"}, + }, + { + prepareSQL: "set @@time_zone = '+08:00'", + sql: "select count(*) from cluster_slow_query where (time > '2020-02-16 18:00:00' and time < '2020-05-14 20:00:00') or (time > '2020-02-17 18:00:00' and time < '2020-05-17 20:00:00')", + result: []string{"6"}, + }, + { + prepareSQL: "set @@time_zone = '+08:00'", + sql: "select count(*) from cluster_slow_query where time > '2020-02-16 18:00:00.000000' and time < '2020-02-17 20:00:00.000000' order by time desc", + result: []string{"5"}, + }, + { + prepareSQL: "set @@time_zone = '+08:00'", + sql: "select time from cluster_slow_query where time > '2020-02-16 18:00:00.000000' and time < '2020-05-14 20:00:00.000000' order by time desc limit 3", + result: []string{"2020-05-14 19:03:54.314615", "2020-02-17 19:00:00.000000", "2020-02-17 18:00:05.000000"}, + }, + } + for _, cas := range cases { + if len(cas.prepareSQL) > 0 { + tk.MustExec(cas.prepareSQL) + } + tk.MustQuery(cas.sql).Check(testkit.RowsWithSep("|", cas.result...)) + } + removeFiles(t, fileNames) + } +} + +func TestSQLDigestTextRetriever(t *testing.T) { + store, dom := testkit.CreateMockStoreAndDomain(t) + srv := createRPCServer(t, dom) + defer srv.Stop() + + tkInit := testkit.NewTestKit(t, store) + tkInit.MustExec("use test") + tkInit.MustExec("set global tidb_enable_stmt_summary = 1") + tkInit.MustQuery("select @@global.tidb_enable_stmt_summary").Check(testkit.Rows("1")) + tkInit.MustExec("drop table if exists test_sql_digest_text_retriever") + tkInit.MustExec("create table test_sql_digest_text_retriever (id int primary key, v int)") + + tk := testkit.NewTestKit(t, store) + tk.MustExec("use test") + require.NoError(t, tk.Session().Auth(&auth.UserIdentity{Username: "root", Hostname: "%"}, nil, nil, nil)) + tk.MustExec("insert into test_sql_digest_text_retriever values (1, 1)") + + insertNormalized, insertDigest := parser.NormalizeDigest("insert into test_sql_digest_text_retriever values (1, 1)") + _, updateDigest := parser.NormalizeDigest("update test_sql_digest_text_retriever set v = v + 1 where id = 1") + r := &expression.SQLDigestTextRetriever{ + SQLDigestsMap: map[string]string{ + insertDigest.String(): "", + updateDigest.String(): "", + }, + } + + err := r.RetrieveLocal(context.Background(), tk.Session().GetRestrictedSQLExecutor()) + require.NoError(t, err) + require.Equal(t, insertNormalized, r.SQLDigestsMap[insertDigest.String()]) + require.Equal(t, "", r.SQLDigestsMap[updateDigest.String()]) +} + +func prepareLogs(t *testing.T, logData []string, fileNames []string) { + writeFile := func(file string, data string) { + if strings.HasSuffix(file, ".gz") { + f, err := os.Create(file) + require.NoError(t, err) + gz := gzip.NewWriter(f) + _, err = gz.Write([]byte(data)) + require.NoError(t, err) + require.NoError(t, gz.Close()) + require.NoError(t, f.Close()) + } else { + f, err := os.OpenFile(file, os.O_CREATE|os.O_WRONLY|os.O_TRUNC, 0644) + require.NoError(t, err) + _, err = f.Write([]byte(data)) + require.NoError(t, err) + require.NoError(t, f.Close()) + } + } + + for i, log := range logData { + writeFile(fileNames[i], log) + } +} + +func removeFiles(t *testing.T, fileNames []string) { + for _, fileName := range fileNames { + require.NoError(t, os.Remove(fileName)) + } +} diff --git a/planner/core/memtable_predicate_extractor.go b/planner/core/memtable_predicate_extractor.go index 22b3216ae03b3..bbb9a9c64f43a 100644 --- a/planner/core/memtable_predicate_extractor.go +++ b/planner/core/memtable_predicate_extractor.go @@ -1192,22 +1192,19 @@ func (e *SlowQueryExtractor) Extract( } func (e *SlowQueryExtractor) setTimeRange(start, end int64) { - const defaultSlowQueryDuration = 24 * time.Hour - var startTime, endTime time.Time if start == 0 && end == 0 { return } + var startTime, endTime time.Time if start != 0 { startTime = e.convertToTime(start) + } else { + startTime, _ = types.MinDatetime.GoTime(time.UTC) } if end != 0 { endTime = e.convertToTime(end) - } - if start == 0 { - startTime = endTime.Add(-defaultSlowQueryDuration) - } - if end == 0 { - endTime = startTime.Add(defaultSlowQueryDuration) + } else { + endTime, _ = types.MaxDatetime.GoTime(time.UTC) } timeRange := &TimeRange{ StartTime: startTime, From 1bcc056d807f88899192d70a79baaccc0e3dfdcf Mon Sep 17 00:00:00 2001 From: crazycs520 Date: Mon, 6 Jan 2025 15:20:27 +0800 Subject: [PATCH 2/3] Revert "This is an automated cherry-pick of #56356" This reverts commit a9eae6e4ba4c0ced9c454ee95f038abee4b1e361. --- executor/slow_query.go | 78 ++-- executor/slow_query_test.go | 153 -------- infoschema/cluster_tables_test.go | 2 +- pkg/executor/cluster_table_test.go | 356 ------------------- planner/core/memtable_predicate_extractor.go | 13 +- 5 files changed, 29 insertions(+), 573 deletions(-) delete mode 100644 pkg/executor/cluster_table_test.go diff --git a/executor/slow_query.go b/executor/slow_query.go index a93dfb73b673d..9900ed61a41ee 100644 --- a/executor/slow_query.go +++ b/executor/slow_query.go @@ -923,6 +923,18 @@ func (e *slowQueryRetriever) getAllFiles(ctx context.Context, sctx sessionctx.Co e.stats.totalFileNum = totalFileNum }() } + if e.extractor == nil || !e.extractor.Enable { + totalFileNum = 1 + //nolint: gosec + file, err := os.Open(logFilePath) + if err != nil { + if os.IsNotExist(err) { + return nil, nil + } + return nil, err + } + return []logFile{{file: file}}, nil + } var logFiles []logFile logDir := filepath.Dir(logFilePath) ext := filepath.Ext(logFilePath) @@ -966,20 +978,17 @@ func (e *slowQueryRetriever) getAllFiles(ctx context.Context, sctx sessionctx.Co return handleErr(err) } start := types.NewTime(types.FromGoTime(fileStartTime), mysql.TypeDatetime, types.MaxFsp) - if e.checker.enableTimeCheck { - notInAllTimeRanges := true - for _, tr := range e.checker.timeRanges { - if start.Compare(tr.endTime) <= 0 { - notInAllTimeRanges = false - break - } - } - if notInAllTimeRanges { - return nil + notInAllTimeRanges := true + for _, tr := range e.checker.timeRanges { + if start.Compare(tr.endTime) <= 0 { + notInAllTimeRanges = false + break } } + if notInAllTimeRanges { + return nil + } -<<<<<<< HEAD:executor/slow_query.go // Get the file end time. fileEndTime, err := e.getFileEndTime(ctx, file) if err != nil { @@ -991,28 +1000,6 @@ func (e *slowQueryRetriever) getAllFiles(ctx context.Context, sctx sessionctx.Co if !(start.Compare(tr.endTime) > 0 || end.Compare(tr.startTime) < 0) { inTimeRanges = true break -======= - // If we want to get the end time from a compressed file, - // we need uncompress the whole file which is very slow and consume a lot of memory. - if !compressed { - // Get the file end time. - fileEndTime, err := e.getFileEndTime(ctx, file) - if err != nil { - return handleErr(err) - } - if e.checker.enableTimeCheck { - end := types.NewTime(types.FromGoTime(fileEndTime), mysql.TypeDatetime, types.MaxFsp) - inTimeRanges := false - for _, tr := range e.checker.timeRanges { - if !(start.Compare(tr.endTime) > 0 || end.Compare(tr.startTime) < 0) { - inTimeRanges = true - break - } - } - if !inTimeRanges { - return nil - } ->>>>>>> 484c1ae88ee (executor: fix issue that query slow_query table return wrong result (#56356)):pkg/executor/slow_query.go } } if !inTimeRanges { @@ -1040,32 +1027,7 @@ func (e *slowQueryRetriever) getAllFiles(ctx context.Context, sctx sessionctx.Co slices.SortFunc(logFiles, func(i, j logFile) int { return cmp.Compare(i.start.UnixNano(), j.start.UnixNano()) }) -<<<<<<< HEAD:executor/slow_query.go return logFiles, err -======= - // Assume no time range overlap in log files and remove unnecessary log files for compressed files. - var ret []logFile - for i, file := range logFiles { - if i == len(logFiles)-1 || !file.compressed || !e.checker.enableTimeCheck { - ret = append(ret, file) - continue - } - start := types.NewTime(types.FromGoTime(logFiles[i].start), mysql.TypeDatetime, types.MaxFsp) - // use next file.start as endTime - end := types.NewTime(types.FromGoTime(logFiles[i+1].start), mysql.TypeDatetime, types.MaxFsp) - inTimeRanges := false - for _, tr := range e.checker.timeRanges { - if !(start.Compare(tr.endTime) > 0 || end.Compare(tr.startTime) < 0) { - inTimeRanges = true - break - } - } - if inTimeRanges { - ret = append(ret, file) - } - } - return ret, err ->>>>>>> 484c1ae88ee (executor: fix issue that query slow_query table return wrong result (#56356)):pkg/executor/slow_query.go } func (e *slowQueryRetriever) getFileStartTime(ctx context.Context, file *os.File) (time.Time, error) { diff --git a/executor/slow_query_test.go b/executor/slow_query_test.go index 8bd95d0e31a77..389cd06afde3a 100644 --- a/executor/slow_query_test.go +++ b/executor/slow_query_test.go @@ -360,162 +360,9 @@ select 7;` config.UpdateGlobal(func(conf *config.Config) { conf.Log.SlowQueryFile = fileName3 }) -<<<<<<< HEAD:executor/slow_query_test.go fileNames := []string{fileName0, fileName1, fileName2, fileName3} prepareLogs(t, logData, fileNames) defer func() { -======= - for k := 0; k < 2; k++ { - // k = 0 for normal files - // k = 1 for compressed files - var fileNames []string - if k == 0 { - fileNames = []string{fileName0, fileName1, fileName2, fileName3} - } else { - fileNames = []string{fileName0 + ".gz", fileName1 + ".gz", fileName2 + ".gz", fileName3} - } - prepareLogs(t, logData, fileNames) - - cases := []struct { - startTime string - endTime string - files []string - querys []string - }{ - { - startTime: "2020-02-15T18:00:00.000000+08:00", - endTime: "2020-02-17T20:00:00.000000+08:00", - files: []string{fileName1, fileName2, fileName3}, - querys: []string{ - "select 1;", - "select 2;", - "select 3;", - "select 4;", - "select 5;", - "select 6;", - }, - }, - { - startTime: "2020-02-15T18:00:02.000000+08:00", - endTime: "2020-02-16T20:00:00.000000+08:00", - files: []string{fileName1, fileName2, fileName3}, - querys: []string{ - "select 2;", - "select 3;", - "select 4;", - "select 5;", - }, - }, - { - startTime: "2020-02-16T18:00:03.000000+08:00", - endTime: "2020-02-16T18:59:00.000000+08:00", - files: []string{fileName2}, - querys: []string{ - "select 4;", - }, - }, - { - startTime: "2020-02-16T18:00:03.000000+08:00", - endTime: "2020-02-16T20:00:00.000000+08:00", - files: []string{fileName2, fileName3}, - querys: []string{ - "select 4;", - "select 5;", - }, - }, - { - startTime: "2020-02-16T19:00:00.000000+08:00", - endTime: "2020-02-17T17:00:00.000000+08:00", - files: []string{fileName3}, - querys: []string{ - "select 5;", - }, - }, - { - startTime: "2010-01-01T00:00:00.000000+08:00", - endTime: "2010-01-01T01:00:00.000000+08:00", - files: []string{}, - }, - { - startTime: "2020-03-01T00:00:00.000000+08:00", - endTime: "2010-03-01T01:00:00.000000+08:00", - files: []string{}, - }, - { - startTime: "", - endTime: "", - files: []string{fileName1, fileName2, fileName3}, - querys: []string{ - "select 1;", - "select 2;", - "select 3;", - "select 4;", - "select 5;", - "select 6;", - "select 7;", - }, - }, - { - startTime: "2020-04-15T18:00:05.299063744+08:00", - endTime: "2020-04-15T18:00:05.299063744+08:00", - files: []string{fileName3}, - querys: []string{ - "select 7;", - }, - }, - } - - loc, err := time.LoadLocation("Asia/Shanghai") - require.NoError(t, err) - sctx := mock.NewContext() - sctx.ResetSessionAndStmtTimeZone(loc) - sctx.GetSessionVars().SlowQueryFile = fileName3 - for i, cas := range cases { - extractor := &plannercore.SlowQueryExtractor{Enable: len(cas.startTime) > 0 && len(cas.endTime) > 0} - if extractor.Enable { - startTime, err := ParseTime(cas.startTime) - require.NoError(t, err) - endTime, err := ParseTime(cas.endTime) - require.NoError(t, err) - extractor.TimeRanges = []*plannercore.TimeRange{{StartTime: startTime, EndTime: endTime}} - } - retriever, err := newSlowQueryRetriever() - require.NoError(t, err) - retriever.extractor = extractor - err = retriever.initialize(context.Background(), sctx) - require.NoError(t, err) - comment := fmt.Sprintf("compressed: %v, case id: %v", k, i) - if len(retriever.files) > 0 { - var reader *bufio.Reader - reader, err := retriever.getNextReader() - require.NoError(t, err, comment) - rows, err := parseLog(retriever, sctx, reader) - require.NoError(t, err, comment) - require.Equal(t, len(rows), len(cas.querys), comment) - for i, row := range rows { - require.Equal(t, row[len(row)-1].GetString(), cas.querys[i], comment) - } - } - - if k == 0 { - require.Equal(t, len(retriever.files), len(cas.files), comment) - for i, file := range retriever.files { - require.Equal(t, file.file.Name(), cas.files[i], comment) - } - } else { - // for compressed file, sometimes it will contains one more file. - require.True(t, (len(retriever.files) == len(cas.files)) || (len(retriever.files) == len(cas.files)+1), comment) - var fileNames []string - for _, file := range retriever.files { - fileNames = append(fileNames, strings.TrimSuffix(file.file.Name(), ".gz")) - } - for _, file := range cas.files { - require.Contains(t, fileNames, file, comment) - } - } - require.NoError(t, retriever.close()) - } ->>>>>>> 484c1ae88ee (executor: fix issue that query slow_query table return wrong result (#56356)):pkg/executor/slow_query_test.go removeFiles(fileNames) }() diff --git a/infoschema/cluster_tables_test.go b/infoschema/cluster_tables_test.go index 38681d7da7d77..f9f1f0c6c1f75 100644 --- a/infoschema/cluster_tables_test.go +++ b/infoschema/cluster_tables_test.go @@ -245,7 +245,7 @@ func TestSelectClusterTable(t *testing.T) { tk.MustQuery("select query_time, conn_id from `CLUSTER_SLOW_QUERY` order by time limit 1").Check(testkit.Rows("4.895492 6")) tk.MustQuery("select count(*) from `CLUSTER_SLOW_QUERY` group by digest").Check(testkit.Rows("1", "1")) tk.MustQuery("select digest, count(*) from `CLUSTER_SLOW_QUERY` group by digest order by digest").Check(testkit.Rows("124acb3a0bec903176baca5f9da00b4e7512a41c93b417923f26502edeb324cc 1", "42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772 1")) - tk.MustQuery(`select length(query) as l,time from information_schema.cluster_slow_query where time > "2019-02-12 19:33:56" order by abs(l) desc limit 10;`).Check(testkit.Rows("21 2019-02-12 19:33:56.571953", "16 2021-09-08 14:39:54.506967")) + tk.MustQuery(`select length(query) as l,time from information_schema.cluster_slow_query where time > "2019-02-12 19:33:56" order by abs(l) desc limit 10;`).Check(testkit.Rows("21 2019-02-12 19:33:56.571953")) tk.MustQuery("select count(*) from `CLUSTER_SLOW_QUERY` where time > now() group by digest").Check(testkit.Rows()) re := tk.MustQuery("select * from `CLUSTER_statements_summary`") require.NotNil(t, re) diff --git a/pkg/executor/cluster_table_test.go b/pkg/executor/cluster_table_test.go deleted file mode 100644 index 62acd59b4bac5..0000000000000 --- a/pkg/executor/cluster_table_test.go +++ /dev/null @@ -1,356 +0,0 @@ -// Copyright 2022 PingCAP, Inc. -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. - -package executor_test - -import ( - "compress/gzip" - "context" - "fmt" - "net" - "os" - "strings" - "testing" - "time" - - "github.com/pingcap/tidb/pkg/config" - "github.com/pingcap/tidb/pkg/domain" - "github.com/pingcap/tidb/pkg/expression" - "github.com/pingcap/tidb/pkg/parser" - "github.com/pingcap/tidb/pkg/parser/auth" - "github.com/pingcap/tidb/pkg/parser/mysql" - "github.com/pingcap/tidb/pkg/server" - "github.com/pingcap/tidb/pkg/testkit" - "github.com/pingcap/tidb/pkg/util" - "github.com/stretchr/testify/require" - "google.golang.org/grpc" -) - -func createRPCServer(t *testing.T, dom *domain.Domain) *grpc.Server { - sm := &testkit.MockSessionManager{} - sm.PS = append(sm.PS, &util.ProcessInfo{ - ID: 1, - User: "root", - Host: "127.0.0.1", - Command: mysql.ComQuery, - }) - - lis, err := net.Listen("tcp", "127.0.0.1:0") - require.NoError(t, err) - - srv := server.NewRPCServer(config.GetGlobalConfig(), dom, sm) - port := lis.Addr().(*net.TCPAddr).Port - go func() { - err = srv.Serve(lis) - require.NoError(t, err) - }() - - config.UpdateGlobal(func(conf *config.Config) { - conf.Status.StatusPort = uint(port) - }) - - return srv -} - -func TestClusterTableSlowQuery(t *testing.T) { - store, dom := testkit.CreateMockStoreAndDomain(t) - srv := createRPCServer(t, dom) - defer srv.Stop() - - logData0 := "" - logData1 := ` -# Time: 2020-02-15T18:00:01.000000+08:00 -select 1; -# Time: 2020-02-15T19:00:05.000000+08:00 -select 2;` - logData2 := ` -# Time: 2020-02-16T18:00:01.000000+08:00 -select 3; -# Time: 2020-02-16T18:00:05.000000+08:00 -select 4;` - logData3 := ` -# Time: 2020-02-16T19:00:00.000000+08:00 -select 5; -# Time: 2020-02-17T18:00:05.000000+08:00 -select 6;` - logData4 := ` -# Time: 2020-05-14T19:03:54.314615176+08:00 -select 7;` - logData := []string{logData0, logData1, logData2, logData3, logData4} - - fileName0 := "tidb-slow-query-2020-02-14T19-04-05.01.log" - fileName1 := "tidb-slow-query-2020-02-15T19-04-05.01.log" - fileName2 := "tidb-slow-query-2020-02-16T19-04-05.01.log" - fileName3 := "tidb-slow-query-2020-02-17T18-00-05.01.log" - fileName4 := "tidb-slow-query.log" - fileNames := []string{fileName0, fileName1, fileName2, fileName3, fileName4} - defer config.RestoreFunc()() - config.UpdateGlobal(func(conf *config.Config) { - conf.Log.SlowQueryFile = fileName4 - }) - - prepareLogs(t, logData, fileNames) - defer func() { - removeFiles(t, fileNames) - }() - tk := testkit.NewTestKit(t, store) - loc, err := time.LoadLocation("Asia/Shanghai") - require.NoError(t, err) - tk.Session().GetSessionVars().TimeZone = loc - tk.MustExec("use information_schema") - cases := []struct { - prepareSQL string - sql string - result []string - }{ - { - sql: "select count(*),min(time),max(time) from %s where time > '2019-01-26 21:51:00' and time < now()", - result: []string{"7|2020-02-15 18:00:01.000000|2020-05-14 19:03:54.314615"}, - }, - { - sql: "select count(*),min(time),max(time) from %s where time > '2020-02-15 19:00:00' and time < '2020-02-16 18:00:02'", - result: []string{"2|2020-02-15 19:00:05.000000|2020-02-16 18:00:01.000000"}, - }, - { - sql: "select count(*),min(time),max(time) from %s where time > '2020-02-16 18:00:02' and time < '2020-02-17 17:00:00'", - result: []string{"2|2020-02-16 18:00:05.000000|2020-02-16 19:00:00.000000"}, - }, - { - sql: "select count(*),min(time),max(time) from %s where time > '2020-02-16 18:00:02' and time < '2020-02-17 20:00:00'", - result: []string{"3|2020-02-16 18:00:05.000000|2020-02-17 18:00:05.000000"}, - }, - { - sql: "select count(*),min(time),max(time) from %s", - result: []string{"7|2020-02-15 18:00:01.000000|2020-05-14 19:03:54.314615"}, - }, - { - sql: "select count(*),min(time),max(time) from %s where time > '2020-02-16 20:00:00'", - result: []string{"2|2020-02-17 18:00:05.000000|2020-05-14 19:03:54.314615"}, - }, - { - sql: "select count(*) from %s where time > '2020-02-17 20:00:00'", - result: []string{"1"}, - }, - { - sql: "select count(*) from %s where time > '1980-01-11 00:00:00'", - result: []string{"7"}, - }, - { - sql: "select count(*) from %s where time < '2024-01-01 00:00:00'", - result: []string{"7"}, - }, - { - sql: "select query from %s where time > '2019-01-26 21:51:00' and time < now()", - result: []string{"select 1;", "select 2;", "select 3;", "select 4;", "select 5;", "select 6;", "select 7;"}, - }, - // Test for different timezone. - { - prepareSQL: "set @@time_zone = '+00:00'", - sql: "select time from %s where time = '2020-02-17 10:00:05.000000'", - result: []string{"2020-02-17 10:00:05.000000"}, - }, - { - prepareSQL: "set @@time_zone = '+02:00'", - sql: "select time from %s where time = '2020-02-17 12:00:05.000000'", - result: []string{"2020-02-17 12:00:05.000000"}, - }, - // Test for issue 17224 - { - prepareSQL: "set @@time_zone = '+08:00'", - sql: "select time from %s where time = '2020-05-14 19:03:54.314615'", - result: []string{"2020-05-14 19:03:54.314615"}, - }, - } - for _, cas := range cases { - if len(cas.prepareSQL) > 0 { - tk.MustExec(cas.prepareSQL) - } - sql := fmt.Sprintf(cas.sql, "slow_query") - tk.MustQuery(sql).Check(testkit.RowsWithSep("|", cas.result...)) - sql = fmt.Sprintf(cas.sql, "cluster_slow_query") - tk.MustQuery(sql).Check(testkit.RowsWithSep("|", cas.result...)) - } -} - -func TestIssue20236(t *testing.T) { - store, dom := testkit.CreateMockStoreAndDomain(t) - srv := createRPCServer(t, dom) - defer srv.Stop() - - logData0 := "" - logData1 := ` -# Time: 2020-02-15T18:00:01.000000+08:00 -select 1; -# Time: 2020-02-15T19:00:05.000000+08:00 -select 2; -# Time: 2020-02-15T20:00:05.000000+08:00` - logData2 := `select 3; -# Time: 2020-02-16T18:00:01.000000+08:00 -select 4; -# Time: 2020-02-16T18:00:05.000000+08:00 -select 5;` - logData3 := ` -# Time: 2020-02-16T19:00:00.000000+08:00 -select 6; -# Time: 2020-02-17T18:00:05.000000+08:00 -select 7; -# Time: 2020-02-17T19:00:00.000000+08:00` - logData4 := `select 8; -# Time: 2020-02-17T20:00:00.000000+08:00 -select 9 -# Time: 2020-05-14T19:03:54.314615176+08:00 -select 10;` - logData := []string{logData0, logData1, logData2, logData3, logData4} - - fileName0 := "tidb-slow-20236-2020-02-14T19-04-05.01.log" - fileName1 := "tidb-slow-20236-2020-02-15T19-04-05.01.log" - fileName2 := "tidb-slow-20236-2020-02-16T19-04-05.01.log" - fileName3 := "tidb-slow-20236-2020-02-17T18-00-05.01.log" - fileName4 := "tidb-slow-20236.log" - defer config.RestoreFunc()() - config.UpdateGlobal(func(conf *config.Config) { - conf.Log.SlowQueryFile = fileName4 - }) - for k := 0; k < 2; k++ { - // k = 0 for normal files - // k = 1 for compressed files - var fileNames []string - if k == 0 { - fileNames = []string{fileName0, fileName1, fileName2, fileName3, fileName4} - } else { - fileNames = []string{fileName0 + ".gz", fileName1 + ".gz", fileName2 + ".gz", fileName3 + ".gz", fileName4} - } - prepareLogs(t, logData, fileNames) - tk := testkit.NewTestKit(t, store) - loc, err := time.LoadLocation("Asia/Shanghai") - require.NoError(t, err) - tk.Session().GetSessionVars().TimeZone = loc - tk.MustExec("use information_schema") - cases := []struct { - prepareSQL string - sql string - result []string - }{ - { - prepareSQL: "set @@time_zone = '+08:00'", - sql: "select time from cluster_slow_query where time > '2020-02-17 12:00:05.000000' and time < '2020-05-14 20:00:00.000000'", - result: []string{"2020-02-17 18:00:05.000000", "2020-02-17 19:00:00.000000", "2020-05-14 19:03:54.314615"}, - }, - { - prepareSQL: "set @@time_zone = '+08:00'", - sql: "select time from cluster_slow_query where time > '2020-02-17 12:00:05.000000' and time < '2020-05-14 20:00:00.000000' order by time desc", - result: []string{"2020-05-14 19:03:54.314615", "2020-02-17 19:00:00.000000", "2020-02-17 18:00:05.000000"}, - }, - { - prepareSQL: "set @@time_zone = '+08:00'", - sql: "select time from cluster_slow_query where (time > '2020-02-15 18:00:00' and time < '2020-02-15 20:00:00') or (time > '2020-02-17 18:00:00' and time < '2020-05-14 20:00:00') order by time", - result: []string{"2020-02-15 18:00:01.000000", "2020-02-15 19:00:05.000000", "2020-02-17 18:00:05.000000", "2020-02-17 19:00:00.000000", "2020-05-14 19:03:54.314615"}, - }, - { - prepareSQL: "set @@time_zone = '+08:00'", - sql: "select time from cluster_slow_query where (time > '2020-02-15 18:00:00' and time < '2020-02-15 20:00:00') or (time > '2020-02-17 18:00:00' and time < '2020-05-14 20:00:00') order by time desc", - result: []string{"2020-05-14 19:03:54.314615", "2020-02-17 19:00:00.000000", "2020-02-17 18:00:05.000000", "2020-02-15 19:00:05.000000", "2020-02-15 18:00:01.000000"}, - }, - { - prepareSQL: "set @@time_zone = '+08:00'", - sql: "select count(*) from cluster_slow_query where time > '2020-02-15 18:00:00.000000' and time < '2020-05-14 20:00:00.000000' order by time desc", - result: []string{"9"}, - }, - { - prepareSQL: "set @@time_zone = '+08:00'", - sql: "select count(*) from cluster_slow_query where (time > '2020-02-16 18:00:00' and time < '2020-05-14 20:00:00') or (time > '2020-02-17 18:00:00' and time < '2020-05-17 20:00:00')", - result: []string{"6"}, - }, - { - prepareSQL: "set @@time_zone = '+08:00'", - sql: "select count(*) from cluster_slow_query where time > '2020-02-16 18:00:00.000000' and time < '2020-02-17 20:00:00.000000' order by time desc", - result: []string{"5"}, - }, - { - prepareSQL: "set @@time_zone = '+08:00'", - sql: "select time from cluster_slow_query where time > '2020-02-16 18:00:00.000000' and time < '2020-05-14 20:00:00.000000' order by time desc limit 3", - result: []string{"2020-05-14 19:03:54.314615", "2020-02-17 19:00:00.000000", "2020-02-17 18:00:05.000000"}, - }, - } - for _, cas := range cases { - if len(cas.prepareSQL) > 0 { - tk.MustExec(cas.prepareSQL) - } - tk.MustQuery(cas.sql).Check(testkit.RowsWithSep("|", cas.result...)) - } - removeFiles(t, fileNames) - } -} - -func TestSQLDigestTextRetriever(t *testing.T) { - store, dom := testkit.CreateMockStoreAndDomain(t) - srv := createRPCServer(t, dom) - defer srv.Stop() - - tkInit := testkit.NewTestKit(t, store) - tkInit.MustExec("use test") - tkInit.MustExec("set global tidb_enable_stmt_summary = 1") - tkInit.MustQuery("select @@global.tidb_enable_stmt_summary").Check(testkit.Rows("1")) - tkInit.MustExec("drop table if exists test_sql_digest_text_retriever") - tkInit.MustExec("create table test_sql_digest_text_retriever (id int primary key, v int)") - - tk := testkit.NewTestKit(t, store) - tk.MustExec("use test") - require.NoError(t, tk.Session().Auth(&auth.UserIdentity{Username: "root", Hostname: "%"}, nil, nil, nil)) - tk.MustExec("insert into test_sql_digest_text_retriever values (1, 1)") - - insertNormalized, insertDigest := parser.NormalizeDigest("insert into test_sql_digest_text_retriever values (1, 1)") - _, updateDigest := parser.NormalizeDigest("update test_sql_digest_text_retriever set v = v + 1 where id = 1") - r := &expression.SQLDigestTextRetriever{ - SQLDigestsMap: map[string]string{ - insertDigest.String(): "", - updateDigest.String(): "", - }, - } - - err := r.RetrieveLocal(context.Background(), tk.Session().GetRestrictedSQLExecutor()) - require.NoError(t, err) - require.Equal(t, insertNormalized, r.SQLDigestsMap[insertDigest.String()]) - require.Equal(t, "", r.SQLDigestsMap[updateDigest.String()]) -} - -func prepareLogs(t *testing.T, logData []string, fileNames []string) { - writeFile := func(file string, data string) { - if strings.HasSuffix(file, ".gz") { - f, err := os.Create(file) - require.NoError(t, err) - gz := gzip.NewWriter(f) - _, err = gz.Write([]byte(data)) - require.NoError(t, err) - require.NoError(t, gz.Close()) - require.NoError(t, f.Close()) - } else { - f, err := os.OpenFile(file, os.O_CREATE|os.O_WRONLY|os.O_TRUNC, 0644) - require.NoError(t, err) - _, err = f.Write([]byte(data)) - require.NoError(t, err) - require.NoError(t, f.Close()) - } - } - - for i, log := range logData { - writeFile(fileNames[i], log) - } -} - -func removeFiles(t *testing.T, fileNames []string) { - for _, fileName := range fileNames { - require.NoError(t, os.Remove(fileName)) - } -} diff --git a/planner/core/memtable_predicate_extractor.go b/planner/core/memtable_predicate_extractor.go index bbb9a9c64f43a..22b3216ae03b3 100644 --- a/planner/core/memtable_predicate_extractor.go +++ b/planner/core/memtable_predicate_extractor.go @@ -1192,19 +1192,22 @@ func (e *SlowQueryExtractor) Extract( } func (e *SlowQueryExtractor) setTimeRange(start, end int64) { + const defaultSlowQueryDuration = 24 * time.Hour + var startTime, endTime time.Time if start == 0 && end == 0 { return } - var startTime, endTime time.Time if start != 0 { startTime = e.convertToTime(start) - } else { - startTime, _ = types.MinDatetime.GoTime(time.UTC) } if end != 0 { endTime = e.convertToTime(end) - } else { - endTime, _ = types.MaxDatetime.GoTime(time.UTC) + } + if start == 0 { + startTime = endTime.Add(-defaultSlowQueryDuration) + } + if end == 0 { + endTime = startTime.Add(defaultSlowQueryDuration) } timeRange := &TimeRange{ StartTime: startTime, From 05ebe72123b9818813bf7755b5f53d3960eecdbf Mon Sep 17 00:00:00 2001 From: crazycs520 Date: Mon, 6 Jan 2025 15:27:13 +0800 Subject: [PATCH 3/3] executor: fix issue that query slow_query table return wrong result (#56356) Signed-off-by: crazycs520 --- executor/cluster_table_test.go | 16 +++++-- executor/slow_query.go | 50 ++++++++------------ executor/slow_query_test.go | 6 ++- infoschema/cluster_tables_test.go | 2 +- planner/core/memtable_predicate_extractor.go | 13 ++--- 5 files changed, 44 insertions(+), 43 deletions(-) diff --git a/executor/cluster_table_test.go b/executor/cluster_table_test.go index 0653a0ad68fc5..24183d695dd85 100644 --- a/executor/cluster_table_test.go +++ b/executor/cluster_table_test.go @@ -131,15 +131,23 @@ select 7;` }, { sql: "select count(*),min(time),max(time) from %s", - result: []string{"1|2020-05-14 19:03:54.314615|2020-05-14 19:03:54.314615"}, + result: []string{"7|2020-02-15 18:00:01.000000|2020-05-14 19:03:54.314615"}, }, { - sql: "select count(*),min(time) from %s where time > '2020-02-16 20:00:00'", - result: []string{"1|2020-02-17 18:00:05.000000"}, + sql: "select count(*),min(time),max(time) from %s where time > '2020-02-16 20:00:00'", + result: []string{"2|2020-02-17 18:00:05.000000|2020-05-14 19:03:54.314615"}, }, { sql: "select count(*) from %s where time > '2020-02-17 20:00:00'", - result: []string{"0"}, + result: []string{"1"}, + }, + { + sql: "select count(*) from %s where time > '1980-01-11 00:00:00'", + result: []string{"7"}, + }, + { + sql: "select count(*) from %s where time < '2024-01-01 00:00:00'", + result: []string{"7"}, }, { sql: "select query from %s where time > '2019-01-26 21:51:00' and time < now()", diff --git a/executor/slow_query.go b/executor/slow_query.go index 9900ed61a41ee..4deb432dec0b2 100644 --- a/executor/slow_query.go +++ b/executor/slow_query.go @@ -923,18 +923,6 @@ func (e *slowQueryRetriever) getAllFiles(ctx context.Context, sctx sessionctx.Co e.stats.totalFileNum = totalFileNum }() } - if e.extractor == nil || !e.extractor.Enable { - totalFileNum = 1 - //nolint: gosec - file, err := os.Open(logFilePath) - if err != nil { - if os.IsNotExist(err) { - return nil, nil - } - return nil, err - } - return []logFile{{file: file}}, nil - } var logFiles []logFile logDir := filepath.Dir(logFilePath) ext := filepath.Ext(logFilePath) @@ -978,15 +966,17 @@ func (e *slowQueryRetriever) getAllFiles(ctx context.Context, sctx sessionctx.Co return handleErr(err) } start := types.NewTime(types.FromGoTime(fileStartTime), mysql.TypeDatetime, types.MaxFsp) - notInAllTimeRanges := true - for _, tr := range e.checker.timeRanges { - if start.Compare(tr.endTime) <= 0 { - notInAllTimeRanges = false - break + if e.checker.enableTimeCheck { + notInAllTimeRanges := true + for _, tr := range e.checker.timeRanges { + if start.Compare(tr.endTime) <= 0 { + notInAllTimeRanges = false + break + } + } + if notInAllTimeRanges { + return nil } - } - if notInAllTimeRanges { - return nil } // Get the file end time. @@ -994,16 +984,18 @@ func (e *slowQueryRetriever) getAllFiles(ctx context.Context, sctx sessionctx.Co if err != nil { return handleErr(err) } - end := types.NewTime(types.FromGoTime(fileEndTime), mysql.TypeDatetime, types.MaxFsp) - inTimeRanges := false - for _, tr := range e.checker.timeRanges { - if !(start.Compare(tr.endTime) > 0 || end.Compare(tr.startTime) < 0) { - inTimeRanges = true - break + if e.checker.enableTimeCheck { + end := types.NewTime(types.FromGoTime(fileEndTime), mysql.TypeDatetime, types.MaxFsp) + inTimeRanges := false + for _, tr := range e.checker.timeRanges { + if !(start.Compare(tr.endTime) > 0 || end.Compare(tr.startTime) < 0) { + inTimeRanges = true + break + } + } + if !inTimeRanges { + return nil } - } - if !inTimeRanges { - return nil } _, err = file.Seek(0, io.SeekStart) if err != nil { diff --git a/executor/slow_query_test.go b/executor/slow_query_test.go index 389cd06afde3a..5baa4f9e6d095 100644 --- a/executor/slow_query_test.go +++ b/executor/slow_query_test.go @@ -434,8 +434,12 @@ select 7;` { startTime: "", endTime: "", - files: []string{fileName3}, + files: []string{fileName1, fileName2, fileName3}, querys: []string{ + "select 1;", + "select 2;", + "select 3;", + "select 4;", "select 5;", "select 6;", "select 7;", diff --git a/infoschema/cluster_tables_test.go b/infoschema/cluster_tables_test.go index f9f1f0c6c1f75..38681d7da7d77 100644 --- a/infoschema/cluster_tables_test.go +++ b/infoschema/cluster_tables_test.go @@ -245,7 +245,7 @@ func TestSelectClusterTable(t *testing.T) { tk.MustQuery("select query_time, conn_id from `CLUSTER_SLOW_QUERY` order by time limit 1").Check(testkit.Rows("4.895492 6")) tk.MustQuery("select count(*) from `CLUSTER_SLOW_QUERY` group by digest").Check(testkit.Rows("1", "1")) tk.MustQuery("select digest, count(*) from `CLUSTER_SLOW_QUERY` group by digest order by digest").Check(testkit.Rows("124acb3a0bec903176baca5f9da00b4e7512a41c93b417923f26502edeb324cc 1", "42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772 1")) - tk.MustQuery(`select length(query) as l,time from information_schema.cluster_slow_query where time > "2019-02-12 19:33:56" order by abs(l) desc limit 10;`).Check(testkit.Rows("21 2019-02-12 19:33:56.571953")) + tk.MustQuery(`select length(query) as l,time from information_schema.cluster_slow_query where time > "2019-02-12 19:33:56" order by abs(l) desc limit 10;`).Check(testkit.Rows("21 2019-02-12 19:33:56.571953", "16 2021-09-08 14:39:54.506967")) tk.MustQuery("select count(*) from `CLUSTER_SLOW_QUERY` where time > now() group by digest").Check(testkit.Rows()) re := tk.MustQuery("select * from `CLUSTER_statements_summary`") require.NotNil(t, re) diff --git a/planner/core/memtable_predicate_extractor.go b/planner/core/memtable_predicate_extractor.go index 22b3216ae03b3..bbb9a9c64f43a 100644 --- a/planner/core/memtable_predicate_extractor.go +++ b/planner/core/memtable_predicate_extractor.go @@ -1192,22 +1192,19 @@ func (e *SlowQueryExtractor) Extract( } func (e *SlowQueryExtractor) setTimeRange(start, end int64) { - const defaultSlowQueryDuration = 24 * time.Hour - var startTime, endTime time.Time if start == 0 && end == 0 { return } + var startTime, endTime time.Time if start != 0 { startTime = e.convertToTime(start) + } else { + startTime, _ = types.MinDatetime.GoTime(time.UTC) } if end != 0 { endTime = e.convertToTime(end) - } - if start == 0 { - startTime = endTime.Add(-defaultSlowQueryDuration) - } - if end == 0 { - endTime = startTime.Add(defaultSlowQueryDuration) + } else { + endTime, _ = types.MaxDatetime.GoTime(time.UTC) } timeRange := &TimeRange{ StartTime: startTime,