Skip to content

Commit

Permalink
cmd/go: add more information to -debug-actiongraph
Browse files Browse the repository at this point in the history 
Add information about action and build IDs,
commands run, time spent in commands,
and overall time to -debug-actiongraph output.

Also avoid a terrible outcome in:

	go build -debug-actiongraph x.go

Change-Id: I7a3a638f4848d75f2bdc997517f4ab23656da4f1
Reviewed-on: https://go-review.googlesource.com/c/go/+/177138
Run-TryBot: Russ Cox <rsc@golang.org>
Reviewed-by: Bryan C. Mills <bcmills@google.com>
  • Loading branch information
@rsc
rsc committed May 16, 2019
1 parent 86463c1 commit 54260c5
Show file tree
Hide file tree
Showing 5 changed files with 116 additions and 50 deletions.
84 changes: 52 additions & 32 deletions src/cmd/go/internal/work/action.go
View file
Expand Up @@ -91,9 +91,10 @@ type Action struct {
output []byte // output redirect buffer (nil means use b.Print)

// Execution state.
pending int // number of deps yet to complete
priority int // relative execution priority
Failed bool // whether the action failed
pending int // number of deps yet to complete
priority int // relative execution priority
Failed bool // whether the action failed
json *actionJSON // action graph information
}

// BuildActionID returns the action ID section of a's build ID.
Expand Down Expand Up @@ -125,6 +126,9 @@ func (q *actionQueue) Pop() interface{} {
}

func (q *actionQueue) push(a *Action) {
if a.json != nil {
a.json.TimeReady = time.Now()
}
heap.Push(q, a)
}

Expand All @@ -136,16 +140,28 @@ type actionJSON struct {
ID int
Mode string
Package string
Deps []int `json:",omitempty"`
IgnoreFail bool `json:",omitempty"`
Args []string `json:",omitempty"`
Link bool `json:",omitempty"`
Objdir string `json:",omitempty"`
Target string `json:",omitempty"`
Priority int `json:",omitempty"`
Failed bool `json:",omitempty"`
Built string `json:",omitempty"`
VetxOnly bool `json:",omitempty"`
Deps []int `json:",omitempty"`
IgnoreFail bool `json:",omitempty"`
Args []string `json:",omitempty"`
Link bool `json:",omitempty"`
Objdir string `json:",omitempty"`
Target string `json:",omitempty"`
Priority int `json:",omitempty"`
Failed bool `json:",omitempty"`
Built string `json:",omitempty"`
VetxOnly bool `json:",omitempty"`
NeedVet bool `json:",omitempty"`
NeedBuild bool `json:",omitempty"`
ActionID string `json:",omitempty"`
BuildID string `json:",omitempty"`
TimeReady time.Time `json:",omitempty"`
TimeStart time.Time `json:",omitempty"`
TimeDone time.Time `json:",omitempty"`

Cmd []string // `json:",omitempty"`
CmdReal time.Duration `json:",omitempty"`
CmdUser time.Duration `json:",omitempty"`
CmdSys time.Duration `json:",omitempty"`
}

