Пример #1
0
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
}
Пример #2
0
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")
}
Пример #3
0
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)
}
Пример #4
0
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)
}
Пример #5
0
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)")
	}
}
Пример #6
0
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)")
	}
}