cmd/coordinator: clean up HTML status, add scheduler status

The HTML status for the coordinator was way too long. For pending
builds, only show a single line, and render their state as
"waiting_for_machine" rather than "running". And for active builds,
only show the last few lines of status on the home page. People can
click for details.

Then add a scheduler status section too.

I'm also stashing away a build's SchedItem for now (with a little
refactoring to break up a long method), so a future CL can tell people
where a build is in line to get a buildlet.

Updates golang/go#19178

Change-Id: I2f37982ea3c7ee4a6581464117ae533499eba6a4
Reviewed-on: https://go-review.googlesource.com/c/build/+/207179
Reviewed-by: Bryan C. Mills <bcmills@google.com>

Author: bradfitz

cmd/coordinator/coordinator.go

@@ -715,7 +715,7 @@ func serveTryStatusHTML(w http.ResponseWriter, ts *trySet, tss trySetState) {
 		fmt.Fprintf(buf, "<tr valign=top><td align=left>%s</td><td align=center>%s</td><td><pre>%s</pre></td></tr>\n",
 			html.EscapeString(bs.NameAndBranch()),
 			status,
-			bs.HTMLStatusLine())
+			bs.HTMLStatusTruncated())
 	}
 	fmt.Fprintf(buf, "</table>")
 	w.Write(buf.Bytes())
@@ -809,7 +809,7 @@ func writeStatusHeader(w http.ResponseWriter, st *buildStatus) {
 	}
 	if len(st.events) > 0 {
 		io.WriteString(w, "\nEvents:\n")
-		st.writeEventsLocked(w, false)
+		st.writeEventsLocked(w, false, 0)
 	}
 	io.WriteString(w, "\nBuild log:\n")
 	workaroundFlush(w)
