func (s *WorkerTestSuite) RunWorker(config qan.Config, mysqlConn mysql.Connector, i *qan.Interval) (*qan.Result, error) { w := slowlog.NewWorker(s.logger, config, mysqlConn) w.ZeroRunTime = true w.Setup(i) err, res := w.Run() w.Cleanup() return err, res }
func (s *ReportTestSuite) TestResult014(t *C) { si := proto.ServiceInstance{Service: "mysql", InstanceId: 1} config := qan.Config{ ServiceInstance: si, CollectFrom: "slowlog", Interval: 60, WorkerRunTime: 60, ReportLimit: 500, MaxSlowLogSize: 1024 * 1024 * 1000, } logChan := make(chan *proto.LogEntry, 1000) w := slowlog.NewWorker(pct.NewLogger(logChan, "w"), config, mock.NewNullMySQL()) i := &qan.Interval{ Filename: inputDir + "slow014.log", StartOffset: 0, EndOffset: 127118681, } w.Setup(i) result, err := w.Run() t.Assert(err, IsNil) w.Cleanup() start := time.Now().Add(-1 * time.Second) stop := time.Now() interval := &qan.Interval{ Filename: "slow.log", StartTime: start, StopTime: stop, StartOffset: 0, EndOffset: 127118680, } report := qan.MakeReport(config, interval, result) t.Check(report.Global.TotalQueries, Equals, uint64(4)) t.Check(report.Global.UniqueQueries, Equals, uint64(4)) t.Assert(report.Class, HasLen, 4) // This query required improving the log parser to get the correct checksum ID: t.Check(report.Class[0].Id, Equals, "DB9EF18846547B8C") }
func (s *AnalyzerTestSuite) TestRealSlowLogWorker(t *C) { dsn := os.Getenv("PCT_TEST_MYSQL_DSN") if dsn == "" { t.Fatal("PCT_TEST_MYSQL_DSN is not set") } realmysql := mysql.NewConnection(dsn) if err := realmysql.Connect(1); err != nil { t.Fatal(err) } // Don't release all resources immediately because the worker needs the connection defer realmysql.Close() defer test.DrainRecvData(s.dataChan) config := s.config config.Start = []mysql.Query{ mysql.Query{Set: "SET GLOBAL slow_query_log=OFF"}, mysql.Query{Set: "SET GLOBAL long_query_time=0"}, mysql.Query{Set: "SET GLOBAL slow_query_log=ON"}, } config.Stop = []mysql.Query{ mysql.Query{Set: "SET GLOBAL slow_query_log=OFF"}, mysql.Query{Set: "SET GLOBAL long_query_time=10"}, } worker := slowlog.NewWorker(pct.NewLogger(s.logChan, "qan-worker"), config, realmysql) //intervalChan := make(chan *qan.Interval, 1) //iter := mock.NewIter(intervalChan) a := qan.NewRealAnalyzer( pct.NewLogger(s.logChan, "qan-analyzer"), config, s.iter, realmysql, s.restartChan, worker, s.clock, s.spool, ) err := a.Start() t.Assert(err, IsNil) if !test.WaitStatus(3, a, "qan-analyzer", "Idle") { t.Fatal("Timeout waiting for qan-analyzer=Idle") } now := time.Now().UTC() i := &qan.Interval{ Number: 1, StartTime: now, StopTime: now.Add(1 * time.Minute), Filename: inputDir + "slow001.log", StartOffset: 0, EndOffset: 524, } s.intervalChan <- i data := test.WaitData(s.dataChan) t.Assert(data, HasLen, 1) res := data[0].(*qan.Report) t.Check(res.Global.TotalQueries, Equals, uint64(2)) err = a.Stop() t.Assert(err, IsNil) }
func (s *WorkerTestSuite) TestStop(t *C) { config := qan.Config{ ServiceInstance: s.mysqlInstance, Interval: 300, MaxSlowLogSize: 1024 * 1024 * 1024, RemoveOldSlowLogs: true, WorkerRunTime: 60, Start: []mysql.Query{}, Stop: []mysql.Query{}, CollectFrom: "slowlog", } w := slowlog.NewWorker(s.logger, config, s.nullmysql) // Make and set a mock log.LogParser. The worker will use this once when // Start() is called instead of making a real slow log parser. p := mock.NewLogParser() w.SetLogParser(p) now := time.Now() i := &qan.Interval{ Number: 1, StartTime: now, StopTime: now.Add(1 * time.Minute), Filename: inputDir + "slow006.log", StartOffset: 0, EndOffset: 100000, } w.Setup(i) // Run the worker. It calls p.Start() and p.Stop() when done. doneChan := make(chan bool, 1) var res *qan.Result var err error go func() { res, err = w.Run() // calls p.Start() doneChan <- true }() // Send first event. This is aggregated. e := &log.Event{ Offset: 0, Ts: "071015 21:45:10", Query: "select 1 from t", Db: "db1", TimeMetrics: map[string]float32{ "Query_time": 1.111, }, } p.Send(e) // blocks until received // This will block until we send a 2nd event... stopChan := make(chan bool, 1) go func() { w.Stop() stopChan <- true }() // Give Stop() time to send its signal. This isn't ideal, but it's necessary. time.Sleep(500 * time.Millisecond) // Send 2nd event which is not aggregated because a stop ^ is pending. e = &log.Event{ Offset: 100, Ts: "071015 21:50:10", Query: "select 2 from u", Db: "db2", TimeMetrics: map[string]float32{ "Query_time": 2.222, }, } p.Send(e) // blocks until received // Side test: Status() status := w.Status() t.Check(strings.HasPrefix(status["qan-worker"], "Parsing "+i.Filename), Equals, true) if !test.WaitState(stopChan) { t.Fatal("Timeout waiting for <-stopChan") } if !test.WaitState(doneChan) { t.Fatal("Timeout waiting for <-doneChan") } t.Check(res.Global.TotalQueries, Equals, uint64(1)) t.Check(res.Class, HasLen, 1) }
func (s *WorkerTestSuite) TestRotateSlowLog(t *C) { // Same as TestRotateAndRemoveSlowLog but qan.Config.RemoveOldSlowLogs=false // so the old slow log file is not removed. slowlogFile := "slow006.log" files, _ := filepath.Glob("/tmp/" + slowlogFile + "-[0-9]*") for _, file := range files { os.Remove(file) } // See TestStartService() for description of these startup tasks. config := qan.Config{ ServiceInstance: s.mysqlInstance, Interval: 300, MaxSlowLogSize: 1000, RemoveOldSlowLogs: false, // <-- HERE ExampleQueries: false, WorkerRunTime: 600, Start: []mysql.Query{ mysql.Query{Set: "-- start"}, }, Stop: []mysql.Query{ mysql.Query{Set: "-- stop"}, }, CollectFrom: "slowlog", } w := slowlog.NewWorker(s.logger, config, s.nullmysql) // Make copy of slow log because test will mv/rename it. cp := exec.Command("cp", inputDir+slowlogFile, "/tmp/"+slowlogFile) cp.Run() // First interval: 0 - 736 now := time.Now() i1 := &qan.Interval{ Filename: "/tmp/" + slowlogFile, StartOffset: 0, EndOffset: 736, StartTime: now, StopTime: now, } // Rotation happens in Setup(), but the log isn't rotated yet. w.Setup(i1) gotSet := s.nullmysql.GetSet() t.Check(gotSet, HasLen, 0) res, err := w.Run() t.Assert(err, IsNil) w.Cleanup() t.Check(res.Global.TotalQueries, Equals, uint64(2)) t.Check(res.Global.UniqueQueries, Equals, uint64(1)) // Second interval: 736 - 1833, but will actually go to end: 2200. i2 := &qan.Interval{ Filename: "/tmp/" + slowlogFile, StartOffset: 736, EndOffset: 1833, StartTime: now, StopTime: now, } w.Setup(i2) gotSet = s.nullmysql.GetSet() expectSet := append(config.Stop, config.Start...) if same, diff := IsDeeply(gotSet, expectSet); !same { Dump(gotSet) t.Error(diff) } // When rotated, the interval end offset is extended to end of file. t.Check(i2.EndOffset, Equals, int64(2200)) res, err = w.Run() t.Assert(err, IsNil) // The old slow log is removed in Cleanup(), so it should still exist. files, _ = filepath.Glob("/tmp/" + slowlogFile + "-[0-9]*") t.Check(files, HasLen, 1) w.Cleanup() t.Check(res.Global.TotalQueries, Equals, uint64(4)) t.Check(res.Global.UniqueQueries, Equals, uint64(2)) // Original slow log should no longer exist; it was rotated away. if _, err := os.Stat("/tmp/" + slowlogFile); !os.IsNotExist(err) { t.Error("/tmp/" + slowlogFile + " no longer exists") } // The original slow log should NOT have been removed. files, _ = filepath.Glob("/tmp/" + slowlogFile + "-[0-9]*") t.Check(files, HasLen, 1) defer func() { for _, file := range files { os.Remove(file) } }() // https://jira.percona.com/browse/PCT-466 // Old slow log removed but space not freed in filesystem pid := fmt.Sprintf("%d", os.Getpid()) out, err := exec.Command("lsof", "-p", pid).Output() if err != nil { t.Fatal(err) } if strings.Contains(string(out), "/tmp/"+slowlogFile+"-") { t.Logf("%s\n", string(out)) t.Error("Old slow log removed but not freed in filesystem (PCT-466)") } }
func (s *WorkerTestSuite) TestRotateAndRemoveSlowLog(t *C) { // Clean up files that may interfere with test. slowlogFile := "slow006.log" files, _ := filepath.Glob("/tmp/" + slowlogFile + "-[0-9]*") for _, file := range files { os.Remove(file) } /** * slow006.log is 2200 bytes large. Rotation happens when the worker * sees interval.EndOffset >= MaxSlowLogSize. So we'll use these * intervals: * 0 - 736 * 736 - 1833 * 1833 - 2200 * and set MaxSlowLogSize=1000 which should make the worker rotate the log * after the 2nd interval. When the worker rotates log, it 1) renames log * to NAME-TS where NAME is the original name and TS is the current Unix * timestamp (UTC); and 2) it sets interval.StopOff = file size of NAME-TS * to finish parsing the log. Therefore, results for 2nd interval should * include our 3rd interval. -- The worker also calls Start and Stop so the * nullmysql conn should record the queries being set. */ // See TestStartService() for description of these startup tasks. config := qan.Config{ ServiceInstance: s.mysqlInstance, Interval: 300, MaxSlowLogSize: 1000, // <-- HERE RemoveOldSlowLogs: true, // <-- HERE too ExampleQueries: false, WorkerRunTime: 600, Start: []mysql.Query{ mysql.Query{Set: "-- start"}, }, Stop: []mysql.Query{ mysql.Query{Set: "-- stop"}, }, CollectFrom: "slowlog", } w := slowlog.NewWorker(s.logger, config, s.nullmysql) // Make copy of slow log because test will mv/rename it. cp := exec.Command("cp", inputDir+slowlogFile, "/tmp/"+slowlogFile) cp.Run() // First interval: 0 - 736 now := time.Now() i1 := &qan.Interval{ Filename: "/tmp/" + slowlogFile, StartOffset: 0, EndOffset: 736, StartTime: now, StopTime: now, } // Rotation happens in Setup(), but the log isn't rotated yet. w.Setup(i1) gotSet := s.nullmysql.GetSet() t.Check(gotSet, HasLen, 0) res, err := w.Run() t.Assert(err, IsNil) w.Cleanup() t.Check(res.Global.TotalQueries, Equals, uint64(2)) t.Check(res.Global.UniqueQueries, Equals, uint64(1)) // Second interval: 736 - 1833, but will actually go to end: 2200. i2 := &qan.Interval{ Filename: "/tmp/" + slowlogFile, StartOffset: 736, EndOffset: 1833, StartTime: now, StopTime: now, } w.Setup(i2) gotSet = s.nullmysql.GetSet() expectSet := append(config.Stop, config.Start...) if same, diff := IsDeeply(gotSet, expectSet); !same { Dump(gotSet) t.Error(diff) } // When rotated, the interval end offset is extended to end of file. t.Check(i2.EndOffset, Equals, int64(2200)) res, err = w.Run() t.Assert(err, IsNil) // The old slow log is removed in Cleanup(), so it should still exist. files, _ = filepath.Glob("/tmp/" + slowlogFile + "-[0-9]*") t.Check(files, HasLen, 1) w.Cleanup() t.Check(res.Global.TotalQueries, Equals, uint64(4)) t.Check(res.Global.UniqueQueries, Equals, uint64(2)) // Original slow log should no longer exist; it was rotated away. if _, err := os.Stat("/tmp/" + slowlogFile); !os.IsNotExist(err) { t.Error("/tmp/" + slowlogFile + " no longer exists") } // The original slow log should have been renamed to slow006-TS, parsed, and removed. files, _ = filepath.Glob("/tmp/" + slowlogFile + "-[0-9]*") if len(files) != 0 { t.Errorf("Old slow log removed, got %+v", files) } defer func() { for _, file := range files { os.Remove(file) } }() // https://jira.percona.com/browse/PCT-466 // Old slow log removed but space not freed in filesystem pid := fmt.Sprintf("%d", os.Getpid()) out, err := exec.Command("lsof", "-p", pid).Output() if err != nil { t.Fatal(err) } if strings.Contains(string(out), "/tmp/"+slowlogFile+"-") { t.Logf("%s\n", string(out)) t.Error("Old slow log removed but not freed in filesystem (PCT-466)") } }