diff --git a/cmd/coordinator/buildstatus.go b/cmd/coordinator/buildstatus.go index ebeec8160f..7ca4873288 100644 --- a/cmd/coordinator/buildstatus.go +++ b/cmd/coordinator/buildstatus.go @@ -34,6 +34,7 @@ import ( "golang.org/x/build/internal/buildstats" clog "golang.org/x/build/internal/coordinator/log" "golang.org/x/build/internal/coordinator/pool" + "golang.org/x/build/internal/coordinator/schedule" "golang.org/x/build/internal/singleflight" "golang.org/x/build/internal/sourcecache" "golang.org/x/build/internal/spanlog" @@ -102,14 +103,14 @@ type buildStatus struct { hasBuildlet int32 // atomic: non-zero if this build has a buildlet; for status.go. - mu sync.Mutex // guards following - canceled bool // whether this build was forcefully canceled, so errors should be ignored - schedItem *SchedItem // for the initial buildlet (ignoring helpers for now) - logURL string // if non-empty, permanent URL of log - bc *buildlet.Client // nil initially, until pool returns one - done time.Time // finished running - succeeded bool // set when done - output livelog.Buffer // stdout and stderr + mu sync.Mutex // guards following + canceled bool // whether this build was forcefully canceled, so errors should be ignored + schedItem *schedule.SchedItem // for the initial buildlet (ignoring helpers for now) + logURL string // if non-empty, permanent URL of log + bc *buildlet.Client // nil initially, until pool returns one + done time.Time // finished running + succeeded bool // set when done + output livelog.Buffer // stdout and stderr events []eventAndTime useSnapshotMemo *bool // if non-nil, memoized result of useSnapshot } @@ -293,7 +294,7 @@ func (st *buildStatus) getHelpers() <-chan *buildlet.Client { } func (st *buildStatus) onceInitHelpersFunc() { - schedTmpl := &SchedItem{ + schedTmpl := &schedule.SchedItem{ BuilderRev: st.BuilderRev, HostType: st.conf.HostType, IsTry: st.isTry(), @@ -377,7 +378,7 @@ func (st *buildStatus) checkDep(ctx context.Context, dep string) (have bool, err var errSkipBuildDueToDeps = errors.New("build was skipped due to missing deps") func (st *buildStatus) getBuildlet() (*buildlet.Client, error) { - schedItem := &SchedItem{ + schedItem := &schedule.SchedItem{ HostType: st.conf.HostType, IsTry: st.trySet != nil, BuilderRev: st.BuilderRev, @@ -610,7 +611,7 @@ func (st *buildStatus) buildRecord() *types.BuildRecord { return rec } -func (st *buildStatus) spanRecord(sp *span, err error) *types.SpanRecord { +func (st *buildStatus) SpanRecord(sp *schedule.Span, err error) *types.SpanRecord { rec := &types.SpanRecord{ BuildID: st.buildID, IsTry: st.isTry(), @@ -621,11 +622,11 @@ func (st *buildStatus) spanRecord(sp *span, err error) *types.SpanRecord { OS: st.conf.GOOS(), Arch: st.conf.GOARCH(), - Event: sp.event, - Detail: sp.optText, - StartTime: sp.start, - EndTime: sp.end, - Seconds: sp.end.Sub(sp.start).Seconds(), + Event: sp.Event(), + Detail: sp.OptText(), + StartTime: sp.Start(), + EndTime: sp.End(), + Seconds: sp.End().Sub(sp.Start()).Seconds(), } if err != nil { rec.Error = err.Error() @@ -700,7 +701,7 @@ func (st *buildStatus) crossCompileMakeAndSnapshot(config *dashboard.CrossCompil ctx, cancel := context.WithCancel(st.ctx) defer cancel() sp := st.CreateSpan("get_buildlet_cross") - kubeBC, err := sched.GetBuildlet(ctx, &SchedItem{ + kubeBC, err := sched.GetBuildlet(ctx, &schedule.SchedItem{ HostType: config.CompileHostType, IsTry: st.trySet != nil, BuilderRev: st.BuilderRev, @@ -1576,7 +1577,7 @@ func (st *buildStatus) runTestsOnBuildlet(bc *buildlet.Client, tis []*testItem, } func (st *buildStatus) CreateSpan(event string, optText ...string) spanlog.Span { - return createSpan(st, event, optText...) + return schedule.CreateSpan(st, event, optText...) } func (st *buildStatus) LogEventTime(event string, optText ...string) { diff --git a/cmd/coordinator/coordinator.go b/cmd/coordinator/coordinator.go index 950a2148a2..c66740244b 100644 --- a/cmd/coordinator/coordinator.go +++ b/cmd/coordinator/coordinator.go @@ -60,6 +60,7 @@ import ( clog "golang.org/x/build/internal/coordinator/log" "golang.org/x/build/internal/coordinator/pool" "golang.org/x/build/internal/coordinator/remote" + "golang.org/x/build/internal/coordinator/schedule" "golang.org/x/build/internal/https" "golang.org/x/build/internal/secret" "golang.org/x/build/maintner/maintnerd/apipb" @@ -88,7 +89,7 @@ var ( processID = "P" + randHex(9) ) -var sched = NewScheduler() +var sched = schedule.NewScheduler() var Version string // set by linker -X @@ -1746,7 +1747,7 @@ func (ts *trySet) noteBuildComplete(bs *buildStatus) { // getBuildlets creates up to n buildlets and sends them on the returned channel // before closing the channel. -func getBuildlets(ctx context.Context, n int, schedTmpl *SchedItem, lg pool.Logger) <-chan *buildlet.Client { +func getBuildlets(ctx context.Context, n int, schedTmpl *schedule.SchedItem, lg pool.Logger) <-chan *buildlet.Client { ch := make(chan *buildlet.Client) // NOT buffered var wg sync.WaitGroup wg.Add(n) @@ -1975,61 +1976,6 @@ type eventAndTime struct { text string // optional detail text } -// span is an event covering a region of time. -// A span ultimately ends in an error or success, and will eventually -// be visualized and logged. -type span struct { - event string // event name like "get_foo" or "write_bar" - optText string // optional details for event - start time.Time - end time.Time - el pool.EventTimeLogger // where we log to at the end; TODO: this will change -} - -func createSpan(el pool.EventTimeLogger, event string, optText ...string) *span { - if len(optText) > 1 { - panic("usage") - } - start := time.Now() - var opt string - if len(optText) > 0 { - opt = optText[0] - } - el.LogEventTime(event, opt) - return &span{ - el: el, - event: event, - start: start, - optText: opt, - } -} - -// Done ends a span. -// It is legal to call Done multiple times. Only the first call -// logs. -// Done always returns its input argument. -func (s *span) Done(err error) error { - if !s.end.IsZero() { - return err - } - t1 := time.Now() - s.end = t1 - td := t1.Sub(s.start) - var text bytes.Buffer - fmt.Fprintf(&text, "after %s", friendlyDuration(td)) - if err != nil { - fmt.Fprintf(&text, "; err=%v", err) - } - if s.optText != "" { - fmt.Fprintf(&text, "; %v", s.optText) - } - if st, ok := s.el.(*buildStatus); ok { - clog.CoordinatorProcess().PutSpanRecord(st.spanRecord(s, err)) - } - s.el.LogEventTime("finish_"+s.event, text.String()) - return err -} - var nl = []byte("\n") // getRepoHead returns the commit hash of the latest master HEAD diff --git a/cmd/coordinator/remote.go b/cmd/coordinator/remote.go index ca0d75e88f..1694ddaede 100644 --- a/cmd/coordinator/remote.go +++ b/cmd/coordinator/remote.go @@ -39,6 +39,7 @@ import ( "golang.org/x/build/buildlet" "golang.org/x/build/dashboard" "golang.org/x/build/internal/coordinator/pool" + "golang.org/x/build/internal/coordinator/schedule" "golang.org/x/build/internal/envutil" "golang.org/x/build/internal/gophers" "golang.org/x/build/internal/secret" @@ -167,7 +168,7 @@ func handleBuildletCreate(w http.ResponseWriter, r *http.Request) { w.(http.Flusher).Flush() } - si := &SchedItem{ + si := &schedule.SchedItem{ HostType: bconf.HostType, IsGomote: true, } @@ -237,7 +238,7 @@ func handleBuildletCreate(w http.ResponseWriter, r *http.Request) { for { select { case <-ticker: - st := sched.waiterState(si) + st := sched.WaiterState(si) sendJSONLine(msg{Status: &st}) case bc := <-resc: now := timeNow() diff --git a/cmd/coordinator/status.go b/cmd/coordinator/status.go index 5ccd69af1d..ee0f41812e 100644 --- a/cmd/coordinator/status.go +++ b/cmd/coordinator/status.go @@ -36,6 +36,7 @@ import ( "golang.org/x/build/cmd/coordinator/internal" "golang.org/x/build/dashboard" "golang.org/x/build/internal/coordinator/pool" + "golang.org/x/build/internal/coordinator/schedule" "golang.org/x/build/internal/secret" "golang.org/x/build/kubernetes/api" "golang.org/x/oauth2" @@ -718,7 +719,7 @@ func handleStatus(w http.ResponseWriter, r *http.Request) { pool.ReversePool().WriteHTMLStatus(&buf) data.ReversePoolStatus = template.HTML(buf.String()) - data.SchedState = sched.state() + data.SchedState = sched.State() buf.Reset() if err := statusTmpl.Execute(&buf, data); err != nil { @@ -783,7 +784,7 @@ type statusData struct { KubePoolStatus template.HTML // TODO: embed template ReversePoolStatus template.HTML // TODO: embed template RemoteBuildlets template.HTML - SchedState schedulerState + SchedState schedule.SchedulerState DiskFree string Version string HealthCheckers []*healthChecker diff --git a/cmd/coordinator/status_test.go b/cmd/coordinator/status_test.go index 83215f66a2..6e5cb3d606 100644 --- a/cmd/coordinator/status_test.go +++ b/cmd/coordinator/status_test.go @@ -17,6 +17,8 @@ import ( "strings" "testing" "time" + + "golang.org/x/build/internal/coordinator/schedule" ) var durationTests = []struct { @@ -108,27 +110,27 @@ func TestHandleStatus_HealthFormatting(t *testing.T) { func TestStatusSched(t *testing.T) { data := statusData{ - SchedState: schedulerState{ - HostTypes: []schedulerHostState{ + SchedState: schedule.SchedulerState{ + HostTypes: []schedule.SchedulerHostState{ { HostType: "no-special", LastProgress: 5 * time.Minute, - Total: schedulerWaitingState{Count: 10, Newest: 5 * time.Minute, Oldest: 61 * time.Minute}, - Regular: schedulerWaitingState{Count: 1}, + Total: schedule.SchedulerWaitingState{Count: 10, Newest: 5 * time.Minute, Oldest: 61 * time.Minute}, + Regular: schedule.SchedulerWaitingState{Count: 1}, }, { HostType: "with-try", LastProgress: 5 * time.Minute, - Total: schedulerWaitingState{Count: 3}, - Try: schedulerWaitingState{Count: 1, Newest: 2 * time.Second, Oldest: 5 * time.Minute}, - Regular: schedulerWaitingState{Count: 2}, + Total: schedule.SchedulerWaitingState{Count: 3}, + Try: schedule.SchedulerWaitingState{Count: 1, Newest: 2 * time.Second, Oldest: 5 * time.Minute}, + Regular: schedule.SchedulerWaitingState{Count: 2}, }, { HostType: "gomote-and-try", - Total: schedulerWaitingState{Count: 6, Newest: 3 * time.Second, Oldest: 4 * time.Minute}, - Gomote: schedulerWaitingState{Count: 2, Newest: 3 * time.Second, Oldest: 4 * time.Minute}, - Try: schedulerWaitingState{Count: 1}, - Regular: schedulerWaitingState{Count: 3}, + Total: schedule.SchedulerWaitingState{Count: 6, Newest: 3 * time.Second, Oldest: 4 * time.Minute}, + Gomote: schedule.SchedulerWaitingState{Count: 2, Newest: 3 * time.Second, Oldest: 4 * time.Minute}, + Try: schedule.SchedulerWaitingState{Count: 1}, + Regular: schedule.SchedulerWaitingState{Count: 3}, }, }, }, diff --git a/internal/coordinator/schedule/fake_schedule.go b/internal/coordinator/schedule/fake_schedule.go new file mode 100644 index 0000000000..3d583031de --- /dev/null +++ b/internal/coordinator/schedule/fake_schedule.go @@ -0,0 +1,35 @@ +// Copyright 2018 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +//go:build go1.13 && (linux || darwin) +// +build go1.13 +// +build linux darwin + +package schedule + +import ( + "context" + + "golang.org/x/build/buildlet" + "golang.org/x/build/types" +) + +// Fake is a fake scheduler. +type Fake struct{} + +// NewFake returns a fake scheduler. +func NewFake() *Fake { return &Fake{} } + +// State returns the state of the fake scheduler. +func (f *Fake) State() (st SchedulerState) { return SchedulerState{} } + +// WaiterState is the waiter state of the fake scheduler. +func (f *Fake) WaiterState(waiter *SchedItem) (ws types.BuildletWaitStatus) { + return types.BuildletWaitStatus{} +} + +// GetBuildlet returns a fake buildlet client for the requested buildlet. +func (f *Fake) GetBuildlet(ctx context.Context, si *SchedItem) (*buildlet.Client, error) { + return &buildlet.Client{}, nil +} diff --git a/cmd/coordinator/sched.go b/internal/coordinator/schedule/schedule.go similarity index 94% rename from cmd/coordinator/sched.go rename to internal/coordinator/schedule/schedule.go index 5d9d740366..8e98d073f6 100644 --- a/cmd/coordinator/sched.go +++ b/internal/coordinator/schedule/schedule.go @@ -6,7 +6,7 @@ // +build go1.16 // +build linux darwin -package main +package schedule import ( "context" @@ -139,7 +139,7 @@ func (stderrLogger) LogEventTime(event string, optText ...string) { } func (l stderrLogger) CreateSpan(event string, optText ...string) spanlog.Span { - return createSpan(l, event, optText...) + return CreateSpan(l, event, optText...) } // getPoolBuildlet is launched as its own goroutine to do a @@ -207,13 +207,13 @@ func (s *Scheduler) hasWaiter(si *SchedItem) bool { return s.waiting[si.HostType][si] } -type schedulerWaitingState struct { +type SchedulerWaitingState struct { Count int Newest time.Duration Oldest time.Duration } -func (st *schedulerWaitingState) add(si *SchedItem) { +func (st *SchedulerWaitingState) add(si *SchedItem) { st.Count++ age := time.Since(si.requestTime).Round(time.Second) if st.Newest == 0 || age < st.Newest { @@ -224,20 +224,20 @@ func (st *schedulerWaitingState) add(si *SchedItem) { } } -type schedulerHostState struct { +type SchedulerHostState struct { HostType string LastProgress time.Duration - Total schedulerWaitingState - Gomote schedulerWaitingState - Try schedulerWaitingState - Regular schedulerWaitingState + Total SchedulerWaitingState + Gomote SchedulerWaitingState + Try SchedulerWaitingState + Regular SchedulerWaitingState } -type schedulerState struct { - HostTypes []schedulerHostState +type SchedulerState struct { + HostTypes []SchedulerHostState } -func (s *Scheduler) state() (st schedulerState) { +func (s *Scheduler) State() (st SchedulerState) { s.mu.Lock() defer s.mu.Unlock() @@ -245,7 +245,7 @@ func (s *Scheduler) state() (st schedulerState) { if len(m) == 0 { continue } - var hst schedulerHostState + var hst SchedulerHostState hst.HostType = hostType for si := range m { hst.Total.add(si) @@ -270,9 +270,9 @@ func (s *Scheduler) state() (st schedulerState) { return st } -// waiterState returns tells waiter how many callers are on the line +// WaiterState returns tells waiter how many callers are on the line // in front of them. -func (s *Scheduler) waiterState(waiter *SchedItem) (ws types.BuildletWaitStatus) { +func (s *Scheduler) WaiterState(waiter *SchedItem) (ws types.BuildletWaitStatus) { s.mu.Lock() defer s.mu.Unlock() diff --git a/cmd/coordinator/sched_test.go b/internal/coordinator/schedule/schedule_test.go similarity index 99% rename from cmd/coordinator/sched_test.go rename to internal/coordinator/schedule/schedule_test.go index 97e44e7842..f40234d1b3 100644 --- a/cmd/coordinator/sched_test.go +++ b/internal/coordinator/schedule/schedule_test.go @@ -6,7 +6,7 @@ // +build go1.16 // +build linux darwin -package main +package schedule import ( "context" @@ -124,7 +124,7 @@ type discardLogger struct{} func (discardLogger) LogEventTime(event string, optText ...string) {} func (discardLogger) CreateSpan(event string, optText ...string) spanlog.Span { - return createSpan(discardLogger{}, event, optText...) + return CreateSpan(discardLogger{}, event, optText...) } // step is a test step for TestScheduler diff --git a/internal/coordinator/schedule/span.go b/internal/coordinator/schedule/span.go new file mode 100644 index 0000000000..c51c2ee537 --- /dev/null +++ b/internal/coordinator/schedule/span.go @@ -0,0 +1,107 @@ +// Copyright 2021 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +//go:build linux || darwin +// +build linux darwin + +package schedule + +import ( + "bytes" + "fmt" + "strings" + "time" + + clog "golang.org/x/build/internal/coordinator/log" + "golang.org/x/build/internal/coordinator/pool" + "golang.org/x/build/types" +) + +type Spanner interface { + SpanRecord(*Span, error) *types.SpanRecord +} + +// Span is an event covering a region of time. +// A Span ultimately ends in an error or success, and will eventually +// be visualized and logged. +type Span struct { + event string // event name like "get_foo" or "write_bar" + optText string // optional details for event + start time.Time + end time.Time + el pool.EventTimeLogger // where we log to at the end; TODO: this will change +} + +// Event is the span's event. +func (s *Span) Event() string { + return s.event +} + +// OptText is the optional text for a span. +func (s *Span) OptText() string { + return s.optText +} + +// Start is the start time for the span.. +func (s *Span) Start() time.Time { + return s.start +} + +// End is the end time for an span. +func (s *Span) End() time.Time { + return s.end +} + +// CreateSpan creates a span with the appropriate metadata. It also starts the span. +func CreateSpan(el pool.EventTimeLogger, event string, optText ...string) *Span { + start := time.Now() + el.LogEventTime(event, optText...) + return &Span{ + el: el, + event: event, + start: start, + optText: strings.Join(optText, " "), + } +} + +// Done ends a span. +// It is legal to call Done multiple times. Only the first call +// logs. +// Done always returns its input argument. +func (s *Span) Done(err error) error { + if !s.end.IsZero() { + return err + } + t1 := time.Now() + s.end = t1 + td := t1.Sub(s.start) + var text bytes.Buffer + fmt.Fprintf(&text, "after %s", friendlyDuration(td)) + if err != nil { + fmt.Fprintf(&text, "; err=%v", err) + } + if s.optText != "" { + fmt.Fprintf(&text, "; %v", s.optText) + } + if st, ok := s.el.(Spanner); ok { + clog.CoordinatorProcess().PutSpanRecord(st.SpanRecord(s, err)) + } + s.el.LogEventTime("finish_"+s.event, text.String()) + return err +} + +// TODO: This is a copy of the function in cmd/coordinator/status.go. This should be removed once status +// is moved into it's own package. +func friendlyDuration(d time.Duration) string { + if d > 10*time.Second { + d2 := ((d + 50*time.Millisecond) / (100 * time.Millisecond)) * (100 * time.Millisecond) + return d2.String() + } + if d > time.Second { + d2 := ((d + 5*time.Millisecond) / (10 * time.Millisecond)) * (10 * time.Millisecond) + return d2.String() + } + d2 := ((d + 50*time.Microsecond) / (100 * time.Microsecond)) * (100 * time.Microsecond) + return d2.String() +} diff --git a/internal/coordinator/schedule/span_test.go b/internal/coordinator/schedule/span_test.go new file mode 100644 index 0000000000..25fe44396b --- /dev/null +++ b/internal/coordinator/schedule/span_test.go @@ -0,0 +1,37 @@ +// Copyright 2021 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +//go:build linux || darwin +// +build linux darwin + +package schedule + +import ( + "testing" +) + +type fakeEventTimeLogger struct { + event string + optText []string +} + +func (l *fakeEventTimeLogger) LogEventTime(event string, optText ...string) { + l.event = event + l.optText = optText +} + +func TestSpan(t *testing.T) { + l := &fakeEventTimeLogger{} + event := "log_event" + s := CreateSpan(l, event, "a", "b", "c") + if err := s.Done(nil); err != nil { + t.Fatalf("Span.Done() = %s; want no error", err) + } + if l.event != "finish_"+event { + t.Errorf("EventTimeLogger.event = %q, want %q", l.event, "finish_"+event) + } + if len(l.optText) == 0 { + t.Errorf("EventTimeLogger.optText = %+v; want entries", l.optText) + } +}