@@ -1818,6 +1818,34 @@ 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{
+		HostType:   st.conf.HostType,
+		IsTry:      st.trySet != nil,
+		BuilderRev: st.BuilderRev,
+	}
+	st.mu.Lock()
+	st.schedItem = schedItem
+	st.mu.Unlock()
+
+	sp := st.CreateSpan("get_buildlet")
+	bc, err := sched.GetBuildlet(st.ctx, st, schedItem)
+	sp.Done(err)
+	if err != nil {
+		err = fmt.Errorf("failed to get a buildlet: %v", err)
+		go st.reportErr(err)
+		return nil, err
+	}
+	atomic.StoreInt32(&st.hasBuildlet, 1)
+
+	st.mu.Lock()
+	st.bc = bc
+	st.mu.Unlock()
+	st.LogEventTime("using_buildlet", bc.IPPort())
+
+	return bc, nil
+}
+
 func (st *buildStatus) build() error {
 	if deps := st.conf.GoDeps; len(deps) > 0 {
 		ctx, cancel := context.WithTimeout(st.ctx, 30*time.Second)
@@ -1854,25 +1882,11 @@ func (st *buildStatus) build() error {
 		st.forceSnapshotUsage()
 	}
 
-	sp = st.CreateSpan("get_buildlet")
-	bc, err := sched.GetBuildlet(st.ctx, st, &SchedItem{
-		HostType:   st.conf.HostType,
-		IsTry:      st.trySet != nil,
-		BuilderRev: st.BuilderRev,
-	})
-	sp.Done(err)
+	bc, err := st.getBuildlet()
 	if err != nil {
-		err = fmt.Errorf("failed to get a buildlet: %v", err)
-		go st.reportErr(err)
 		return err
 	}
-	atomic.StoreInt32(&st.hasBuildlet, 1)
 	defer bc.Close()
-	st.mu.Lock()
-	st.bc = bc
-	st.mu.Unlock()
-
-	st.LogEventTime("using_buildlet", bc.IPPort())
 
 	if st.useSnapshot() {
 		sp := st.CreateSpan("write_snapshot_tar")
@@ -1967,6 +1981,8 @@ func (st *buildStatus) build() error {
 	return nil
 }
 
+func (st *buildStatus) HasBuildlet() bool { return atomic.LoadInt32(&st.hasBuildlet) != 0 }
+
 func (st *buildStatus) isTry() bool { return st.trySet != nil }
 
 func (st *buildStatus) isSlowBot() bool {
@@ -3367,8 +3383,8 @@ func (s byTestDuration) Swap(i, j int)      { s[i], s[j] = s[j], s[i] }
 
 type eventAndTime struct {
 	t    time.Time
-	evt  string
-	text string
+	evt  string // "get_source", "make_and_test", "make", etc
+	text string // optional detail text
 }
 
 // buildStatus is the status of a build.
@@ -3391,6 +3407,7 @@ type buildStatus struct {
 	hasBenchResults bool // set by runTests, may only be used when build() returns.
 
 	mu              sync.Mutex       // guards following
+	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
@@ -3544,8 +3561,9 @@ func (st *buildStatus) hasEvent(event string) bool {
 
 // HTMLStatusLine returns the HTML to show within the <pre> block on
 // the main page's list of active builds.
-func (st *buildStatus) HTMLStatusLine() template.HTML      { return st.htmlStatusLine(true) }
-func (st *buildStatus) HTMLStatusLine_done() template.HTML { return st.htmlStatusLine(false) }
+func (st *buildStatus) HTMLStatusLine() template.HTML      { return st.htmlStatus(singleLine) }
+func (st *buildStatus) HTMLStatusTruncated() template.HTML { return st.htmlStatus(truncated) }
+func (st *buildStatus) HTMLStatus() template.HTML          { return st.htmlStatus(full) }
 
 func strSliceTo(s string, n int) string {
 	if len(s) <= n {
@@ -3554,7 +3572,15 @@ func strSliceTo(s string, n int) string {
 	return s[:n]
 }
 
-func (st *buildStatus) htmlStatusLine(full bool) template.HTML {
+type buildStatusDetail int
+
+const (
+	singleLine buildStatusDetail = iota
+	truncated
+	full
+)
+
+func (st *buildStatus) htmlStatus(detail buildStatusDetail) template.HTML {
 	if st == nil {
 		return "[nil]"
 	}
@@ -3588,13 +3614,17 @@ func (st *buildStatus) htmlStatusLine(full bool) template.HTML {
 
 	var state string
 	if st.done.IsZero() {
-		state = "running"
+		if st.HasBuildlet() {
+			state = "running"
+		} else {
+			state = "waiting_for_machine"
+		}
 	} else if st.succeeded {
 		state = "succeeded"
 	} else {
 		state = "<font color='#700000'>failed</font>"
 	}
-	if full {
+	if detail > singleLine {
 		fmt.Fprintf(&buf, "; <a href='%s'>%s</a>; %s", html.EscapeString(st.logsURLLocked()), state, html.EscapeString(st.bc.String()))
 	} else {
 		fmt.Fprintf(&buf, "; <a href='%s'>%s</a>", html.EscapeString(st.logsURLLocked()), state)
@@ -3605,9 +3635,13 @@ func (st *buildStatus) htmlStatusLine(full bool) template.HTML {
 		t = st.startTime
 	}
 	fmt.Fprintf(&buf, ", %v ago", time.Since(t).Round(time.Second))
-	if full {
+	if detail > singleLine {
 		buf.WriteByte('\n')
-		st.writeEventsLocked(&buf, true)
+		lastLines := 0
+		if detail == truncated {
+			lastLines = 3
+		}
+		st.writeEventsLocked(&buf, true, lastLines)
 	}
 	return template.HTML(buf.String())
 }
@@ -3633,10 +3667,20 @@ func (st *buildStatus) logsURLLocked() string {
 }
 
 // st.mu must be held.
-func (st *buildStatus) writeEventsLocked(w io.Writer, htmlMode bool) {
-	var lastT time.Time
-	for _, evt := range st.events {
-		lastT = evt.t
+// If numLines is greater than zero, it's the number of final lines to truncate to.
+func (st *buildStatus) writeEventsLocked(w io.Writer, htmlMode bool, numLines int) {
+	startAt := 0
+	if numLines > 0 {
+		startAt = len(st.events) - numLines
+		if startAt > 0 {
+			io.WriteString(w, "...\n")
+		} else {
+			startAt = 0
+		}
+	}
+
+	for i := startAt; i < len(st.events); i++ {
+		evt := st.events[i]
 		e := evt.evt
 		text := evt.text
 		if htmlMode {
@@ -3648,8 +3692,9 @@ func (st *buildStatus) writeEventsLocked(w io.Writer, htmlMode bool) {
 		}
 		fmt.Fprintf(w, "  %v %s %s\n", evt.t.Format(time.RFC3339), e, text)
 	}
-	if st.isRunningLocked() {
-		fmt.Fprintf(w, " %7s (now)\n", fmt.Sprintf("+%0.1fs", time.Since(lastT).Seconds()))
+	if st.isRunningLocked() && len(st.events) > 0 {
+		lastEvt := st.events[len(st.events)-1]
+		fmt.Fprintf(w, " %7s (now)\n", fmt.Sprintf("+%0.1fs", time.Since(lastEvt.t).Seconds()))
 	}
 }
 

cmd/coordinator/sched.go

@@ -11,6 +11,7 @@ import (
 	"context"
 	"fmt"
 	"log"
+	"sort"
 	"sync"
 	"time"
 
@@ -33,7 +34,7 @@ var useScheduler = false
 // for buildlets, starts the creation of buildlets from BuildletPools,
 // and prioritizes which callers gets them first when they're ready.
 type Scheduler struct {
-	// mu guards waiting and hostsCreating.
+	// mu guards the following fields.
 	mu sync.Mutex
 
 	// waiting contains all the set of callers who are waiting for
@@ -43,6 +44,8 @@ type Scheduler struct {
 	// hostsCreating is the number of GetBuildlet calls currently in flight
 	// to each hostType's respective buildlet pool.
 	hostsCreating map[string]int // hostType -> count
+
+	lastProgress map[string]time.Time // hostType -> time last delivered buildlet
 }
 
 // A getBuildletResult is a buildlet that was just created and is up and
@@ -61,6 +64,7 @@ func NewScheduler() *Scheduler {
 	s := &Scheduler{
 		hostsCreating: make(map[string]int),
 		waiting:       make(map[string]map[*SchedItem]bool),
+		lastProgress:  make(map[string]time.Time),
 	}
 	return s
 }
@@ -83,6 +87,10 @@ func (s *Scheduler) matchBuildlet(res getBuildletResult) {
 		case ch := <-waiter.wantRes:
 			// Normal happy case. Something gets its buildlet.
 			ch <- res.Client
+
+			s.mu.Lock()
+			s.lastProgress[res.HostType] = time.Now()
+			s.mu.Unlock()
 			return
 		case <-waiter.ctxDone:
 			// Waiter went away in the tiny window between
@@ -205,6 +213,64 @@ func (s *Scheduler) hasWaiter(si *SchedItem) bool {
 	return s.waiting[si.HostType][si]
 }
 
+type schedulerWaitingState struct {
+	Count  int
+	Newest time.Duration
+	Oldest time.Duration
+}
+
+func (st *schedulerWaitingState) add(si *SchedItem) {
+	st.Count++
+	age := time.Since(si.requestTime).Round(time.Second)
+	if st.Newest == 0 || age < st.Newest {
+		st.Newest = age
+	}
+	if st.Oldest == 0 || age > st.Oldest {
+		st.Oldest = age
+	}
+}
+
+type schedulerHostState struct {
+	HostType     string
+	LastProgress time.Duration
+	Total        schedulerWaitingState
+	Gomote       schedulerWaitingState
+	Try          schedulerWaitingState
+	Regular      schedulerWaitingState
+}
+
+type schedulerState struct {
+	HostTypes []schedulerHostState
+}
+
+func (s *Scheduler) state() (st schedulerState) {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+
+	for hostType, m := range s.waiting {
+		if len(m) == 0 {
+			continue
+		}
+		var hst schedulerHostState
+		hst.HostType = hostType
+		hst.LastProgress = time.Since(s.lastProgress[hostType]).Round(time.Second)
+		for si := range m {
+			hst.Total.add(si)
+			if si.IsGomote {
+				hst.Gomote.add(si)
+			} else if si.IsTry {
+				hst.Try.add(si)
+			} else {
+				hst.Regular.add(si)
+			}
+		}
+		st.HostTypes = append(st.HostTypes, hst)
+	}
+
+	sort.Slice(st.HostTypes, func(i, j int) bool { return st.HostTypes[i].HostType < st.HostTypes[j].HostType })
+	return st
+}
+
 // schedLess reports whether scheduled item ia is "less" (more
 // important) than scheduled item ib.
 func schedLess(ia, ib *SchedItem) bool {

cmd/coordinator/status.go

@@ -574,7 +574,7 @@ func handleStatus(w http.ResponseWriter, r *http.Request) {
 		HealthCheckers: healthCheckers,
 	}
 	for _, st := range status {
-		if atomic.LoadInt32(&st.hasBuildlet) != 0 {
+		if st.HasBuildlet() {
 			data.ActiveBuilds++
 			data.Active = append(data.Active, st)
 			if st.conf.IsReverse() {
@@ -626,6 +626,8 @@ func handleStatus(w http.ResponseWriter, r *http.Request) {
 	reversePool.WriteHTMLStatus(&buf)
 	data.ReversePoolStatus = template.HTML(buf.String())
 
+	data.SchedState = sched.state()
+
 	buf.Reset()
 	if err := statusTmpl.Execute(&buf, data); err != nil {
 		http.Error(w, err.Error(), http.StatusInternalServerError)
@@ -688,6 +690,7 @@ type statusData struct {
 	KubePoolStatus    template.HTML // TODO: embed template
 	ReversePoolStatus template.HTML // TODO: embed template
 	RemoteBuildlets   template.HTML
+	SchedState        schedulerState
 	DiskFree          string
 	Version           string
 	HealthCheckers    []*healthChecker
@@ -729,7 +732,19 @@ var statusTmpl = template.Must(template.New("status").Parse(`
 {{.Trybots}}
 {{end}}
 
-<h2 id=remote>Remote buildlets <a href='#remote'>¶</a></h3>
+<h2 id=sched>Scheduler State <a href='#sched'>¶</a></h2>
+<ul>
+   {{range .SchedState.HostTypes}}
+       <li><b>{{.HostType}}</b>: {{.Total.Count}} waiting (oldest {{.Total.Oldest}}, newest {{.Total.Newest}}, progress {{.LastProgress}})
+          {{if or .Gomote.Count .Try.Count}}<ul>
+            {{if .Gomote.Count}}<li>gomote: {{.Gomote.Count}} (oldest {{.Gomote.Oldest}}, newest {{.Gomote.Newest}})</li>{{end}}
+            {{if .Try.Count}}<li>try: {{.Try.Count}} (oldest {{.Try.Oldest}}, newest {{.Try.Newest}})</li>{{end}}
+          </ul>{{end}}
+       </li>
+   {{end}}
+</ul>
+
+<h2 id=remote>Remote buildlets <a href='#remote'>¶</a></h2>
 {{.RemoteBuildlets}}
 
 <h2 id=pools>Buildlet pools <a href='#pools'>¶</a></h2>
@@ -742,21 +757,21 @@ var statusTmpl = template.Must(template.New("status").Parse(`
 <h2 id=active>Active builds <a href='#active'>¶</a></h2>
 <ul>
 	{{range .Active}}
-	<li><pre>{{.HTMLStatusLine}}</pre></li>
+	<li><pre>{{.HTMLStatusTruncated}}</pre></li>
 	{{end}}
 </ul>
 
 <h2 id=pending>Pending builds <a href='#pending'>¶</a></h2>
 <ul>
 	{{range .Pending}}
-	<li><pre>{{.HTMLStatusLine}}</pre></li>
+	<li><span>{{.HTMLStatusLine}}</span></li>
 	{{end}}
 </ul>
 
 <h2 id=completed>Recently completed <a href='#completed'>¶</a></h2>
 <ul>
 	{{range .Recent}}
-	<li><span>{{.HTMLStatusLine_done}}</span></li>
+	<li><span>{{.HTMLStatusLine}}</span></li>
 	{{end}}
 </ul>