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)")
}
}
