replication: refactor driving logic (no more explicit state machine)

This commit is contained in:
Christian Schwarz
2019-02-22 11:40:27 +01:00
parent 0230c6321f
commit 07b43bffa4
33 changed files with 1594 additions and 1515 deletions
+301
View File
@@ -0,0 +1,301 @@
package driver
import (
"context"
"sync"
"time"
"github.com/zrepl/zrepl/replication/report"
"github.com/zrepl/zrepl/util/chainlock"
)
type run struct {
l *chainlock.L
startedAt, finishedAt time.Time
// the attempts attempted so far:
// All but the last in this slice must have finished with some errors.
// The last attempt may not be finished and may not have errors.
attempts []*attempt
}
type Planner interface {
Plan(context.Context) ([]FS, error)
}
// an attempt represents a single planning & execution of fs replications
type attempt struct {
planner Planner
l *chainlock.L
startedAt, finishedAt time.Time
// after Planner.Plan was called, planErr and fss are mutually exclusive with regards to nil-ness
// if both are nil, it must be assumed that Planner.Plan is active
planErr *timedError
fss []*fs
}
type timedError struct {
Err error
Time time.Time
}
func newTimedError(err error, t time.Time) *timedError {
if err == nil {
panic("error must be non-nil")
}
if t.IsZero() {
panic("t must be non-zero")
}
return &timedError{err, t}
}
func (e *timedError) IntoReportError() *report.TimedError {
if e == nil {
return nil
}
return report.NewTimedError(e.Err.Error(), e.Time)
}
type FS interface {
PlanFS(context.Context) ([]Step, error)
ReportInfo() *report.FilesystemInfo
}
type Step interface {
TargetDate() time.Time
Step(context.Context) error
ReportInfo() *report.StepInfo
}
type fs struct {
fs FS
l *chainlock.L
planning struct {
done bool
err *timedError
}
// valid iff planning.done && planning.err == nil
planned struct {
// valid iff planning.done && planning.err == nil
stepErr *timedError
// all steps, in the order in which they must be completed
steps []*step
// index into steps, pointing at the step that is currently executing
// if step >= len(steps), no more work needs to be done
step int
}
}
type step struct {
l *chainlock.L
step Step
}
type ReportFunc func() *report.Report
type WaitFunc func(block bool) (done bool)
func Do(ctx context.Context, planner Planner) (ReportFunc, WaitFunc) {
l := chainlock.New()
run := &run{
l: l,
startedAt: time.Now(),
}
done := make(chan struct{})
go func() {
defer close(done)
run.l.Lock()
a1 := &attempt{
l: l,
startedAt: time.Now(),
planner: planner,
}
run.attempts = append(run.attempts, a1)
run.l.Unlock()
a1.do(ctx)
}()
wait := func(block bool) bool {
if block {
<-done
}
select {
case <-done:
return true
default:
return false
}
}
report := func() *report.Report {
defer run.l.Lock().Unlock()
return run.report()
}
return report, wait
}
func (a *attempt) do(ctx context.Context) {
pfss, err := a.planner.Plan(ctx)
errTime := time.Now()
defer a.l.Lock().Unlock()
if err != nil {
a.planErr = newTimedError(err, errTime)
a.fss = nil
a.finishedAt = time.Now()
return
}
for _, pfs := range pfss {
fs := &fs{
fs: pfs,
l: a.l,
}
a.fss = append(a.fss, fs)
}
stepQueue := newStepQueue()
defer stepQueue.Start(1)()
var fssesDone sync.WaitGroup
for _, f := range a.fss {
fssesDone.Add(1)
go func(f *fs) {
defer fssesDone.Done()
f.do(ctx, stepQueue)
}(f)
}
a.l.DropWhile(func() {
fssesDone.Wait()
})
a.finishedAt = time.Now()
}
func (fs *fs) do(ctx context.Context, pq *stepQueue) {
psteps, err := fs.fs.PlanFS(ctx)
errTime := time.Now()
defer fs.l.Lock().Unlock()
fs.planning.done = true
if err != nil {
fs.planning.err = newTimedError(err, errTime)
return
}
for _, pstep := range psteps {
step := &step{
l: fs.l,
step: pstep,
}
fs.planned.steps = append(fs.planned.steps, step)
}
for i, s := range fs.planned.steps {
var (
err error
errTime time.Time
)
// lock must not be held while executing step in order for reporting to work
fs.l.DropWhile(func() {
targetDate := s.step.TargetDate()
defer pq.WaitReady(fs, targetDate)()
err = s.step.Step(ctx) // no shadow
errTime = time.Now() // no shadow
})
if err != nil {
fs.planned.stepErr = newTimedError(err, errTime)
break
}
fs.planned.step = i + 1 // fs.planned.step must be == len(fs.planned.steps) if all went OK
}
}
// caller must hold lock l
func (r *run) report() *report.Report {
report := &report.Report{
Attempts: make([]*report.AttemptReport, len(r.attempts)),
StartAt: r.startedAt,
FinishAt: r.finishedAt,
}
for i := range report.Attempts {
report.Attempts[i] = r.attempts[i].report()
}
return report
}
// caller must hold lock l
func (a *attempt) report() *report.AttemptReport {
r := &report.AttemptReport{
// State is set below
Filesystems: make([]*report.FilesystemReport, len(a.fss)),
StartAt: a.startedAt,
FinishAt: a.finishedAt,
PlanError: a.planErr.IntoReportError(),
}
for i := range r.Filesystems {
r.Filesystems[i] = a.fss[i].report()
}
state := report.AttemptPlanning
if a.planErr != nil {
state = report.AttemptPlanningError
} else if a.fss != nil {
if a.finishedAt.IsZero() {
state = report.AttemptFanOutFSs
} else {
fsWithError := false
for _, s := range r.Filesystems {
fsWithError = fsWithError || s.Error() != nil
}
state = report.AttemptDone
if fsWithError {
state = report.AttemptFanOutError
}
}
}
r.State = state
return r
}
// caller must hold lock l
func (f *fs) report() *report.FilesystemReport {
state := report.FilesystemPlanningErrored
if f.planning.err == nil {
if f.planning.done {
if f.planned.stepErr != nil {
state = report.FilesystemSteppingErrored
} else if f.planned.step < len(f.planned.steps) {
state = report.FilesystemStepping
} else {
state = report.FilesystemDone
}
} else {
state = report.FilesystemPlanning
}
}
r := &report.FilesystemReport{
Info: f.fs.ReportInfo(),
State: state,
PlanError: f.planning.err.IntoReportError(),
StepError: f.planned.stepErr.IntoReportError(),
Steps: make([]*report.StepReport, len(f.planned.steps)),
CurrentStep: f.planned.step,
}
for i := range r.Steps {
r.Steps[i] = f.planned.steps[i].report()
}
return r
}
// caller must hold lock l
func (s *step) report() *report.StepReport {
r := &report.StepReport{
Info: s.step.ReportInfo(),
}
return r
}
@@ -0,0 +1,204 @@
package driver
import (
"context"
"encoding/json"
"fmt"
"sort"
"sync/atomic"
"testing"
"time"
"github.com/stretchr/testify/require"
"github.com/zrepl/zrepl/replication/report"
"github.com/stretchr/testify/assert"
jsondiff "github.com/yudai/gojsondiff"
jsondiffformatter "github.com/yudai/gojsondiff/formatter"
)
type mockPlanner struct {
stepCounter uint32
fss []FS // *mockFS
}
func (p *mockPlanner) Plan(ctx context.Context) ([]FS, error) {
time.Sleep(1 * time.Second)
p.fss = []FS{
&mockFS{
&p.stepCounter,
"zroot/one",
nil,
},
&mockFS{
&p.stepCounter,
"zroot/two",
nil,
},
}
return p.fss, nil
}
type mockFS struct {
globalStepCounter *uint32
name string
steps []Step
}
func (f *mockFS) PlanFS(ctx context.Context) ([]Step, error) {
if f.steps != nil {
panic("PlanFS used twice")
}
switch f.name {
case "zroot/one":
f.steps = []Step{
&mockStep{
fs: f,
ident: "a",
duration: 1 * time.Second,
targetDate: time.Unix(2, 0),
},
&mockStep{
fs: f,
ident: "b",
duration: 1 * time.Second,
targetDate: time.Unix(10, 0),
},
&mockStep{
fs: f,
ident: "c",
duration: 1 * time.Second,
targetDate: time.Unix(20, 0),
},
}
case "zroot/two":
f.steps = []Step{
&mockStep{
fs: f,
ident: "u",
duration: 500 * time.Millisecond,
targetDate: time.Unix(15, 0),
},
&mockStep{
fs: f,
duration: 500 * time.Millisecond,
ident: "v",
targetDate: time.Unix(30, 0),
},
}
default:
panic("unimplemented")
}
return f.steps, nil
}
func (f *mockFS) ReportInfo() *report.FilesystemInfo {
return &report.FilesystemInfo{Name: f.name}
}
type mockStep struct {
fs *mockFS
ident string
duration time.Duration
targetDate time.Time
// filled by method Step
globalCtr uint32
}
func (f *mockStep) String() string {
return fmt.Sprintf("%s{%s} targetDate=%s globalCtr=%v", f.fs.name, f.ident, f.targetDate, f.globalCtr)
}
func (f *mockStep) Step(ctx context.Context) error {
f.globalCtr = atomic.AddUint32(f.fs.globalStepCounter, 1)
time.Sleep(f.duration)
return nil
}
func (f *mockStep) TargetDate() time.Time {
return f.targetDate
}
func (f *mockStep) ReportInfo() *report.StepInfo {
return &report.StepInfo{From: f.ident, To: f.ident, BytesExpected: 100, BytesReplicated: 25}
}
// TODO: add meaningful validation (i.e. actual checks)
// Since the stepqueue is not deterministic due to scheduler jitter,
// we cannot test for any definitive sequence of steps here.
// Such checks would further only be sensible for a non-concurrent step-queue,
// but we're going to have concurrent replication in the future.
//
// For the time being, let's just exercise the code a bit.
func TestReplication(t *testing.T) {
ctx := context.Background()
mp := &mockPlanner{}
getReport, wait := Do(ctx, mp)
begin := time.Now()
fireAt := []time.Duration{
// the following values are relative to the start
500 * time.Millisecond, // planning
1500 * time.Millisecond, // nothing is done, a is running
2500 * time.Millisecond, // a done, b running
3250 * time.Millisecond, // a,b done, u running
3750 * time.Millisecond, // a,b,u done, c running
4750 * time.Millisecond, // a,b,u,c done, v running
5250 * time.Millisecond, // a,b,u,c,v done
}
reports := make([]*report.Report, len(fireAt))
for i := range fireAt {
sleepUntil := begin.Add(fireAt[i])
time.Sleep(sleepUntil.Sub(time.Now()))
reports[i] = getReport()
// uncomment for viewing non-diffed results
// t.Logf("report @ %6.4f:\n%s", fireAt[i].Seconds(), pretty.Sprint(reports[i]))
}
waitBegin := time.Now()
wait(true)
waitDuration := time.Now().Sub(waitBegin)
assert.True(t, waitDuration < 10*time.Millisecond, "%v", waitDuration) // and that's gratious
prev, err := json.Marshal(reports[0])
require.NoError(t, err)
for _, r := range reports[1:] {
this, err := json.Marshal(r)
require.NoError(t, err)
differ := jsondiff.New()
diff, err := differ.Compare(prev, this)
require.NoError(t, err)
df := jsondiffformatter.NewDeltaFormatter()
res, err := df.Format(diff)
res = res
require.NoError(t, err)
// uncomment the following line to get json diffs between each captured step
// t.Logf("%s", res)
prev, err = json.Marshal(r)
require.NoError(t, err)
}
steps := make([]*mockStep, 0)
for _, fs := range mp.fss {
for _, step := range fs.(*mockFS).steps {
steps = append(steps, step.(*mockStep))
}
}
// sort steps in pq order (although, remember, pq is not deterministic)
sort.Slice(steps, func(i, j int) bool {
return steps[i].targetDate.Before(steps[j].targetDate)
})
// manual inspection of the globalCtr value should show that, despite
// scheduler-dependent behavior of pq, steps should generally be taken
// from oldest to newest target date (globally, not per FS).
t.Logf("steps sorted by target date:")
for _, step := range steps {
t.Logf("\t%s", step)
}
}
+163
View File
@@ -0,0 +1,163 @@
package driver
import (
"container/heap"
"time"
"github.com/zrepl/zrepl/util/chainlock"
)
type stepQueueRec struct {
ident interface{}
targetDate time.Time
wakeup chan StepCompletedFunc
}
type stepQueue struct {
stop chan struct{}
reqs chan stepQueueRec
}
type stepQueueHeapItem struct {
idx int
req stepQueueRec
}
type stepQueueHeap []*stepQueueHeapItem
func (h stepQueueHeap) Less(i, j int) bool {
return h[i].req.targetDate.Before(h[j].req.targetDate)
}
func (h stepQueueHeap) Swap(i, j int) {
h[i], h[j] = h[j], h[i]
h[i].idx = i
h[j].idx = j
}
func (h stepQueueHeap) Len() int {
return len(h)
}
func (h *stepQueueHeap) Push(elem interface{}) {
hitem := elem.(*stepQueueHeapItem)
hitem.idx = h.Len()
*h = append(*h, hitem)
}
func (h *stepQueueHeap) Pop() interface{} {
elem := (*h)[h.Len()-1]
elem.idx = -1
*h = (*h)[:h.Len()-1]
return elem
}
// returned stepQueue must be closed with method Close
func newStepQueue() *stepQueue {
q := &stepQueue{
stop: make(chan struct{}),
reqs: make(chan stepQueueRec),
}
return q
}
// the returned done function must be called to free resources
// allocated by the call to Start
//
// No WaitReady calls must be active at the time done is called
// The behavior of calling WaitReady after done was called is undefined
func (q *stepQueue) Start(concurrency int) (done func()) {
if concurrency < 1 {
panic("concurrency must be >= 1")
}
// l protects pending and queueItems
l := chainlock.New()
pendingCond := l.NewCond()
// priority queue
pending := &stepQueueHeap{}
// ident => queueItem
queueItems := make(map[interface{}]*stepQueueHeapItem)
// stopped is used for cancellation of "wake" goroutine
stopped := false
active := 0
go func() { // "stopper" goroutine
<-q.stop
defer l.Lock().Unlock()
stopped = true
pendingCond.Broadcast()
}()
go func() { // "reqs" goroutine
for {
select {
case <-q.stop:
select {
case <-q.reqs:
panic("WaitReady call active while calling Close")
default:
return
}
case req := <-q.reqs:
func() {
defer l.Lock().Unlock()
if _, ok := queueItems[req.ident]; ok {
panic("WaitReady must not be called twice for the same ident")
}
qitem := &stepQueueHeapItem{
req: req,
}
queueItems[req.ident] = qitem
heap.Push(pending, qitem)
pendingCond.Broadcast()
}()
}
}
}()
go func() { // "wake" goroutine
defer l.Lock().Unlock()
for {
for !stopped && (active >= concurrency || pending.Len() == 0) {
pendingCond.Wait()
}
if stopped {
return
}
if pending.Len() <= 0 {
return
}
active++
next := heap.Pop(pending).(*stepQueueHeapItem).req
delete(queueItems, next.ident)
next.wakeup <- func() {
defer l.Lock().Unlock()
active--
pendingCond.Broadcast()
}
}
}()
done = func() {
close(q.stop)
}
return done
}
type StepCompletedFunc func()
func (q *stepQueue) sendAndWaitForWakeup(ident interface{}, targetDate time.Time) StepCompletedFunc {
req := stepQueueRec{
ident,
targetDate,
make(chan StepCompletedFunc),
}
q.reqs <- req
return <-req.wakeup
}
// Wait for the ident with targetDate to be selected to run.
func (q *stepQueue) WaitReady(ident interface{}, targetDate time.Time) StepCompletedFunc {
if targetDate.IsZero() {
panic("targetDate of zero is reserved for marking Done")
}
return q.sendAndWaitForWakeup(ident, targetDate)
}
@@ -0,0 +1,166 @@
package driver
import (
"fmt"
"math"
"sort"
"sync"
"sync/atomic"
"testing"
"time"
"github.com/montanaflynn/stats"
"github.com/stretchr/testify/assert"
)
func TestPqNotconcurrent(t *testing.T) {
var ctr uint32
q := newStepQueue()
var wg sync.WaitGroup
wg.Add(3)
go func() {
defer wg.Done()
defer q.WaitReady("1", time.Unix(1, 0))()
ret := atomic.AddUint32(&ctr, 1)
assert.Equal(t, uint32(1), ret)
}()
go func() {
defer wg.Done()
defer q.WaitReady("2", time.Unix(2, 0))()
ret := atomic.AddUint32(&ctr, 1)
assert.Equal(t, uint32(2), ret)
}()
go func() {
defer wg.Done()
defer q.WaitReady("3", time.Unix(3, 0))()
ret := atomic.AddUint32(&ctr, 1)
assert.Equal(t, uint32(3), ret)
}()
time.Sleep(1 * time.Second)
defer q.Start(1)()
wg.Wait()
}
type record struct {
fs int
step int
globalCtr uint32
wakeAt time.Duration // relative to begin
}
func (r record) String() string {
return fmt.Sprintf("fs %08d step %08d globalCtr %08d wakeAt %2.8f", r.fs, r.step, r.globalCtr, r.wakeAt.Seconds())
}
// This tests uses stepPq concurrently, simulating the following scenario:
// Given a number of filesystems F, each filesystem has N steps to take.
// The number of concurrent steps is limited to C.
// The target date for each step is the step number N.
// Hence, there are always F filesystems runnable (calling WaitReady)
// The priority queue prioritizes steps with lower target data (= lower step number).
// Hence, all steps with lower numbers should be woken up before steps with higher numbers.
// However, scheduling is not 100% deterministic (runtime, OS scheduler, etc).
// Hence, perform some statistics on the wakeup times and assert that the mean wakeup
// times for each step are close together.
func TestPqConcurrent(t *testing.T) {
q := newStepQueue()
var wg sync.WaitGroup
filesystems := 100
stepsPerFS := 20
sleepTimePerStep := 50 * time.Millisecond
wg.Add(filesystems)
var globalCtr uint32
begin := time.Now()
records := make(chan []record, filesystems)
for fs := 0; fs < filesystems; fs++ {
go func(fs int) {
defer wg.Done()
recs := make([]record, 0)
for step := 0; step < stepsPerFS; step++ {
pos := atomic.AddUint32(&globalCtr, 1)
t := time.Unix(int64(step), 0)
done := q.WaitReady(fs, t)
wakeAt := time.Now().Sub(begin)
time.Sleep(sleepTimePerStep)
done()
recs = append(recs, record{fs, step, pos, wakeAt})
}
records <- recs
}(fs)
}
concurrency := 5
defer q.Start(concurrency)()
wg.Wait()
close(records)
t.Logf("loop done")
flattenedRecs := make([]record, 0)
for recs := range records {
flattenedRecs = append(flattenedRecs, recs...)
}
sort.Slice(flattenedRecs, func(i, j int) bool {
return flattenedRecs[i].globalCtr < flattenedRecs[j].globalCtr
})
wakeTimesByStep := map[int][]float64{}
for _, rec := range flattenedRecs {
wakeTimes, ok := wakeTimesByStep[rec.step]
if !ok {
wakeTimes = []float64{}
}
wakeTimes = append(wakeTimes, rec.wakeAt.Seconds())
wakeTimesByStep[rec.step] = wakeTimes
}
meansByStepId := make([]float64, stepsPerFS)
interQuartileRangesByStepIdx := make([]float64, stepsPerFS)
for step := 0; step < stepsPerFS; step++ {
t.Logf("step %d", step)
mean, _ := stats.Mean(wakeTimesByStep[step])
meansByStepId[step] = mean
t.Logf("\tmean: %v", mean)
median, _ := stats.Median(wakeTimesByStep[step])
t.Logf("\tmedian: %v", median)
midhinge, _ := stats.Midhinge(wakeTimesByStep[step])
t.Logf("\tmidhinge: %v", midhinge)
min, _ := stats.Min(wakeTimesByStep[step])
t.Logf("\tmin: %v", min)
max, _ := stats.Max(wakeTimesByStep[step])
t.Logf("\tmax: %v", max)
quartiles, _ := stats.Quartile(wakeTimesByStep[step])
t.Logf("\t%#v", quartiles)
interQuartileRange, _ := stats.InterQuartileRange(wakeTimesByStep[step])
t.Logf("\tinter-quartile range: %v", interQuartileRange)
interQuartileRangesByStepIdx[step] = interQuartileRange
}
iqrMean, _ := stats.Mean(interQuartileRangesByStepIdx)
t.Logf("inter-quartile-range mean: %v", iqrMean)
iqrDev, _ := stats.StandardDeviation(interQuartileRangesByStepIdx)
t.Logf("inter-quartile-range deviation: %v", iqrDev)
// each step should have the same "distribution" (=~ "spread")
assert.True(t, iqrDev < 0.01)
minTimeForAllStepsWithIdxI := sleepTimePerStep.Seconds() * float64(filesystems) / float64(concurrency)
t.Logf("minTimeForAllStepsWithIdxI = %11.8f", minTimeForAllStepsWithIdxI)
for i, mean := range meansByStepId {
// we can't just do (i + 0.5) * minTimeforAllStepsWithIdxI
// because this doesn't account for drift
idealMean := 0.5 * minTimeForAllStepsWithIdxI
if i > 0 {
previousMean := meansByStepId[i-1]
idealMean = previousMean + minTimeForAllStepsWithIdxI
}
deltaFromIdeal := idealMean - mean
t.Logf("step %02d delta from ideal mean wake time: %11.8f - %11.8f = %11.8f", i, idealMean, mean, deltaFromIdeal)
assert.True(t, math.Abs(deltaFromIdeal) < 0.05)
}
}