func (s *ManagerTestSuite) TestBegan(t *check.C) {
var began time.Time
// between intervals
began = ticker.Began(300, 1388577750)
t.Check(began.Unix(), check.Equals, int64(1388577600))
// 1s before next interval
began = ticker.Began(300, 1388577899)
t.Check(began.Unix(), check.Equals, int64(1388577600))
// at interval
began = ticker.Began(300, 1388577900)
t.Check(began.Unix(), check.Equals, int64(1388577900))
}
// @goroutine[1]
func (m *Manager) run(config Config) {
defer func() {
if m.sync.IsGraceful() {
m.status.Update("qan-log-parser", "Stopped")
} else {
m.status.Update("qan-log-parser", "Crashed")
}
m.sync.Done()
}()
m.status.Update("qan-log-parser", "Starting")
// If time to next interval is more than 1 minute, then start first
// interval now. This means first interval will have partial results.
t := m.clock.ETA(m.tickChan)
if t > 60 {
began := ticker.Began(config.Interval, uint(time.Now().UTC().Unix()))
m.logger.Info("First interval began at", began)
m.tickChan <- began
} else {
m.logger.Info(fmt.Sprintf("First interval begins in %.1f seconds", t))
}
intervalChan := m.iter.IntervalChan()
lastTs := time.Time{}
for {
m.logger.Debug("run:wait")
m.workersMux.RLock()
runningWorkers := len(m.workers)
m.workersMux.RUnlock()
m.status.Update("qan-log-parser", fmt.Sprintf("Idle (%d of %d running)", runningWorkers, config.MaxWorkers))
select {
case interval := <-intervalChan:
m.logger.Debug(fmt.Sprintf("run:interval:%d", interval.Number))
m.workersMux.RLock()
runningWorkers := len(m.workers)
m.workersMux.RUnlock()
m.logger.Debug(fmt.Sprintf("%d workers running", runningWorkers))
if runningWorkers >= config.MaxWorkers {
m.logger.Warn("All workers busy, interval dropped")
continue
}
if interval.EndOffset >= config.MaxSlowLogSize {
m.logger.Info("Rotating slow log")
if err := m.rotateSlowLog(config, interval); err != nil {
m.logger.Error(err)
}
}
m.status.Update("qan-log-parser", "Running worker")
job := &Job{
Id: fmt.Sprintf("%d", interval.Number),
SlowLogFile: interval.Filename,
StartOffset: interval.StartOffset,
EndOffset: interval.EndOffset,
RunTime: time.Duration(config.WorkerRunTime) * time.Second,
ExampleQueries: config.ExampleQueries,
}
w := m.workerFactory.Make(fmt.Sprintf("qan-worker-%d", interval.Number))
m.workersMux.Lock()
m.workers[w] = interval
m.workersMux.Unlock()
// Run a worker to parse this slice of the slow log.
go func(interval *Interval) {
m.logger.Debug(fmt.Sprintf("run:interval:%d:start", interval.Number))
defer func() {
m.logger.Debug(fmt.Sprintf("run:interval:%d:done", interval.Number))
if err := recover(); err != nil {
// Worker caused panic. Log it as error because this shouldn't happen.
m.logger.Error(fmt.Sprintf("Lost interval %s: %s", interval, err))
}
m.workerDoneChan <- w
}()
t0 := time.Now()
result, err := w.Run(job)
t1 := time.Now()
if err != nil {
m.logger.Error(err)
return
}
if result == nil {
m.logger.Error("Nil result", fmt.Sprintf("+%v", job))
return
}
result.RunTime = t1.Sub(t0).Seconds()
report := MakeReport(config.ServiceInstance, interval, result, config)
if err := m.spool.Write("qan", report); err != nil {
m.logger.Warn("Lost report:", err)
}
}(interval)
case worker := <-m.workerDoneChan:
m.logger.Debug("run:worker:done")
m.status.Update("qan-log-parser", "Reaping worker")
m.workersMux.Lock()
interval := m.workers[worker]
delete(m.workers, worker)
m.workersMux.Unlock()
if interval.StartTime.After(lastTs) {
t0 := interval.StartTime.Format("2006-01-02 15:04:05")
t1 := interval.StopTime.Format("15:04:05 MST")
m.status.Update("qan-last-interval", fmt.Sprintf("%s to %s", t0, t1))
lastTs = interval.StartTime
}
for file, cnt := range m.oldSlowLogs {
if cnt == 1 {
m.status.Update("qan-log-parser", "Removing old slow log "+file)
if err := os.Remove(file); err != nil {
m.logger.Warn(err)
} else {
delete(m.oldSlowLogs, file)
m.logger.Info("Removed " + file)
}
} else {
m.oldSlowLogs[file] = cnt - 1
}
}
case <-m.sync.StopChan:
m.logger.Debug("run:stop")
m.sync.Graceful()
return
}
}
}
func (a *RealAnalyzer) run() {
a.logger.Debug("run:call")
defer a.logger.Debug("run:return")
mysqlConfigured := false
go a.configureMySQL(a.config.Start, 0) // try forever
defer func() {
a.logger.Info("Stopping")
a.status.Update(a.name, "Stopping worker")
a.worker.Stop()
a.status.Update(a.name, "Stopping interval iter")
a.iter.Stop()
if !mysqlConfigured {
a.status.Update(a.name, "Stopping MySQL config")
a.configureMySQLSync.Stop()
a.configureMySQLSync.Wait()
}
a.status.Update(a.name, "Stopping QAN on MySQL")
a.configureMySQL(a.config.Stop, 1) // try once
if err := recover(); err != nil {
a.logger.Error("QAN crashed: ", err)
a.status.Update(a.name, "Crashed")
} else {
a.status.Update(a.name, "Stopped")
a.logger.Info("Stopped")
}
a.runSync.Done()
}()
workerRunning := false
lastTs := time.Time{}
currentInterval := &Interval{}
for {
a.logger.Debug("run:idle")
if mysqlConfigured {
if workerRunning {
a.status.Update(a.name, "Running")
} else {
a.status.Update(a.name, "Idle")
}
} else {
a.status.Update(a.name, "Trying to configure MySQL")
}
select {
case interval := <-a.iter.IntervalChan():
if !mysqlConfigured {
a.logger.Debug(fmt.Sprintf("run:interval:%d:skip (mysql not configured)", interval.Number))
continue
}
if workerRunning {
a.logger.Warn(fmt.Sprintf("Skipping interval '%s' because interval '%s' is still being parsed",
interval, currentInterval))
continue
}
a.status.Update(a.name, fmt.Sprintf("Starting interval '%s'", interval))
a.logger.Debug(fmt.Sprintf("run:interval:%s", interval))
currentInterval = interval
// Run the worker, timing it, make a report from its results, spool
// the report. When done the interval is returned on workerDoneChan.
go a.runWorker(interval)
workerRunning = true
case interval := <-a.workerDoneChan:
a.logger.Debug("run:worker:done")
a.status.Update(a.name, fmt.Sprintf("Cleaning up after interval '%s'", interval))
workerRunning = false
if interval.StartTime.After(lastTs) {
t0 := interval.StartTime.Format("2006-01-02 15:04:05")
if a.config.CollectFrom == "slowlog" {
t1 := interval.StopTime.Format("15:04:05 MST")
a.status.Update(a.name+"-last-interval", fmt.Sprintf("%s to %s", t0, t1))
} else {
a.status.Update(a.name+"-last-interval", fmt.Sprintf("%s", t0))
}
lastTs = interval.StartTime
}
case mysqlConfigured = <-a.mysqlConfiguredChan:
a.logger.Debug("run:mysql:configured")
// Start the IntervalIter once MySQL has been configured.
// This avoids no data or partial data, e.g. slow log verbosity
// not set yet.
a.iter.Start()
// If the next interval is more than 1 minute in the future,
// simulate a clock tick now to start the iter early. For example,
// if the interval is 5m and it's currently 01:00, the next interval
// starts in 4m and stops in 9m, so data won't be reported for about
// 10m. Instead, tick now so start interval=01:00 and end interval
// =05:00 and data is reported in about 6m.
tickChan := a.iter.TickChan()
t := a.clock.ETA(tickChan)
if t > 60 {
began := ticker.Began(a.config.Interval, uint(time.Now().UTC().Unix()))
a.logger.Info("First interval began at", began)
tickChan <- began
} else {
a.logger.Info(fmt.Sprintf("First interval begins in %.1f seconds", t))
}
case <-a.restartChan:
a.logger.Debug("run:mysql:restart")
// If MySQL is not configured, then configureMySQL() should already
// be running, trying to configure it. Else, we need to run
// configureMySQL again.
if mysqlConfigured {
mysqlConfigured = false
a.iter.Stop()
go a.configureMySQL(a.config.Start, 0) // try forever
}
case <-a.runSync.StopChan:
a.logger.Debug("run:stop")
return
}
}
}