// cacheKey is the key for the action cache.
Expand Down Expand Up @@ -175,26 +191,30 @@ func actionGraphJSON(a *Action) string {

var list []*actionJSON
for id, a := range workq {
aj := &actionJSON{
Mode: a.Mode,
ID: id,
IgnoreFail: a.IgnoreFail,
Args: a.Args,
Objdir: a.Objdir,
Target: a.Target,
Failed: a.Failed,
Priority: a.priority,
Built: a.built,
VetxOnly: a.VetxOnly,
}
if a.Package != nil {
// TODO(rsc): Make this a unique key for a.Package somehow.
aj.Package = a.Package.ImportPath
}
for _, a1 := range a.Deps {
aj.Deps = append(aj.Deps, inWorkq[a1])
if a.json == nil {
a.json = &actionJSON{
Mode: a.Mode,
ID: id,
IgnoreFail: a.IgnoreFail,
Args: a.Args,
Objdir: a.Objdir,
Target: a.Target,
Failed: a.Failed,
Priority: a.priority,
Built: a.built,
VetxOnly: a.VetxOnly,
NeedBuild: a.needBuild,
NeedVet: a.needVet,
}
if a.Package != nil {
// TODO(rsc): Make this a unique key for a.Package somehow.
a.json.Package = a.Package.ImportPath
}
for _, a1 := range a.Deps {
a.json.Deps = append(a.json.Deps, inWorkq[a1])
}
}
list = append(list, aj)
list = append(list, a.json)
}

js, err := json.MarshalIndent(list, "", "\t")
Expand Down
15 changes: 15 additions & 0 deletions src/cmd/go/internal/work/buildid.go
View file
Expand Up @@ -423,6 +423,9 @@ func (b *Builder) useCache(a *Action, p *load.Package, actionHash cache.ActionID
// engineered 96-bit partial SHA256 collision.
a.actionID = actionHash
actionID := hashToString(actionHash)
if a.json != nil {
a.json.ActionID = actionID
}
contentID := actionID // temporary placeholder, likely unique
a.buildID = actionID + buildIDSeparator + contentID

Expand All @@ -440,6 +443,9 @@ func (b *Builder) useCache(a *Action, p *load.Package, actionHash cache.ActionID
buildID, _ = buildid.ReadFile(target)
if strings.HasPrefix(buildID, actionID+buildIDSeparator) {
a.buildID = buildID
if a.json != nil {
a.json.BuildID = a.buildID
}
a.built = target
// Poison a.Target to catch uses later in the build.
a.Target = "DO NOT USE - " + a.Mode
Expand Down Expand Up @@ -482,6 +488,9 @@ func (b *Builder) useCache(a *Action, p *load.Package, actionHash cache.ActionID
// Poison a.Target to catch uses later in the build.
a.Target = "DO NOT USE - main build pseudo-cache Target"
a.built = "DO NOT USE - main build pseudo-cache built"
if a.json != nil {
a.json.BuildID = a.buildID
}
return true
}
// Otherwise restore old build ID for main build.
Expand Down Expand Up @@ -549,6 +558,9 @@ func (b *Builder) useCache(a *Action, p *load.Package, actionHash cache.ActionID
a.built = file
a.Target = "DO NOT USE - using cache"
a.buildID = buildID
if a.json != nil {
a.json.BuildID = a.buildID
}
if p := a.Package; p != nil {
// Clearer than explaining that something else is stale.
p.StaleReason = "not installed but available in build cache"
Expand Down Expand Up @@ -644,6 +656,9 @@ func (b *Builder) updateBuildID(a *Action, target string, rewrite bool) error {

// Replace with new content-based ID.
a.buildID = newID
if a.json != nil {
a.json.BuildID = a.buildID
}
if len(matches) == 0 {
// Assume the user specified -buildid= to override what we were going to choose.
return nil
Expand Down
63 changes: 47 additions & 16 deletions src/cmd/go/internal/work/exec.go
View file
Expand Up @@ -75,13 +75,22 @@ func (b *Builder) Do(root *Action) {
a.priority = i
}

if cfg.DebugActiongraph != "" {
js := actionGraphJSON(root)
if err := ioutil.WriteFile(cfg.DebugActiongraph, []byte(js), 0666); err != nil {
fmt.Fprintf(os.Stderr, "go: writing action graph: %v\n", err)
base.SetExitStatus(1)
// Write action graph, without timing information, in case we fail and exit early.
writeActionGraph := func() {
if file := cfg.DebugActiongraph; file != "" {
if strings.HasSuffix(file, ".go") {
// Do not overwrite Go source code in:
// go build -debug-actiongraph x.go
base.Fatalf("go: refusing to write action graph to %v\n", file)
}
js := actionGraphJSON(root)
if err := ioutil.WriteFile(file, []byte(js), 0666); err != nil {
fmt.Fprintf(os.Stderr, "go: writing action graph: %v\n", err)
base.SetExitStatus(1)
}
}
}
writeActionGraph()

b.readySema = make(chan bool, len(all))

Expand All @@ -100,11 +109,16 @@ func (b *Builder) Do(root *Action) {
// Handle runs a single action and takes care of triggering
// any actions that are runnable as a result.
handle := func(a *Action) {
if a.json != nil {
a.json.TimeStart = time.Now()
}
var err error

if a.Func != nil && (!a.Failed || a.IgnoreFail) {
err = a.Func(b, a)
}
if a.json != nil {
a.json.TimeDone = time.Now()
}

// The actions run in parallel but all the updates to the
// shared work state are serialized through b.exec.
Expand Down Expand Up @@ -170,6 +184,9 @@ func (b *Builder) Do(root *Action) {
}

wg.Wait()

// Write action graph again, this time with timing information.
writeActionGraph()
}

// buildActionID computes the action ID for a build action.
Expand Down Expand Up @@ -1322,7 +1339,7 @@ func (b *Builder) getPkgConfigFlags(p *load.Package) (cflags, ldflags []string,
}
}
var out []byte
out, err = b.runOut(p.Dir, nil, b.PkgconfigCmd(), "--cflags", pcflags, "--", pkgs)
out, err = b.runOut(nil, p.Dir, nil, b.PkgconfigCmd(), "--cflags", pcflags, "--", pkgs)
if err != nil {
b.showOutput(nil, p.Dir, b.PkgconfigCmd()+" --cflags "+strings.Join(pcflags, " ")+" -- "+strings.Join(pkgs, " "), string(out))
b.Print(err.Error() + "\n")
Expand All @@ -1337,7 +1354,7 @@ func (b *Builder) getPkgConfigFlags(p *load.Package) (cflags, ldflags []string,
return nil, nil, err
}
}
out, err = b.runOut(p.Dir, nil, b.PkgconfigCmd(), "--libs", pcflags, "--", pkgs)
out, err = b.runOut(nil, p.Dir, nil, b.PkgconfigCmd(), "--libs", pcflags, "--", pkgs)
if err != nil {
b.showOutput(nil, p.Dir, b.PkgconfigCmd()+" --libs "+strings.Join(pcflags, " ")+" -- "+strings.Join(pkgs, " "), string(out))
b.Print(err.Error() + "\n")
Expand Down Expand Up @@ -1437,6 +1454,9 @@ func BuildInstallFunc(b *Builder, a *Action) (err error) {

a1 := a.Deps[0]
a.buildID = a1.buildID
if a.json != nil {
a.json.BuildID = a.buildID
}

// If we are using the eventual install target as an up-to-date
// cached copy of the thing we built, then there's no need to
Expand Down Expand Up @@ -1853,7 +1873,7 @@ var cgoTypeSigRe = lazyregexp.New(`\b_C2?(type|func|var|macro)_\B`)
// If the command fails, run prints information about the failure
// and returns a non-nil error.
func (b *Builder) run(a *Action, dir string, desc string, env []string, cmdargs ...interface{}) error {
out, err := b.runOut(dir, env, cmdargs...)
out, err := b.runOut(a, dir, env, cmdargs...)
if len(out) > 0 {
if desc == "" {
desc = b.fmtcmd(dir, "%s", strings.Join(str.StringList(cmdargs...), " "))
Expand Down Expand Up @@ -1885,7 +1905,8 @@ func (b *Builder) processOutput(out []byte) string {

// runOut runs the command given by cmdline in the directory dir.
// It returns the command output and any errors that occurred.
func (b *Builder) runOut(dir string, env []string, cmdargs ...interface{}) ([]byte, error) {
// It accumulates execution time in a.
func (b *Builder) runOut(a *Action, dir string, env []string, cmdargs ...interface{}) ([]byte, error) {
cmdline := str.StringList(cmdargs...)

for _, arg := range cmdline {
Expand Down Expand Up @@ -1926,7 +1947,17 @@ func (b *Builder) runOut(dir string, env []string, cmdargs ...interface{}) ([]by
cmd.Dir = dir
cmd.Env = base.EnvForDir(cmd.Dir, os.Environ())
cmd.Env = append(cmd.Env, env...)
start := time.Now()
err := cmd.Run()
if a != nil && a.json != nil {
aj := a.json
aj.Cmd = append(aj.Cmd, joinUnambiguously(cmdline))
aj.CmdReal += time.Since(start)
if ps := cmd.ProcessState; ps != nil {
aj.CmdUser += ps.UserTime()
aj.CmdSys += ps.SystemTime()
}
}

// err can be something like 'exit status 1'.
// Add information about what program was running.
Expand Down Expand Up @@ -2124,7 +2155,7 @@ func (b *Builder) ccompile(a *Action, p *load.Package, outfile string, flags []s
if !filepath.IsAbs(outfile) {
outfile = filepath.Join(p.Dir, outfile)
}
output, err := b.runOut(filepath.Dir(file), b.cCompilerEnv(), compiler, flags, "-o", outfile, "-c", filepath.Base(file))
output, err := b.runOut(a, filepath.Dir(file), b.cCompilerEnv(), compiler, flags, "-o", outfile, "-c", filepath.Base(file))
if len(output) > 0 {
// On FreeBSD 11, when we pass -g to clang 3.8 it
// invokes its internal assembler with -dwarf-version=2.
Expand Down Expand Up @@ -2157,7 +2188,7 @@ func (b *Builder) ccompile(a *Action, p *load.Package, outfile string, flags []s
}

// gccld runs the gcc linker to create an executable from a set of object files.
func (b *Builder) gccld(p *load.Package, objdir, outfile string, flags []string, objs []string) error {
func (b *Builder) gccld(a *Action, p *load.Package, objdir, outfile string, flags []string, objs []string) error {
var cmd []string
if len(p.CXXFiles) > 0 || len(p.SwigCXXFiles) > 0 {
cmd = b.GxxCmd(p.Dir, objdir)
Expand All @@ -2167,7 +2198,7 @@ func (b *Builder) gccld(p *load.Package, objdir, outfile string, flags []string,

cmdargs := []interface{}{cmd, "-o", outfile, objs, flags}
dir := p.Dir
out, err := b.runOut(dir, b.cCompilerEnv(), cmdargs...)
out, err := b.runOut(a, dir, b.cCompilerEnv(), cmdargs...)
if len(out) > 0 {
// Filter out useless linker warnings caused by bugs outside Go.
// See also cmd/link/internal/ld's hostlink method.
Expand Down Expand Up @@ -2651,7 +2682,7 @@ func (b *Builder) dynimport(a *Action, p *load.Package, objdir, importGo, cgoExe
}
ldflags = append(n, "-pie")
}
if err := b.gccld(p, objdir, dynobj, ldflags, linkobj); err != nil {
if err := b.gccld(a, p, objdir, dynobj, ldflags, linkobj); err != nil {
return err
}

Expand Down Expand Up @@ -2710,7 +2741,7 @@ var (
)

func (b *Builder) swigDoVersionCheck() error {
out, err := b.runOut("", nil, "swig", "-version")
out, err := b.runOut(nil, "", nil, "swig", "-version")
if err != nil {
return err
}
Expand Down Expand Up @@ -2865,7 +2896,7 @@ func (b *Builder) swigOne(a *Action, p *load.Package, file, objdir string, pcCFL
args = append(args, "-c++")
}

out, err := b.runOut(p.Dir, nil, "swig", args, file)
out, err := b.runOut(a, p.Dir, nil, "swig", args, file)
if err != nil {
if len(out) > 0 {
if bytes.Contains(out, []byte("-intgosize")) || bytes.Contains(out, []byte("-cgo")) {
Expand Down
2 changes: 1 addition & 1 deletion src/cmd/go/internal/work/gc.go
View file
Expand Up @@ -140,7 +140,7 @@ func (gcToolchain) gc(b *Builder, a *Action, archive string, importcfg []byte, s
args = append(args, mkAbs(p.Dir, f))
}

output, err = b.runOut(p.Dir, nil, args...)
output, err = b.runOut(a, p.Dir, nil, args...)
return ofile, output, err
}

Expand Down
2 changes: 1 addition & 1 deletion src/cmd/go/internal/work/gccgo.go
View file
Expand Up @@ -94,7 +94,7 @@ func (tools gccgoToolchain) gc(b *Builder, a *Action, archive string, importcfg
args = append(args, mkAbs(p.Dir, f))
}

output, err = b.runOut(p.Dir, nil, args)
output, err = b.runOut(a, p.Dir, nil, args)
return ofile, output, err
}

Expand Down

0 comments on commit 54260c5

Please sign in to comment.