cmd/go: mark trace flows between actions

This could help make it easier to identify blocking
dependencies when examining traces. Flows can be turned
off when viewing traces to remove potential distractions.

Updates #38714

Change-Id: Ibfd3f1a1861e3cac31addb053a2fca7ee796c4d7
Reviewed-on: https://go-review.googlesource.com/c/go/+/248322
Run-TryBot: Michael Matloob <matloob@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Bryan C. Mills <bcmills@google.com>

src/cmd/go/internal/trace/trace.go

@@ -15,6 +15,18 @@ import (
 	"time"
 )
 
+// Constants used in event fields.
+// See https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU
+// for more details.
+const (
+	phaseDurationBegin = "B"
+	phaseDurationEnd   = "E"
+	phaseFlowStart     = "s"
+	phaseFlowEnd       = "f"
+
+	bindEnclosingSlice = "e"
+)
+
 var traceStarted int32
 
 func getTraceContext(ctx context.Context) (traceContext, bool) {
@@ -39,7 +51,7 @@ func StartSpan(ctx context.Context, name string) (context.Context, *Span) {
 		Name:  childSpan.name,
 		Time:  float64(childSpan.start.UnixNano()) / float64(time.Microsecond),
 		TID:   childSpan.tid,
-		Phase: "B",
+		Phase: phaseDurationBegin,
 	})
 	ctx = context.WithValue(ctx, traceKey{}, traceContext{tc.t, tc.tid})
 	return ctx, childSpan
@@ -56,6 +68,34 @@ func StartGoroutine(ctx context.Context) context.Context {
 	return context.WithValue(ctx, traceKey{}, traceContext{tc.t, tc.t.getNextTID()})
 }
 
+// Flow marks a flow indicating that the 'to' span depends on the 'from' span.
+// Flow should be called while the 'to' span is in progress.
+func Flow(ctx context.Context, from *Span, to *Span) {
+	tc, ok := getTraceContext(ctx)
+	if !ok || from == nil || to == nil {
+		return
+	}
+
+	id := tc.t.getNextFlowID()
+	tc.t.writeEvent(&traceviewer.Event{
+		Name:     from.name + " -> " + to.name,
+		Category: "flow",
+		ID:       id,
+		Time:     float64(from.end.UnixNano()) / float64(time.Microsecond),
+		Phase:    phaseFlowStart,
+		TID:      from.tid,
+	})
+	tc.t.writeEvent(&traceviewer.Event{
+		Name:      from.name + " -> " + to.name,
+		Category:  "flow", // TODO(matloob): Add Category to Flow?
+		ID:        id,
+		Time:      float64(to.start.UnixNano()) / float64(time.Microsecond),
+		Phase:     phaseFlowEnd,
+		TID:       to.tid,
+		BindPoint: bindEnclosingSlice,
+	})
+}
+
 type Span struct {
 	t *tracer
 
@@ -74,7 +114,7 @@ func (s *Span) Done() {
 		Name:  s.name,
 		Time:  float64(s.end.UnixNano()) / float64(time.Microsecond),
 		TID:   s.tid,
-		Phase: "E",
+		Phase: phaseDurationEnd,
 	})
 }
 
@@ -82,6 +122,7 @@ type tracer struct {
 	file chan traceFile // 1-buffered
 
 	nextTID    uint64
+	nextFlowID uint64
 }
 
 func (t *tracer) writeEvent(ev *traceviewer.Event) error {
@@ -123,6 +164,10 @@ func (t *tracer) getNextTID() uint64 {
 	return atomic.AddUint64(&t.nextTID, 1)
 }
 
+func (t *tracer) getNextFlowID() uint64 {
+	return atomic.AddUint64(&t.nextFlowID, 1)
+}
+
 // traceKey is the context key for tracing information. It is unexported to prevent collisions with context keys defined in
 // other packages.
 type traceKey struct{}

src/cmd/go/internal/work/action.go

@@ -26,6 +26,7 @@ import (
 	"cmd/go/internal/cache"
 	"cmd/go/internal/cfg"
 	"cmd/go/internal/load"
+	"cmd/go/internal/trace"
 	"cmd/internal/buildid"
 )
 
@@ -96,6 +97,7 @@ type Action struct {
 	priority  int         // relative execution priority
 	Failed    bool        // whether the action failed
 	json      *actionJSON // action graph information
+	traceSpan *trace.Span
 }
 
 // BuildActionID returns the action ID section of a's build ID.

src/cmd/go/internal/work/exec.go

@@ -127,6 +127,10 @@ func (b *Builder) Do(ctx context.Context, root *Action) {
 				desc += "(" + a.Mode + " " + a.Package.Desc() + ")"
 			}
 			ctx, span := trace.StartSpan(ctx, desc)
+			a.traceSpan = span
+			for _, d := range a.Deps {
+				trace.Flow(ctx, d.traceSpan, a.traceSpan)
+			}
 			err = a.Func(b, ctx, a)
 			span.Done()
 		}