// Copyright 2019 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 slow_query import ( "bufio" "bytes" "context" "fmt" "os" "strings" "testing" "time" "github.com/onsi/gomega" "github.com/pingcap/tidb/parser/terror" "github.com/pingcap/tidb/types" "github.com/pingcap/tidb/util/execdetails" "github.com/pingcap/tidb/util/logutil" "github.com/pingcap-inc/clinic/pkg/slow_query/variable" ) var testCols = []string{ variable.SlowLogTimeStr, variable.SlowLogTxnStartTSStr, variable.SlowLogUserStr, variable.SlowLogHostStr, variable.SlowLogConnIDStr, variable.SlowLogExecRetryCount, variable.SlowLogExecRetryTime, variable.SlowLogQueryTimeStr, variable.SlowLogParseTimeStr, variable.SlowLogCompileTimeStr, variable.SlowLogRewriteTimeStr, variable.SlowLogPreprocSubQueriesStr, variable.SlowLogPreProcSubQueryTimeStr, variable.SlowLogOptimizeTimeStr, variable.SlowLogWaitTSTimeStr, execdetails.PreWriteTimeStr, execdetails.WaitPrewriteBinlogTimeStr, execdetails.CommitTimeStr, execdetails.GetCommitTSTimeStr, execdetails.CommitBackoffTimeStr, execdetails.BackoffTypesStr, execdetails.ResolveLockTimeStr, execdetails.LocalLatchWaitTimeStr, execdetails.WriteKeysStr, execdetails.WriteSizeStr, execdetails.PrewriteRegionStr, execdetails.TxnRetryStr, execdetails.CopTimeStr, execdetails.ProcessTimeStr, execdetails.WaitTimeStr, execdetails.BackoffTimeStr, execdetails.LockKeysTimeStr, execdetails.RequestCountStr, execdetails.TotalKeysStr, execdetails.ProcessKeysStr, execdetails.RocksdbDeleteSkippedCountStr, execdetails.RocksdbKeySkippedCountStr, execdetails.RocksdbBlockCacheHitCountStr, execdetails.RocksdbBlockReadCountStr, execdetails.RocksdbBlockReadByteStr, variable.SlowLogDBStr, variable.SlowLogIndexNamesStr, variable.SlowLogIsInternalStr, variable.SlowLogDigestStr, variable.SlowLogStatsInfoStr, variable.SlowLogCopProcAvg, variable.SlowLogCopProcP90, variable.SlowLogCopProcMax, variable.SlowLogCopProcAddr, variable.SlowLogCopWaitAvg, variable.SlowLogCopWaitP90, variable.SlowLogCopWaitMax, variable.SlowLogCopWaitAddr, variable.SlowLogMemMax, variable.SlowLogDiskMax, variable.SlowLogKVTotal, variable.SlowLogPDTotal, variable.SlowLogBackoffTotal, variable.SlowLogWriteSQLRespTotal, variable.SlowLogResultRows, variable.SlowLogBackoffDetail, variable.SlowLogPrepared, variable.SlowLogSucc, variable.SlowLogIsExplicitTxn, variable.SlowLogPlanFromCache, variable.SlowLogPlanFromBinding, variable.SlowLogPlan, variable.SlowLogPlanDigest, variable.SlowLogPrevStmt, variable.SlowLogQuerySQLStr, } func parseLog(retriever *SlowQueryRetriever, reader *bufio.Reader, logNum int) ([][]types.Datum, error) { retriever.taskList = make(chan slowLogTask, 100) ctx := context.Background() retriever.parseSlowLog(ctx, reader, 64) task, ok := <-retriever.taskList if !ok { return nil, nil } var rows [][]types.Datum var err error result := <-task.resultCh rows, err = result.rows, result.err return rows, err } func newSlowQueryRetriever(loc *time.Location) (*SlowQueryRetriever, error) { return &SlowQueryRetriever{concurrency: 1, outputCols: testCols, timeZone: loc}, nil } func parseSlowLog(reader *bufio.Reader, logNum int, loc *time.Location) ([][]types.Datum, error) { retriever, err := newSlowQueryRetriever(loc) if err != nil { return nil, err } // Ignore the error is ok for test. terror.Log(retriever.initialize(context.Background())) rows, err := parseLog(retriever, reader, logNum) return rows, err } func TestParseSlowLogFile(t *testing.T) { g := gomega.NewWithT(t) slowLogStr := `# Time: 2019-04-28T15:24:04.309074+08:00 # Txn_start_ts: 405888132465033227 # User@Host: root[root] @ localhost [127.0.0.1] # Exec_retry_time: 0.12 Exec_retry_count: 57 # Conn_ID: 0 # Query_time: 0.216905 # Cop_time: 0.38 Process_time: 0.021 Request_count: 1 Total_keys: 637 Processed_keys: 436 # Rocksdb_delete_skipped_count: 10 Rocksdb_key_skipped_count: 10 Rocksdb_block_cache_hit_count: 10 Rocksdb_block_read_count: 10 Rocksdb_block_read_byte: 100 # 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_proc_addr: 127.0.0.1:20160 # Cop_wait_avg: 0.05 Cop_wait_p90: 0.6 Cop_wait_max: 0.8 Cop_wait_addr: 0.0.0.0:20160 # Cop_backoff_regionMiss_total_times: 200 Cop_backoff_regionMiss_total_time: 0.2 Cop_backoff_regionMiss_max_time: 0.2 Cop_backoff_regionMiss_max_addr: 127.0.0.1 Cop_backoff_regionMiss_avg_time: 0.2 Cop_backoff_regionMiss_p90_time: 0.2 # Cop_backoff_rpcPD_total_times: 200 Cop_backoff_rpcPD_total_time: 0.2 Cop_backoff_rpcPD_max_time: 0.2 Cop_backoff_rpcPD_max_addr: 127.0.0.1 Cop_backoff_rpcPD_avg_time: 0.2 Cop_backoff_rpcPD_p90_time: 0.2 # Cop_backoff_rpcTiKV_total_times: 200 Cop_backoff_rpcTiKV_total_time: 0.2 Cop_backoff_rpcTiKV_max_time: 0.2 Cop_backoff_rpcTiKV_max_addr: 127.0.0.1 Cop_backoff_rpcTiKV_avg_time: 0.2 Cop_backoff_rpcTiKV_p90_time: 0.2 # Mem_max: 70724 # Disk_max: 65536 # Plan_from_cache: true # Plan_from_binding: true # Succ: false # IsExplicitTxn: true # Plan_digest: 60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4 # Prev_stmt: update t set i = 1; use test; select * from t;` reader := bufio.NewReader(bytes.NewBufferString(slowLogStr)) loc, err := time.LoadLocation("Asia/Shanghai") g.Expect(err).ShouldNot(gomega.HaveOccurred()) rows, err := parseSlowLog(reader, 64, loc) g.Expect(err).ShouldNot(gomega.HaveOccurred()) g.Expect(len(rows)).To(gomega.Equal(1)) recordString := "" for i, value := range rows[0] { str, err := value.ToString() g.Expect(err).ShouldNot(gomega.HaveOccurred()) if i > 0 { recordString += "," } if str == "" { t.Logf("i: %+v, str: %+v\n", i, str) } recordString += str } expectRecordString := `2019-04-28T15:24:04.309074+08:00,` + `405888132465033227,root,localhost,0,57,0.12,0.216905,` + `0,0,0,0,0,0,0,0,0,0,0,0,,0,0,0,0,0,0,0.38,0.021,0,0,0,1,637,0,10,10,10,10,100,,,1,42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772,t1:1,t2:2,` + `0.1,0.2,0.03,127.0.0.1:20160,0.05,0.6,0.8,0.0.0.0:20160,70724,65536,0,0,0,0,0,` + `Cop_backoff_regionMiss_total_times: 200 Cop_backoff_regionMiss_total_time: 0.2 Cop_backoff_regionMiss_max_time: 0.2 Cop_backoff_regionMiss_max_addr: 127.0.0.1 Cop_backoff_regionMiss_avg_time: 0.2 Cop_backoff_regionMiss_p90_time: 0.2 Cop_backoff_rpcPD_total_times: 200 Cop_backoff_rpcPD_total_time: 0.2 Cop_backoff_rpcPD_max_time: 0.2 Cop_backoff_rpcPD_max_addr: 127.0.0.1 Cop_backoff_rpcPD_avg_time: 0.2 Cop_backoff_rpcPD_p90_time: 0.2 Cop_backoff_rpcTiKV_total_times: 200 Cop_backoff_rpcTiKV_total_time: 0.2 Cop_backoff_rpcTiKV_max_time: 0.2 Cop_backoff_rpcTiKV_max_addr: 127.0.0.1 Cop_backoff_rpcTiKV_avg_time: 0.2 Cop_backoff_rpcTiKV_p90_time: 0.2,` + `0,0,1,1,1,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,` + `update t set i = 1;,select * from t;` t.Log(expectRecordString) g.Expect(recordString).To(gomega.Equal(expectRecordString), recordString) // Issue 20928 reader = bufio.NewReader(bytes.NewBufferString(slowLogStr)) rows, err = parseSlowLog(reader, 1, loc) g.Expect(err).ShouldNot(gomega.HaveOccurred()) g.Expect(len(rows)).To(gomega.Equal(1)) recordString = "" for i, value := range rows[0] { str, err := value.ToString() g.Expect(err).ShouldNot(gomega.HaveOccurred()) if i > 0 { recordString += "," } recordString += str } expectRecordString = `2019-04-28T15:24:04.309074+08:00,` + `405888132465033227,root,localhost,0,57,0.12,0.216905,` + `0,0,0,0,0,0,0,0,0,0,0,0,,0,0,0,0,0,0,0.38,0.021,0,0,0,1,637,0,10,10,10,10,100,,,1,42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772,t1:1,t2:2,` + `0.1,0.2,0.03,127.0.0.1:20160,0.05,0.6,0.8,0.0.0.0:20160,70724,65536,0,0,0,0,0,` + `Cop_backoff_regionMiss_total_times: 200 Cop_backoff_regionMiss_total_time: 0.2 Cop_backoff_regionMiss_max_time: 0.2 Cop_backoff_regionMiss_max_addr: 127.0.0.1 Cop_backoff_regionMiss_avg_time: 0.2 Cop_backoff_regionMiss_p90_time: 0.2 Cop_backoff_rpcPD_total_times: 200 Cop_backoff_rpcPD_total_time: 0.2 Cop_backoff_rpcPD_max_time: 0.2 Cop_backoff_rpcPD_max_addr: 127.0.0.1 Cop_backoff_rpcPD_avg_time: 0.2 Cop_backoff_rpcPD_p90_time: 0.2 Cop_backoff_rpcTiKV_total_times: 200 Cop_backoff_rpcTiKV_total_time: 0.2 Cop_backoff_rpcTiKV_max_time: 0.2 Cop_backoff_rpcTiKV_max_addr: 127.0.0.1 Cop_backoff_rpcTiKV_avg_time: 0.2 Cop_backoff_rpcTiKV_p90_time: 0.2,` + `0,0,1,1,1,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,` + `update t set i = 1;,select * from t;` g.Expect(recordString).To(gomega.Equal(expectRecordString)) // fix sql contain '# ' bug slowLog := bytes.NewBufferString( `# Time: 2019-04-28T15:24:04.309074+08:00 select a# from t; # Time: 2019-01-24T22:32:29.313255+08:00 # Txn_start_ts: 405888132465033227 # Query_time: 0.216905 # Process_time: 0.021 Request_count: 1 Total_keys: 637 Processed_keys: 436 # Is_internal: true # Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772 # Stats: t1:1,t2:2 # Succ: false select * from t; `) reader = bufio.NewReader(slowLog) _, err = parseSlowLog(reader, 64, loc) g.Expect(err).ShouldNot(gomega.HaveOccurred()) // test for time format compatibility. slowLog = bytes.NewBufferString( `# Time: 2019-04-28T15:24:04.309074+08:00 select * from t; # Time: 2019-04-24-19:41:21.716221 +0800 select * from t; `) reader = bufio.NewReader(slowLog) rows, err = parseSlowLog(reader, 64, loc) g.Expect(err).ShouldNot(gomega.HaveOccurred()) g.Expect(len(rows)).To(gomega.Equal(2)) t0Str, err := rows[0][0].ToString() g.Expect(err).ShouldNot(gomega.HaveOccurred()) g.Expect(t0Str).To(gomega.Equal("2019-04-28T15:24:04.309074+08:00")) t1Str, err := rows[1][0].ToString() g.Expect(err).ShouldNot(gomega.HaveOccurred()) g.Expect(t1Str).To(gomega.Equal("2019-04-24-19:41:21.716221 +0800")) // Add parse error check. slowLog = bytes.NewBufferString( `# Time: 2019-04-28T15:24:04.309074+08:00 # Succ: abc select * from t; `) reader = bufio.NewReader(slowLog) _, err = parseSlowLog(reader, 64, loc) g.Expect(err).ShouldNot(gomega.HaveOccurred()) } // It changes MaxOfMaxAllowedPacket, so must be stayed in SerialSuite. func TestParseSlowLogFileSerial(t *testing.T) { g := gomega.NewWithT(t) loc, err := time.LoadLocation("Asia/Shanghai") g.Expect(err).ShouldNot(gomega.HaveOccurred()) // test for bufio.Scanner: token too long. slowLog := bytes.NewBufferString( `# Time: 2019-04-28T15:24:04.309074+08:00 select * from t; # Time: 2019-04-24-19:41:21.716221 +0800 `) originValue := variable.MaxOfMaxAllowedPacket variable.MaxOfMaxAllowedPacket = 65536 sql := strings.Repeat("x", int(variable.MaxOfMaxAllowedPacket+1)) slowLog.WriteString(sql) reader := bufio.NewReader(slowLog) _, err = parseSlowLog(reader, 64, loc) g.Expect(err).Should(gomega.HaveOccurred()) g.Expect(err.Error()).To(gomega.Equal("single line length exceeds limit: 65536")) variable.MaxOfMaxAllowedPacket = originValue reader = bufio.NewReader(slowLog) _, err = parseSlowLog(reader, 64, loc) g.Expect(err).ShouldNot(gomega.HaveOccurred()) } func TestSlowLogParseTime(t *testing.T) { g := gomega.NewWithT(t) t1Str := "2019-01-24T22:32:29.313255+08:00" t2Str := "2019-01-24T22:32:29.313255" t1, err := ParseTime(t1Str) g.Expect(err).ShouldNot(gomega.HaveOccurred()) loc, err := time.LoadLocation("Asia/Shanghai") g.Expect(err).ShouldNot(gomega.HaveOccurred()) t2, err := time.ParseInLocation("2006-01-02T15:04:05.999999999", t2Str, loc) g.Expect(err).ShouldNot(gomega.HaveOccurred()) g.Expect(t1.Unix()).To(gomega.Equal(t2.Unix())) t1Format := t1.In(loc).Format(logutil.SlowLogTimeFormat) g.Expect(t1Format).To(gomega.Equal(t1Str)) } // TestFixParseSlowLogFile bugfix // sql select * from INFORMATION_SCHEMA.SLOW_QUERY limit 1; // ERROR 1105 (HY000): string "2019-05-12-11:23:29.61474688" doesn't has a prefix that matches format "2006-01-02-15:04:05.999999999 -0700", err: parsing time "2019-05-12-11:23:29.61474688" as "2006-01-02-15:04:05.999999999 -0700": cannot parse "" as "-0700" func TestFixParseSlowLogFile(t *testing.T) { g := gomega.NewWithT(t) slowLog := bytes.NewBufferString( `# Time: 2019-05-12-11:23:29.614327491 +0800 # Txn_start_ts: 405888132465033227 # Query_time: 0.216905 # Process_time: 0.021 Request_count: 1 Total_keys: 637 Processed_keys: 436 # 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 # Time: 2019-05-12-11:23:29.614327491 +0800 # Txn_start_ts: 405888132465033227 # Query_time: 0.216905 # Process_time: 0.021 Request_count: 1 Total_keys: 637 Processed_keys: 436 # 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 # Plan_digest: 60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4 select * from t;`) scanner := bufio.NewReader(slowLog) loc, err := time.LoadLocation("Asia/Shanghai") g.Expect(err).ShouldNot(gomega.HaveOccurred()) _, err = parseSlowLog(scanner, 64, loc) g.Expect(err).ShouldNot(gomega.HaveOccurred()) // Test parser error. slowLog = bytes.NewBufferString( `# Time: 2019-05-12-11:23:29.614327491 +0800 # Txn_start_ts: 405888132465033227# select * from t; `) scanner = bufio.NewReader(slowLog) _, err = parseSlowLog(scanner, 64, loc) g.Expect(err).ShouldNot(gomega.HaveOccurred()) } func TestSlowQueryRetriever(t *testing.T) { g := gomega.NewWithT(t) 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; # Time: 2020-04-15T18:00:05.299063744+08:00 select 7;` logData := []string{logData0, logData1, logData2, logData3} fileName0 := "tidb-slow-2020-02-14T19-04-05.01.log" fileName1 := "tidb-slow-2020-02-15T19-04-05.01.log" fileName2 := "tidb-slow-2020-02-16T19-04-05.01.log" fileName3 := "tidb-slow.log" fileNames := []string{fileName0, fileName1, fileName2, fileName3} prepareLogs(g, logData, fileNames) defer func() { removeFiles(t, 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{fileName3}, querys: []string{ "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") g.Expect(err).ShouldNot(gomega.HaveOccurred()) // sctx := mock.NewContext() // sctx.GetSessionVars().TimeZone = loc // sctx.GetSessionVars().SlowQueryFile = fileName3 for i, cas := range cases { t.Run("", func(t *testing.T) { comment := fmt.Sprintf("case id: %v", i) retriever, err := newSlowQueryRetriever(loc) g.Expect(err).ShouldNot(gomega.HaveOccurred()) retriever.slowQueryFile = fileName3 timeFilter := len(cas.startTime) > 0 && len(cas.endTime) > 0 if timeFilter { startTime, err := ParseTime(cas.startTime) g.Expect(err).ShouldNot(gomega.HaveOccurred()) endTime, err := ParseTime(cas.endTime) g.Expect(err).ShouldNot(gomega.HaveOccurred()) retriever.filterTimeRanges = true retriever.timeRanges = []slowLogTimeRange{ {startTime, endTime}, } } else { retriever.singleFile = true } err = retriever.initialize(context.Background()) g.Expect(err).ShouldNot(gomega.HaveOccurred()) g.Expect(len(retriever.files)).To(gomega.Equal(len(cas.files)), comment) if len(retriever.files) > 0 { reader := bufio.NewReader(retriever.files[0].file) rows, err := parseLog(retriever, reader, 64) g.Expect(err).ShouldNot(gomega.HaveOccurred()) g.Expect(len(rows)).To(gomega.Equal(len(cas.querys)), comment) for i, row := range rows { g.Expect(row[len(row)-1].GetString()).To(gomega.Equal(cas.querys[i]), comment) } } for i, file := range retriever.files { g.Expect(file.file.Name()).To(gomega.Equal(cas.files[i])) } g.Expect(retriever.Close()).Should(gomega.Succeed()) }) } } func TestSplitbyColon(t *testing.T) { t.Parallel() g := gomega.NewWithT(t) cases := []struct { line string fields []string values []string }{ { "", []string{}, []string{}, }, { "123a", []string{}, []string{"123a"}, }, { "1a: 2b", []string{"1a"}, []string{"2b"}, }, { "1a: [2b 3c] 4d: 5e", []string{"1a", "4d"}, []string{"[2b 3c]", "5e"}, }, { "1a: [2b,3c] 4d: 5e", []string{"1a", "4d"}, []string{"[2b,3c]", "5e"}, }, { "Time: 2021-09-08T14:39:54.506967433+08:00", []string{"Time"}, []string{"2021-09-08T14:39:54.506967433+08:00"}, }, } for _, c := range cases { resFields, resValues := splitByColon(c.line) g.Expect(c.fields).To(gomega.Equal(resFields)) g.Expect(c.values).To(gomega.Equal(resValues)) } } func TestBatchLogForReversedScan(t *testing.T) { g := gomega.NewWithT(t) 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-04-15T18:00:05.299063744+08:00` logData4 := `select 8; # Time: 2020-04-15T19:00:05.299063744+08:00 select 9;` logData := []string{logData0, logData1, logData2, logData3, logData4} fileName0 := "tidb-slow-2020-02-14T19-04-05.01.log" fileName1 := "tidb-slow-2020-02-15T19-04-05.01.log" fileName2 := "tidb-slow-2020-02-16T19-04-05.01.log" fileName3 := "tidb-slow-2020-02-17T19-04-05.01.log" fileName4 := "tidb-slow.log" fileNames := []string{fileName0, fileName1, fileName2, fileName3, fileName4} prepareLogs(g, logData, fileNames) defer func() { removeFiles(t, fileNames) }() cases := []struct { startTime string endTime string files []string logs [][]string }{ { startTime: "2020-02-15T18:00:00.000000+08:00", endTime: "2020-02-15T19:00:00.000000+08:00", files: []string{fileName1}, logs: [][]string{ { "# Time: 2020-02-15T19:00:05.000000+08:00", "select 2;", "# Time: 2020-02-15T18:00:01.000000+08:00", "select 1;", }, }, }, { startTime: "2020-02-15T20:00:05.000000+08:00", endTime: "2020-02-17T19:00:00.000000+08:00", files: []string{fileName1, fileName2, fileName3}, logs: [][]string{ { "# Time: 2020-02-17T18:00:05.000000+08:00", "select 7;", "# Time: 2020-02-16T19:00:00.000000+08:00", "select 6;", "# Time: 2020-02-16T18:00:05.000000+08:00", "select 5;", "# Time: 2020-02-16T18:00:01.000000+08:00", "select 4;", "# Time: 2020-02-16T18:00:01.000000+08:00", "select 3;", }, }, }, { startTime: "2020-02-16T19:00:00.000000+08:00", endTime: "2020-04-15T20:00:00.000000+08:00", files: []string{fileName3, fileName4}, logs: [][]string{ { "# Time: 2020-04-15T19:00:05.299063744+08:00", "select 9;", "Time: 2020-04-15T18:00:05.299063744+08:00", "select 8;", "# Time: 2020-02-17T18:00:05.000000+08:00", "select 7;", "# Time: 2020-02-16T19:00:00.000000+08:00", "select 6;", }, }, }, } loc, err := time.LoadLocation("Asia/Shanghai") g.Expect(err).ShouldNot(gomega.HaveOccurred()) for i, cas := range cases { //extractor := &plannercore.SlowQueryExtractor{Enable: (len(cas.startTime) > 0 && len(cas.endTime) > 0), Desc: true} //if extractor.Enable { // startTime, err := ParseTime(cas.startTime) // g.Expect(err).ShouldNot(gomega.HaveOccurred()) // endTime, err := ParseTime(cas.endTime) // g.Expect(err).ShouldNot(gomega.HaveOccurred()) // extractor.TimeRanges = []*plannercore.TimeRange{{StartTime: startTime, EndTime: endTime}} //} retriever, err := newSlowQueryRetriever(loc) g.Expect(err).ShouldNot(gomega.HaveOccurred()) retriever.desc = true retriever.slowQueryFile = fileName4 timeFilter := len(cas.startTime) > 0 && len(cas.endTime) > 0 if timeFilter { startTime, err := ParseTime(cas.startTime) g.Expect(err).ShouldNot(gomega.HaveOccurred()) endTime, err := ParseTime(cas.endTime) g.Expect(err).ShouldNot(gomega.HaveOccurred()) retriever.filterTimeRanges = true retriever.timeRanges = []slowLogTimeRange{ {startTime, endTime}, } } else { retriever.singleFile = true } err = retriever.initialize(context.Background()) g.Expect(err).ShouldNot(gomega.HaveOccurred()) comment := fmt.Sprintf("case id: %v", i) g.Expect(len(retriever.files)).To(gomega.Equal(len(cas.files)), comment) if len(retriever.files) > 0 { reader := bufio.NewReader(retriever.files[0].file) offset := &offset{length: 0, offset: 0} rows, err := retriever.getBatchLogForReversedScan(context.Background(), reader, offset, 3) g.Expect(err).ShouldNot(gomega.HaveOccurred()) for _, row := range rows { for j, log := range row { g.Expect(log).To(gomega.Equal(cas.logs[0][j]), comment) } } } g.Expect(retriever.Close()).Should(gomega.Succeed()) } } func prepareLogs(g *gomega.WithT, logData, fileNames []string) { writeFile := func(file, data string) { f, err := os.OpenFile(file, os.O_CREATE|os.O_WRONLY|os.O_TRUNC, 0o644) g.Expect(err).ShouldNot(gomega.HaveOccurred()) _, err = f.Write([]byte(data)) g.Expect(f.Close()).Should(gomega.Succeed()) g.Expect(err).ShouldNot(gomega.HaveOccurred()) } for i, log := range logData { writeFile(fileNames[i], log) } } func removeFiles(t *testing.T, fileNames []string) { for _, fileName := range fileNames { if err := os.Remove(fileName); err != nil { t.Errorf("file remove failed, err: %s", err) } } }