cmd/coordinator: create separate spanlog package
This moves main.spanLogger and main.eventSpan to spanlog.Logger and
spanlog.Span. This change is necessary to start pulling build and
benchmark code out of coordinator. The interfaces cannot simply be
copied because Logger contains a function whose return type is
Span, so the interface must be defined in exactly one place.
Updates golang/go#19871
Change-Id: I0a48192e6a5c8f5d0445f4f3d3cce8d91c90f8d3
Reviewed-on: https://go-review.googlesource.com/44174
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
diff --git a/cmd/coordinator/benchmarks.go b/cmd/coordinator/benchmarks.go
index a5f2044..5b800ce 100644
--- a/cmd/coordinator/benchmarks.go
+++ b/cmd/coordinator/benchmarks.go
@@ -14,6 +14,7 @@
"time"
"golang.org/x/build/buildlet"
+ "golang.org/x/build/cmd/coordinator/spanlog"
"golang.org/x/build/dashboard"
)
@@ -73,7 +74,7 @@
}
// buildXBenchmark builds a benchmark from x/benchmarks.
-func buildXBenchmark(sl spanLogger, conf dashboard.BuildConfig, bc *buildlet.Client, goroot string, w io.Writer, rev, pkg, name string) (remoteErr, err error) {
+func buildXBenchmark(sl spanlog.Logger, conf dashboard.BuildConfig, bc *buildlet.Client, goroot string, w io.Writer, rev, pkg, name string) (remoteErr, err error) {
workDir, err := bc.WorkDir()
if err != nil {
return nil, err
@@ -93,7 +94,7 @@
})
}
-func enumerateBenchmarks(sl spanLogger, conf dashboard.BuildConfig, bc *buildlet.Client, goroot string, trySet *trySet) ([]*benchmarkItem, error) {
+func enumerateBenchmarks(sl spanlog.Logger, conf dashboard.BuildConfig, bc *buildlet.Client, goroot string, trySet *trySet) ([]*benchmarkItem, error) {
workDir, err := bc.WorkDir()
if err != nil {
err = fmt.Errorf("buildBench, WorkDir: %v", err)
@@ -239,7 +240,7 @@
return
}
-func (st *buildStatus) buildRev(sl spanLogger, conf dashboard.BuildConfig, bc *buildlet.Client, w io.Writer, goroot string, br builderRev) error {
+func (st *buildStatus) buildRev(sl spanlog.Logger, conf dashboard.BuildConfig, bc *buildlet.Client, w io.Writer, goroot string, br builderRev) error {
if br.snapshotExists() {
return bc.PutTarFromURL(br.snapshotURL(), "go-parent")
}
@@ -270,18 +271,18 @@
if err != nil {
return nil, err
}
- sp := st.createSpan("bench_build_parent", bc.Name())
+ sp := st.CreateSpan("bench_build_parent", bc.Name())
err = st.buildRev(st, st.conf, bc, w, "go-parent", pbr)
- sp.done(err)
+ sp.Done(err)
if err != nil {
return nil, err
}
}
// Build benchmark.
for _, goroot := range []string{"go", "go-parent"} {
- sp := st.createSpan("bench_build", fmt.Sprintf("%s/%s: %s", goroot, b.binary, bc.Name()))
+ sp := st.CreateSpan("bench_build", fmt.Sprintf("%s/%s: %s", goroot, b.binary, bc.Name()))
remoteErr, err = b.build(bc, goroot, w)
- sp.done(err)
+ sp.Done(err)
if remoteErr != nil || err != nil {
return remoteErr, err
}
@@ -305,9 +306,9 @@
for _, c := range commits {
fmt.Fprintf(&c.out, "iteration: %d\nstart-time: %s\n", i, time.Now().UTC().Format(time.RFC3339))
p := path.Join(c.path, b.binary)
- sp := st.createSpan("run_one_bench", p)
+ sp := st.CreateSpan("run_one_bench", p)
remoteErr, err = runOneBenchBinary(st.conf, bc, &c.out, c.path, p, b.args)
- sp.done(err)
+ sp.Done(err)
if err != nil || remoteErr != nil {
c.out.WriteTo(w)
return
diff --git a/cmd/coordinator/coordinator.go b/cmd/coordinator/coordinator.go
index 2fdb3a1..7a91651 100644
--- a/cmd/coordinator/coordinator.go
+++ b/cmd/coordinator/coordinator.go
@@ -51,6 +51,7 @@
"golang.org/x/build/autocertcache"
"golang.org/x/build/buildenv"
"golang.org/x/build/buildlet"
+ "golang.org/x/build/cmd/coordinator/spanlog"
"golang.org/x/build/dashboard"
"golang.org/x/build/gerrit"
"golang.org/x/build/internal/lru"
@@ -228,11 +229,11 @@
type loggerFunc func(event string, optText ...string)
-func (fn loggerFunc) logEventTime(event string, optText ...string) {
+func (fn loggerFunc) LogEventTime(event string, optText ...string) {
fn(event, optText...)
}
-func (fn loggerFunc) createSpan(event string, optText ...string) eventSpan {
+func (fn loggerFunc) CreateSpan(event string, optText ...string) spanlog.Span {
return createSpan(fn, event, optText...)
}
@@ -1241,21 +1242,7 @@
}
type eventTimeLogger interface {
- logEventTime(event string, optText ...string)
-}
-
-// spanLogger is something that has the createSpan method, which
-// creates a event spanning some duration which will eventually be
-// logged and visualized.
-type spanLogger interface {
- // optText is 0 or 1 strings.
- createSpan(event string, optText ...string) eventSpan
-}
-
-type eventSpan interface {
- // done marks a span as done.
- // The err is returned unmodified for convenience at callsites.
- done(err error) error
+ LogEventTime(event string, optText ...string)
}
// logger is the logging interface used within the coordinator.
@@ -1264,7 +1251,7 @@
// a final success status).
type logger interface {
eventTimeLogger // point in time
- spanLogger // action spanning time
+ spanlog.Logger // action spanning time
}
// buildletTimeoutOpt is a context.Value key for BuildletPool.GetBuildlet.
@@ -1300,20 +1287,20 @@
for i := 0; i < n; i++ {
go func(i int) {
defer wg.Done()
- sp := lg.createSpan("get_helper", fmt.Sprintf("helper %d/%d", i+1, n))
+ sp := lg.CreateSpan("get_helper", fmt.Sprintf("helper %d/%d", i+1, n))
bc, err := pool.GetBuildlet(ctx, hostType, lg)
- sp.done(err)
+ sp.Done(err)
if err != nil {
if err != context.Canceled {
log.Printf("failed to get a %s buildlet: %v", hostType, err)
}
return
}
- lg.logEventTime("empty_helper_ready", bc.Name())
+ lg.LogEventTime("empty_helper_ready", bc.Name())
select {
case ch <- bc:
case <-ctx.Done():
- lg.logEventTime("helper_killed_before_use", bc.Name())
+ lg.LogEventTime("helper_killed_before_use", bc.Name())
bc.Close()
return
}
@@ -1442,7 +1429,7 @@
}
time.AfterFunc(st.expectedMakeBashDuration()-st.expectedBuildletStartDuration(),
func() {
- st.logEventTime("starting_helpers")
+ st.LogEventTime("starting_helpers")
st.getHelpers() // and ignore the result.
})
}
@@ -1501,8 +1488,8 @@
}
func (st *buildStatus) checkDep(ctx context.Context, dep string) (have bool, err error) {
- span := st.createSpan("ask_maintner_has_ancestor")
- defer func() { span.done(err) }()
+ span := st.CreateSpan("ask_maintner_has_ancestor")
+ defer func() { span.Done(err) }()
tries := 0
for {
tries++
@@ -1512,7 +1499,7 @@
})
if err != nil {
if tries == 3 {
- span.done(err)
+ span.Done(err)
return false, err
}
time.Sleep(1 * time.Second)
@@ -1543,7 +1530,7 @@
return err
}
if !has {
- st.logEventTime(eventSkipBuildMissingDep)
+ st.LogEventTime(eventSkipBuildMissingDep)
fmt.Fprintf(st, "skipping build; commit %s lacks ancestor %s\n", st.rev, dep)
return errSkipBuildDueToDeps
}
@@ -1553,13 +1540,13 @@
putBuildRecord(st.buildRecord())
- sp := st.createSpan("checking_for_snapshot")
+ sp := st.CreateSpan("checking_for_snapshot")
if inStaging {
err := storageClient.Bucket(buildEnv.SnapBucket).Object(st.snapshotObjectName()).Delete(context.Background())
- st.logEventTime("deleted_snapshot", fmt.Sprint(err))
+ st.LogEventTime("deleted_snapshot", fmt.Sprint(err))
}
snapshotExists := st.useSnapshot()
- sp.done(nil)
+ sp.Done(nil)
if config := st.getCrossCompileConfig(); !snapshotExists && config != nil {
if err := st.crossCompileMakeAndSnapshot(config); err != nil {
@@ -1568,10 +1555,10 @@
st.forceSnapshotUsage()
}
- sp = st.createSpan("get_buildlet")
+ sp = st.CreateSpan("get_buildlet")
pool := st.buildletPool()
bc, err := pool.GetBuildlet(st.ctx, st.conf.HostType, st)
- sp.done(err)
+ sp.Done(err)
if err != nil {
return fmt.Errorf("failed to get a buildlet: %v", err)
}
@@ -1581,14 +1568,14 @@
st.bc = bc
st.mu.Unlock()
- st.logEventTime("using_buildlet", bc.IPPort())
+ st.LogEventTime("using_buildlet", bc.IPPort())
if st.useSnapshot() {
- sp := st.createSpan("write_snapshot_tar")
+ sp := st.CreateSpan("write_snapshot_tar")
if err := bc.PutTarFromURL(st.snapshotURL(), "go"); err != nil {
- return sp.done(fmt.Errorf("failed to put snapshot to buildlet: %v", err))
+ return sp.Done(fmt.Errorf("failed to put snapshot to buildlet: %v", err))
}
- sp.done(nil)
+ sp.Done(nil)
} else {
// Write the Go source and bootstrap tool chain in parallel.
var grp syncutil.Group
@@ -1606,7 +1593,7 @@
}
fmt.Fprint(st, "\n\n")
- makeTest := st.createSpan("make_and_test") // warning: magic event named used by handleLogs
+ makeTest := st.CreateSpan("make_and_test") // warning: magic event named used by handleLogs
var remoteErr error
if st.conf.SplitMakeRun() {
@@ -1614,7 +1601,7 @@
} else {
remoteErr, err = st.runAllLegacy()
}
- makeTest.done(err)
+ makeTest.Done(err)
// bc (aka st.bc) may be invalid past this point, so let's
// close it to make sure we we don't accidentally use it.
@@ -1631,10 +1618,10 @@
// "done" event. (which the try coordinator looks for)
return err
}
- st.logEventTime(eventDone, doneMsg)
+ st.LogEventTime(eventDone, doneMsg)
if devPause {
- st.logEventTime("DEV_MAIN_SLEEP")
+ st.LogEventTime("DEV_MAIN_SLEEP")
time.Sleep(5 * time.Minute)
}
@@ -1800,9 +1787,9 @@
// though, or slower once we ship everything around.
ctx, cancel := context.WithCancel(st.ctx)
defer cancel()
- sp := st.createSpan("get_buildlet_cross")
+ sp := st.CreateSpan("get_buildlet_cross")
kubeBC, err := kubePool.GetBuildlet(ctx, config.Buildlet, st)
- sp.done(err)
+ sp.Done(err)
if err != nil {
return err
}
@@ -1812,8 +1799,8 @@
return err
}
- makeSpan := st.createSpan("make_cross_compile_kube")
- defer func() { makeSpan.done(err) }()
+ makeSpan := st.CreateSpan("make_cross_compile_kube")
+ defer func() { makeSpan.Done(err) }()
goos, goarch := st.conf.GOOS(), st.conf.GOARCH()
@@ -1845,7 +1832,7 @@
if remoteErr != nil {
// Add the "done" event if make.bash fails, otherwise
// try builders will loop forever:
- st.logEventTime(eventDone, fmt.Sprintf("make.bash failed: %v", remoteErr))
+ st.LogEventTime(eventDone, fmt.Sprintf("make.bash failed: %v", remoteErr))
return fmt.Errorf("remote error: %v", remoteErr)
}
@@ -1862,7 +1849,7 @@
// remoteErr and err are as described at the top of this file.
func (st *buildStatus) runMake(bc *buildlet.Client, goroot string, w io.Writer) (remoteErr, err error) {
// Build the source code.
- makeSpan := st.createSpan("make", st.conf.MakeScript())
+ makeSpan := st.CreateSpan("make", st.conf.MakeScript())
remoteErr, err = bc.Exec(path.Join(goroot, st.conf.MakeScript()), buildlet.ExecOpts{
Output: w,
ExtraEnv: append(st.conf.Env(), "GOBIN="),
@@ -1870,18 +1857,18 @@
Args: st.conf.MakeScriptArgs(),
})
if err != nil {
- makeSpan.done(err)
+ makeSpan.Done(err)
return nil, err
}
if remoteErr != nil {
- makeSpan.done(remoteErr)
+ makeSpan.Done(remoteErr)
return fmt.Errorf("make script failed: %v", remoteErr), nil
}
- makeSpan.done(nil)
+ makeSpan.Done(nil)
// Need to run "go install -race std" before the snapshot + tests.
if pkgs := st.conf.GoInstallRacePackages(); len(pkgs) > 0 {
- sp := st.createSpan("install_race_std")
+ sp := st.CreateSpan("install_race_std")
remoteErr, err = bc.Exec(path.Join(goroot, "bin/go"), buildlet.ExecOpts{
Output: w,
ExtraEnv: append(st.conf.Env(), "GOBIN="),
@@ -1889,14 +1876,14 @@
Args: append([]string{"install", "-race"}, pkgs...),
})
if err != nil {
- sp.done(err)
+ sp.Done(err)
return nil, err
}
if remoteErr != nil {
- sp.done(err)
+ sp.Done(err)
return fmt.Errorf("go install -race std failed: %v", remoteErr), nil
}
- sp.done(nil)
+ sp.Done(nil)
}
if st.name == "linux-amd64-racecompile" {
@@ -1913,7 +1900,7 @@
// caller, runMake, per builder config).
// The idea is that this might find data races in cmd/compile.
func (st *buildStatus) runConcurrentGoBuildStdCmd(bc *buildlet.Client) (remoteErr, err error) {
- span := st.createSpan("go_build_c128_std_cmd")
+ span := st.CreateSpan("go_build_c128_std_cmd")
remoteErr, err = bc.Exec("go/bin/go", buildlet.ExecOpts{
Output: st,
ExtraEnv: append(st.conf.Env(), "GOBIN="),
@@ -1921,14 +1908,14 @@
Args: []string{"build", "-a", "-gcflags=-c=8", "std", "cmd"},
})
if err != nil {
- span.done(err)
+ span.Done(err)
return nil, err
}
if remoteErr != nil {
- span.done(remoteErr)
+ span.Done(remoteErr)
return fmt.Errorf("go build failed: %v", remoteErr), nil
}
- span.done(nil)
+ span.Done(nil)
return nil, nil
}
@@ -1939,7 +1926,7 @@
// can split make & run (and then delete the SplitMakeRun method)
func (st *buildStatus) runAllLegacy() (remoteErr, err error) {
allScript := st.conf.AllScript()
- sp := st.createSpan("legacy_all_path", allScript)
+ sp := st.CreateSpan("legacy_all_path", allScript)
remoteErr, err = st.bc.Exec(path.Join("go", allScript), buildlet.ExecOpts{
Output: st,
ExtraEnv: st.conf.Env(),
@@ -1947,14 +1934,14 @@
Args: st.conf.AllScriptArgs(),
})
if err != nil {
- sp.done(err)
+ sp.Done(err)
return nil, err
}
if remoteErr != nil {
- sp.done(err)
+ sp.Done(err)
return fmt.Errorf("all script failed: %v", remoteErr), nil
}
- sp.done(nil)
+ sp.Done(nil)
return nil, nil
}
@@ -1999,20 +1986,20 @@
func (st *buildStatus) writeGoSourceTo(bc *buildlet.Client) error {
// Write the VERSION file.
- sp := st.createSpan("write_version_tar")
+ sp := st.CreateSpan("write_version_tar")
if err := bc.PutTar(versionTgz(st.rev), "go"); err != nil {
- return sp.done(fmt.Errorf("writing VERSION tgz: %v", err))
+ return sp.Done(fmt.Errorf("writing VERSION tgz: %v", err))
}
srcTar, err := getSourceTgz(st, "go", st.rev)
if err != nil {
return err
}
- sp = st.createSpan("write_go_src_tar")
+ sp = st.CreateSpan("write_go_src_tar")
if err := bc.PutTar(srcTar, "go"); err != nil {
- return sp.done(fmt.Errorf("writing tarball from Gerrit: %v", err))
+ return sp.Done(fmt.Errorf("writing tarball from Gerrit: %v", err))
}
- return sp.done(nil)
+ return sp.Done(nil)
}
func (st *buildStatus) writeBootstrapToolchain() error {
@@ -2021,13 +2008,13 @@
return nil
}
const bootstrapDir = "go1.4" // might be newer; name is the default
- sp := st.createSpan("write_go_bootstrap_tar")
- return sp.done(st.bc.PutTarFromURL(u, bootstrapDir))
+ sp := st.CreateSpan("write_go_bootstrap_tar")
+ return sp.Done(st.bc.PutTarFromURL(u, bootstrapDir))
}
func (st *buildStatus) cleanForSnapshot(bc *buildlet.Client) error {
- sp := st.createSpan("clean_for_snapshot")
- return sp.done(bc.RemoveAll(
+ sp := st.CreateSpan("clean_for_snapshot")
+ return sp.Done(bc.RemoveAll(
"go/doc/gopher",
"go/pkg/bootstrap",
))
@@ -2046,8 +2033,8 @@
}
func (st *buildStatus) writeSnapshot(bc *buildlet.Client) (err error) {
- sp := st.createSpan("write_snapshot_to_gcs")
- defer func() { sp.done(err) }()
+ sp := st.CreateSpan("write_snapshot_to_gcs")
+ defer func() { sp.Done(err) }()
// This should happen in 15 seconds or so, but I saw timeouts
// a couple times at 1 minute. Some buildlets might be far
// away on the network, so be more lenient. The timeout mostly
@@ -2055,9 +2042,9 @@
ctx, cancel := context.WithTimeout(context.Background(), 5*time.Minute)
defer cancel()
- tsp := st.createSpan("fetch_snapshot_reader_from_buildlet")
+ tsp := st.CreateSpan("fetch_snapshot_reader_from_buildlet")
tgz, err := bc.GetTar(ctx, "go")
- tsp.done(err)
+ tsp.Done(err)
if err != nil {
return err
}
@@ -2094,7 +2081,7 @@
remoteErr, err = st.bc.Exec(path.Join("go", "bin", "go"), buildlet.ExecOpts{
Output: &buf,
ExtraEnv: append(st.conf.Env(), "GOROOT="+goroot),
- OnStartExec: func() { st.logEventTime("discovering_tests") },
+ OnStartExec: func() { st.LogEventTime("discovering_tests") },
Path: []string{"$WORKDIR/go/bin", "$PATH"},
Args: args,
})
@@ -2538,7 +2525,7 @@
return minGoTestSpeed * 2
}
-func fetchSubrepo(sl spanLogger, bc *buildlet.Client, repo, rev string) error {
+func fetchSubrepo(sl spanlog.Logger, bc *buildlet.Client, repo, rev string) error {
tgz, err := getSourceTgz(sl, repo, rev)
if err != nil {
return err
@@ -2547,7 +2534,7 @@
}
func (st *buildStatus) runSubrepoTests() (remoteErr, err error) {
- st.logEventTime("fetching_subrepo", st.subName)
+ st.LogEventTime("fetching_subrepo", st.subName)
workDir, err := st.bc.WorkDir()
if err != nil {
@@ -2629,8 +2616,8 @@
}
}
- sp := st.createSpan("running_subrepo_tests", st.subName)
- defer func() { sp.done(err) }()
+ sp := st.CreateSpan("running_subrepo_tests", st.subName)
+ defer func() { sp.Done(err) }()
return st.bc.Exec(path.Join("go", "bin", "go"), buildlet.ExecOpts{
Output: st,
// TODO(adg): remove vendor experiment variable after Go 1.6
@@ -2659,15 +2646,15 @@
}
var benches []*benchmarkItem
if st.shouldBench() {
- sp := st.createSpan("enumerate_benchmarks")
+ sp := st.CreateSpan("enumerate_benchmarks")
b, err := enumerateBenchmarks(st, st.conf, st.bc, "go", st.trySet)
- sp.done(err)
+ sp.Done(err)
if err == nil {
benches = b
}
}
set := st.newTestSet(testNames, benches)
- st.logEventTime("starting_tests", fmt.Sprintf("%d tests", len(set.items)))
+ st.LogEventTime("starting_tests", fmt.Sprintf("%d tests", len(set.items)))
startTime := time.Now()
workDir, err := st.bc.WorkDir()
@@ -2698,7 +2685,7 @@
}
st.runTestsOnBuildlet(st.bc, tis, mainBuildletGoroot)
}
- st.logEventTime("main_buildlet_broken", st.bc.Name())
+ st.LogEventTime("main_buildlet_broken", st.bc.Name())
}()
go func() {
defer buildletActivity.Done() // for the per-goroutine Add(2) above
@@ -2706,13 +2693,13 @@
buildletActivity.Add(1)
go func(bc *buildlet.Client) {
defer buildletActivity.Done() // for the per-helper Add(1) above
- defer st.logEventTime("closed_helper", bc.Name())
+ defer st.LogEventTime("closed_helper", bc.Name())
defer bc.Close()
if devPause {
defer time.Sleep(5 * time.Minute)
- defer st.logEventTime("DEV_HELPER_SLEEP", bc.Name())
+ defer st.LogEventTime("DEV_HELPER_SLEEP", bc.Name())
}
- st.logEventTime("got_empty_test_helper", bc.String())
+ st.LogEventTime("got_empty_test_helper", bc.String())
if err := bc.PutTarFromURL(st.snapshotURL(), "go"); err != nil {
log.Printf("failed to extract snapshot for helper %s: %v", bc.Name(), err)
return
@@ -2722,17 +2709,17 @@
log.Printf("error discovering workdir for helper %s: %v", bc.Name(), err)
return
}
- st.logEventTime("test_helper_set_up", bc.Name())
+ st.LogEventTime("test_helper_set_up", bc.Name())
goroot := st.conf.FilePathJoin(workDir, "go")
for !bc.IsBroken() {
tis, ok := set.testsToRunBiggestFirst()
if !ok {
- st.logEventTime("no_new_tests_remain", bc.Name())
+ st.LogEventTime("no_new_tests_remain", bc.Name())
return
}
st.runTestsOnBuildlet(bc, tis, goroot)
}
- st.logEventTime("test_helper_is_broken", bc.Name())
+ st.LogEventTime("test_helper_is_broken", bc.Name())
}(helper)
}
}()
@@ -2758,7 +2745,7 @@
timer.Stop()
break AwaitDone
case <-timer.C:
- st.logEventTime("still_waiting_on_test", ti.name)
+ st.LogEventTime("still_waiting_on_test", ti.name)
case <-buildletsGone:
set.cancelAll()
return nil, fmt.Errorf("dist test failed: all buildlets had network errors or timeouts, yet tests remain")
@@ -2801,7 +2788,7 @@
} else {
msg = fmt.Sprintf("took %v", elapsed)
}
- st.logEventTime("tests_complete", msg)
+ st.LogEventTime("tests_complete", msg)
fmt.Fprintf(st, "\nAll tests passed.\n")
for _, f := range benchFiles {
if f.out.Len() > 0 {
@@ -2809,8 +2796,8 @@
}
}
if st.hasBenchResults {
- sp := st.createSpan("upload_bench_results")
- sp.done(st.uploadBenchResults(st.ctx, benchFiles))
+ sp := st.CreateSpan("upload_bench_results")
+ sp.Done(st.uploadBenchResults(st.ctx, benchFiles))
}
return nil, nil
}
@@ -2837,7 +2824,7 @@
if err != nil {
return err
}
- st.logEventTime("bench_upload", status.UploadID)
+ st.LogEventTime("bench_upload", status.UploadID)
return nil
}
@@ -2919,7 +2906,7 @@
spanName = "run_tests_multi"
detail = fmt.Sprintf("%s: %v", bc.Name(), names)
}
- sp := st.createSpan(spanName, detail)
+ sp := st.CreateSpan(spanName, detail)
args := []string{"tool", "dist", "test", "--no-rebuild", "--banner=" + banner}
if st.conf.IsRace() {
@@ -2952,7 +2939,7 @@
})
}
execDuration := time.Since(t0)
- sp.done(err)
+ sp.Done(err)
if err != nil {
bc.MarkBroken() // prevents reuse
for _, ti := range tis {
@@ -3215,7 +3202,7 @@
if len(optText) > 0 {
opt = optText[0]
}
- el.logEventTime(event, opt)
+ el.LogEventTime(event, opt)
return &span{
el: el,
event: event,
@@ -3224,11 +3211,11 @@
}
}
-// done ends a span.
-// It is legal to call done multiple times. Only the first call
+// 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 {
+// Done always returns its input argument.
+func (s *span) Done(err error) error {
if !s.end.IsZero() {
return err
}
@@ -3246,15 +3233,15 @@
if st, ok := s.el.(*buildStatus); ok {
putSpanRecord(st.spanRecord(s, err))
}
- s.el.logEventTime("finish_"+s.event, text.String())
+ s.el.LogEventTime("finish_"+s.event, text.String())
return err
}
-func (st *buildStatus) createSpan(event string, optText ...string) eventSpan {
+func (st *buildStatus) CreateSpan(event string, optText ...string) spanlog.Span {
return createSpan(st, event, optText...)
}
-func (st *buildStatus) logEventTime(event string, optText ...string) {
+func (st *buildStatus) LogEventTime(event string, optText ...string) {
if len(optText) > 1 {
panic("usage")
}
@@ -3427,9 +3414,9 @@
// repo is go.googlesource.com repo ("go", "net", etc)
// rev is git revision.
-func getSourceTgz(sl spanLogger, repo, rev string) (tgz io.Reader, err error) {
- sp := sl.createSpan("get_source")
- defer func() { sp.done(err) }()
+func getSourceTgz(sl spanlog.Logger, repo, rev string) (tgz io.Reader, err error) {
+ sp := sl.CreateSpan("get_source")
+ defer func() { sp.Done(err) }()
key := fmt.Sprintf("%v-%v", repo, rev)
vi, err, _ := sourceGroup.Do(key, func() (interface{}, error) {
@@ -3438,21 +3425,21 @@
}
if useGitMirror() {
- sp := sl.createSpan("get_source_from_gitmirror")
+ sp := sl.CreateSpan("get_source_from_gitmirror")
tgzBytes, err := getSourceTgzFromGitMirror(repo, rev)
if err == nil {
sourceCache.Add(key, tgzBytes)
- sp.done(nil)
+ sp.Done(nil)
return tgzBytes, nil
}
log.Printf("Error fetching source %s/%s from watcher (after %v uptime): %v",
repo, rev, time.Since(processStartTime), err)
- sp.done(errors.New("timeout"))
+ sp.Done(errors.New("timeout"))
}
- sp := sl.createSpan("get_source_from_gerrit", fmt.Sprintf("%v from gerrit", key))
+ sp := sl.CreateSpan("get_source_from_gerrit", fmt.Sprintf("%v from gerrit", key))
tgzBytes, err := getSourceTgzFromGerrit(repo, rev)
- sp.done(err)
+ sp.Done(err)
if err == nil {
sourceCache.Add(key, tgzBytes)
}
diff --git a/cmd/coordinator/gce.go b/cmd/coordinator/gce.go
index 2558b9b..587496c 100644
--- a/cmd/coordinator/gce.go
+++ b/cmd/coordinator/gce.go
@@ -29,6 +29,7 @@
"cloud.google.com/go/storage"
"golang.org/x/build/buildenv"
"golang.org/x/build/buildlet"
+ "golang.org/x/build/cmd/coordinator/spanlog"
"golang.org/x/build/dashboard"
"golang.org/x/build/gerrit"
"golang.org/x/build/internal/lru"
@@ -259,9 +260,9 @@
if !ok {
return nil, fmt.Errorf("gcepool: unknown host type %q", hostType)
}
- qsp := lg.createSpan("awaiting_gce_quota")
+ qsp := lg.CreateSpan("awaiting_gce_quota")
err = p.awaitVMCountQuota(ctx, hconf.GCENumCPU())
- qsp.done(err)
+ qsp.Done(err)
if err != nil {
return nil, err
}
@@ -274,13 +275,13 @@
instName := "buildlet-" + strings.TrimPrefix(hostType, "host-") + "-rn" + randHex(7)
p.setInstanceUsed(instName, true)
- gceBuildletSpan := lg.createSpan("create_gce_buildlet", instName)
- defer func() { gceBuildletSpan.done(err) }()
+ gceBuildletSpan := lg.CreateSpan("create_gce_buildlet", instName)
+ defer func() { gceBuildletSpan.Done(err) }()
var (
needDelete bool
- createSpan eventSpan = lg.createSpan("create_gce_instance", instName)
- waitBuildlet eventSpan // made after create is done
+ createSpan spanlog.Span = lg.CreateSpan("create_gce_instance", instName)
+ waitBuildlet spanlog.Span // made after create is done
curSpan = createSpan // either instSpan or waitBuildlet
)
@@ -294,7 +295,7 @@
log.Printf("GCE VM %q now booting", instName)
},
FallbackToFullPrice: func() string {
- lg.logEventTime("gce_fallback_to_full_price", "for "+instName)
+ lg.LogEventTime("gce_fallback_to_full_price", "for "+instName)
p.setInstanceUsed(instName, false)
newName := instName + "-f"
log.Printf("Gave up on preemptible %q; now booting %q", instName, newName)
@@ -305,16 +306,16 @@
OnInstanceCreated: func() {
needDelete = true
- createSpan.done(nil)
- waitBuildlet = lg.createSpan("wait_buildlet_start", instName)
+ createSpan.Done(nil)
+ waitBuildlet = lg.CreateSpan("wait_buildlet_start", instName)
curSpan = waitBuildlet
},
OnGotInstanceInfo: func() {
- lg.logEventTime("got_instance_info", "waiting_for_buildlet...")
+ lg.LogEventTime("got_instance_info", "waiting_for_buildlet...")
},
})
if err != nil {
- curSpan.done(err)
+ curSpan.Done(err)
log.Printf("Failed to create VM for %s: %v", hostType, err)
if needDelete {
deleteVM(buildEnv.Zone, instName)
@@ -323,7 +324,7 @@
p.setInstanceUsed(instName, false)
return nil, err
}
- waitBuildlet.done(nil)
+ waitBuildlet.Done(nil)
bc.SetDescription("GCE VM: " + instName)
bc.SetOnHeartbeatFailure(func() {
p.putBuildlet(bc, hostType, instName)
diff --git a/cmd/coordinator/kube.go b/cmd/coordinator/kube.go
index 67973c5..13d8f38 100644
--- a/cmd/coordinator/kube.go
+++ b/cmd/coordinator/kube.go
@@ -215,7 +215,7 @@
// the context timeout based on that
var needDelete bool
- lg.logEventTime("creating_kube_pod", podName)
+ lg.LogEventTime("creating_kube_pod", podName)
log.Printf("Creating Kubernetes pod %q for %s", podName, hostType)
bc, err := buildlet.StartPod(ctx, buildletsKubeClient, podName, hostType, buildlet.PodOpts{
@@ -224,21 +224,21 @@
Description: fmt.Sprintf("Go Builder for %s", hostType),
DeleteIn: deleteIn,
OnPodCreating: func() {
- lg.logEventTime("pod_creating")
+ lg.LogEventTime("pod_creating")
p.setPodUsed(podName, true)
p.updatePodHistory(podName, podHistory{requestedAt: time.Now()})
needDelete = true
},
OnPodCreated: func() {
- lg.logEventTime("pod_created")
+ lg.LogEventTime("pod_created")
p.updatePodHistory(podName, podHistory{readyAt: time.Now()})
},
OnGotPodInfo: func() {
- lg.logEventTime("got_pod_info", "waiting_for_buildlet...")
+ lg.LogEventTime("got_pod_info", "waiting_for_buildlet...")
},
})
if err != nil {
- lg.logEventTime("kube_buildlet_create_failure", fmt.Sprintf("%s: %v", podName, err))
+ lg.LogEventTime("kube_buildlet_create_failure", fmt.Sprintf("%s: %v", podName, err))
if needDelete {
log.Printf("Deleting failed pod %q", podName)
diff --git a/cmd/coordinator/reverse.go b/cmd/coordinator/reverse.go
index 1987149..9b49bb7 100644
--- a/cmd/coordinator/reverse.go
+++ b/cmd/coordinator/reverse.go
@@ -263,7 +263,7 @@
defer p.updateWaiterCounter(hostType, -1)
seenErrInUse := false
isHighPriority, _ := ctx.Value(highPriorityOpt{}).(bool)
- sp := lg.createSpan("wait_static_builder", hostType)
+ sp := lg.CreateSpan("wait_static_builder", hostType)
for {
bc, busy := p.tryToGrab(hostType)
if bc != nil {
@@ -271,12 +271,12 @@
case highPriChan(hostType) <- bc:
// Somebody else was more important.
default:
- sp.done(nil)
+ sp.Done(nil)
return p.cleanedBuildlet(bc, lg)
}
}
if busy > 0 && !seenErrInUse {
- lg.logEventTime("waiting_machine_in_use")
+ lg.LogEventTime("waiting_machine_in_use")
seenErrInUse = true
}
var highPri chan *buildlet.Client
@@ -285,9 +285,9 @@
}
select {
case <-ctx.Done():
- return nil, sp.done(ctx.Err())
+ return nil, sp.Done(ctx.Err())
case bc := <-highPri:
- sp.done(nil)
+ sp.Done(nil)
return p.cleanedBuildlet(bc, lg)
case <-time.After(10 * time.Second):
@@ -302,9 +302,9 @@
func (p *reverseBuildletPool) cleanedBuildlet(b *buildlet.Client, lg logger) (*buildlet.Client, error) {
// Clean up any files from previous builds.
- sp := lg.createSpan("clean_buildlet", b.String())
+ sp := lg.CreateSpan("clean_buildlet", b.String())
err := b.RemoveAll(".")
- sp.done(err)
+ sp.Done(err)
if err != nil {
b.Close()
return nil, err
diff --git a/cmd/coordinator/spanlog/spanlog.go b/cmd/coordinator/spanlog/spanlog.go
new file mode 100644
index 0000000..bcf7b3a
--- /dev/null
+++ b/cmd/coordinator/spanlog/spanlog.go
@@ -0,0 +1,31 @@
+// Copyright 2017 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.
+
+// Package spanlog provides span and event logger interfaces that are used
+// by the build coordinator infrastructure.
+package spanlog
+
+// SpanLogger is something that has the CreateSpan method, which
+// creates a event spanning some duration which will eventually be
+// logged and visualized.
+type Logger interface {
+ // CreateSpan logs the start of an event.
+ // optText is 0 or 1 strings.
+ CreateSpan(event string, optText ...string) Span
+}
+
+// Span is a handle that can eventually be closed.
+// Typical usage:
+//
+// sp := sl.CreateSpan("slow_operation")
+// result, err := doSlowOperation()
+// sp.Done(err)
+// // do something with result, err
+type Span interface {
+ // Done marks a span as done.
+ // The err is returned unmodified for convenience at callsites.
+ Done(err error) error
+}
+
+// TODO(quentin): Move loggerFunc and createSpan from coordinator.go to here.
