gopls: additional instrumentation during goimports

Add some visibility into goimports operations, by instrumenting spans in
top-level imports and gocommand operations.

This may be the first time we instrument non-gopls code in this way, but
it should be safe as other build targets (e.g. the goimports or
gopackages commands) do not set a global exporter, and therefore the
cost of event instrumentation should be minimal.

For golang/go#59216

Change-Id: Id2f8fe05d6b61e96cdd2d41cc43b3d4c3cf39e21
Reviewed-on: https://go-review.googlesource.com/c/tools/+/494095
Reviewed-by: Alan Donovan <[email protected]>
Run-TryBot: Robert Findley <[email protected]>
TryBot-Result: Gopher Robot <[email protected]>
gopls-CI: kokoro <[email protected]>

Author: findleyr

gopls/internal/lsp/cache/imports.go

@@ -31,7 +31,10 @@ type importsState struct {
 	cachedDirectoryFilters []string
 }
 
-func (s *importsState) runProcessEnvFunc(ctx context.Context, snapshot *snapshot, fn func(*imports.Options) error) error {
+func (s *importsState) runProcessEnvFunc(ctx context.Context, snapshot *snapshot, fn func(context.Context, *imports.Options) error) error {
+	ctx, done := event.Start(ctx, "cache.importsState.runProcessEnvFunc")
+	defer done()
+
 	s.mu.Lock()
 	defer s.mu.Unlock()
 
@@ -93,7 +96,7 @@ func (s *importsState) runProcessEnvFunc(ctx context.Context, snapshot *snapshot
 		LocalPrefix: localPrefix,
 	}
 
-	if err := fn(opts); err != nil {
+	if err := fn(ctx, opts); err != nil {
 		return err
 	}
 
@@ -114,6 +117,9 @@ func (s *importsState) runProcessEnvFunc(ctx context.Context, snapshot *snapshot
 // the view's process environment. Assumes that the caller is holding the
 // importsState mutex.
 func populateProcessEnvFromSnapshot(ctx context.Context, pe *imports.ProcessEnv, snapshot *snapshot) error {
+	ctx, done := event.Start(ctx, "cache.populateProcessEnvFromSnapshot")
+	defer done()
+
 	if snapshot.view.Options().VerboseOutput {
 		pe.Logf = func(format string, args ...interface{}) {
 			event.Log(ctx, fmt.Sprintf(format, args...))
@@ -153,6 +159,9 @@ func populateProcessEnvFromSnapshot(ctx context.Context, pe *imports.ProcessEnv,
 }
 
 func (s *importsState) refreshProcessEnv() {
+	ctx, done := event.Start(s.ctx, "cache.importsState.refreshProcessEnv")
+	defer done()
+
 	start := time.Now()
 
 	s.mu.Lock()
@@ -164,9 +173,9 @@ func (s *importsState) refreshProcessEnv() {
 
 	event.Log(s.ctx, "background imports cache refresh starting")
 	if err := imports.PrimeCache(context.Background(), env); err == nil {
-		event.Log(s.ctx, fmt.Sprintf("background refresh finished after %v", time.Since(start)))
+		event.Log(ctx, fmt.Sprintf("background refresh finished after %v", time.Since(start)))
 	} else {
-		event.Log(s.ctx, fmt.Sprintf("background refresh finished after %v", time.Since(start)), keys.Err.Of(err))
+		event.Log(ctx, fmt.Sprintf("background refresh finished after %v", time.Since(start)), keys.Err.Of(err))
 	}
 	s.mu.Lock()
 	s.cacheRefreshDuration = time.Since(start)

gopls/internal/lsp/cache/view.go

@@ -436,7 +436,7 @@ func viewEnv(v *View) string {
 	return buf.String()
 }
 
-func (s *snapshot) RunProcessEnvFunc(ctx context.Context, fn func(*imports.Options) error) error {
+func (s *snapshot) RunProcessEnvFunc(ctx context.Context, fn func(context.Context, *imports.Options) error) error {
 	return s.view.importsState.runProcessEnvFunc(ctx, s, fn)
 }
 

gopls/internal/lsp/debug/trace.go

@@ -35,7 +35,7 @@ var TraceTmpl = template.Must(template.Must(BaseTemplate.Clone()).Parse(`
 
         <H2>Recent spans (oldest first)</H2>
         <p>
-	A finite number of recent span start/end times are shown below.
+        A finite number of recent span start/end times are shown below.
         The nesting represents the children of a parent span (and the log events within a span).
         A span may appear twice: chronologically at toplevel, and nested within its parent.
         </p>

gopls/internal/lsp/source/completion/completion.go

@@ -200,7 +200,7 @@ type completer struct {
 	// completionCallbacks is a list of callbacks to collect completions that
 	// require expensive operations. This includes operations where we search
 	// through the entire module cache.
-	completionCallbacks []func(opts *imports.Options) error
+	completionCallbacks []func(context.Context, *imports.Options) error
 
 	// surrounding describes the identifier surrounding the position.
 	surrounding *Selection
@@ -887,7 +887,7 @@ func (c *completer) populateImportCompletions(ctx context.Context, searchImport
 		})
 	}
 
-	c.completionCallbacks = append(c.completionCallbacks, func(opts *imports.Options) error {
+	c.completionCallbacks = append(c.completionCallbacks, func(ctx context.Context, opts *imports.Options) error {
 		return imports.GetImportPaths(ctx, searchImports, prefix, c.filename, c.pkg.GetTypes().Name(), opts.Env)
 	})
 	return nil
@@ -1195,7 +1195,7 @@ func (c *completer) selector(ctx context.Context, sel *ast.SelectorExpr) error {
 	// Rank import paths as goimports would.
 	var relevances map[string]float64
 	if len(paths) > 0 {
-		if err := c.snapshot.RunProcessEnvFunc(ctx, func(opts *imports.Options) error {
+		if err := c.snapshot.RunProcessEnvFunc(ctx, func(ctx context.Context, opts *imports.Options) error {
 			var err error
 			relevances, err = imports.ScoreImportPaths(ctx, opts.Env, paths)
 			return err
@@ -1342,7 +1342,7 @@ func (c *completer) selector(ctx context.Context, sel *ast.SelectorExpr) error {
 		}
 	}
 
-	c.completionCallbacks = append(c.completionCallbacks, func(opts *imports.Options) error {
+	c.completionCallbacks = append(c.completionCallbacks, func(ctx context.Context, opts *imports.Options) error {
 		defer cancel()
 		return imports.GetPackageExports(ctx, add, id.Name, c.filename, c.pkg.GetTypes().Name(), opts.Env)
 	})
@@ -1635,7 +1635,7 @@ func (c *completer) unimportedPackages(ctx context.Context, seen map[string]stru
 	// Rank candidates using goimports' algorithm.
 	var relevances map[string]float64
 	if len(paths) != 0 {
-		if err := c.snapshot.RunProcessEnvFunc(ctx, func(opts *imports.Options) error {
+		if err := c.snapshot.RunProcessEnvFunc(ctx, func(ctx context.Context, opts *imports.Options) error {
 			var err error
 			relevances, err = imports.ScoreImportPaths(ctx, opts.Env, paths)
 			return err
@@ -1708,7 +1708,7 @@ func (c *completer) unimportedPackages(ctx context.Context, seen map[string]stru
 		})
 		count++
 	}
-	c.completionCallbacks = append(c.completionCallbacks, func(opts *imports.Options) error {
+	c.completionCallbacks = append(c.completionCallbacks, func(ctx context.Context, opts *imports.Options) error {
 		defer cancel()
 		return imports.GetAllCandidates(ctx, add, prefix, c.filename, c.pkg.GetTypes().Name(), opts.Env)
 	})

gopls/internal/lsp/source/format.go

@@ -116,8 +116,8 @@ func AllImportsFixes(ctx context.Context, snapshot Snapshot, fh FileHandle) (all
 	if err != nil {
 		return nil, nil, err
 	}
-	if err := snapshot.RunProcessEnvFunc(ctx, func(opts *imports.Options) error {
-		allFixEdits, editsPerFix, err = computeImportEdits(snapshot, pgf, opts)
+	if err := snapshot.RunProcessEnvFunc(ctx, func(ctx context.Context, opts *imports.Options) error {
+		allFixEdits, editsPerFix, err = computeImportEdits(ctx, snapshot, pgf, opts)
 		return err
 	}); err != nil {
 		return nil, nil, fmt.Errorf("AllImportsFixes: %v", err)
@@ -127,11 +127,11 @@ func AllImportsFixes(ctx context.Context, snapshot Snapshot, fh FileHandle) (all
 
 // computeImportEdits computes a set of edits that perform one or all of the
 // necessary import fixes.
-func computeImportEdits(snapshot Snapshot, pgf *ParsedGoFile, options *imports.Options) (allFixEdits []protocol.TextEdit, editsPerFix []*ImportFix, err error) {
+func computeImportEdits(ctx context.Context, snapshot Snapshot, pgf *ParsedGoFile, options *imports.Options) (allFixEdits []protocol.TextEdit, editsPerFix []*ImportFix, err error) {
 	filename := pgf.URI.Filename()
 
 	// Build up basic information about the original file.
-	allFixes, err := imports.FixImports(filename, pgf.Src, options)
+	allFixes, err := imports.FixImports(ctx, filename, pgf.Src, options)
 	if err != nil {
 		return nil, nil, err
 	}

gopls/internal/lsp/source/known_packages.go

@@ -85,7 +85,7 @@ func KnownPackagePaths(ctx context.Context, snapshot Snapshot, fh FileHandle) ([
 	}
 
 	// Augment the set by invoking the goimports algorithm.
-	if err := snapshot.RunProcessEnvFunc(ctx, func(o *imports.Options) error {
+	if err := snapshot.RunProcessEnvFunc(ctx, func(ctx context.Context, o *imports.Options) error {
 		ctx, cancel := context.WithTimeout(ctx, time.Millisecond*80)
 		defer cancel()
 		var seenMu sync.Mutex

gopls/internal/lsp/source/view.go

@@ -117,7 +117,7 @@ type Snapshot interface {
 
 	// RunProcessEnvFunc runs fn with the process env for this snapshot's view.
 	// Note: the process env contains cached module and filesystem state.
-	RunProcessEnvFunc(ctx context.Context, fn func(*imports.Options) error) error
+	RunProcessEnvFunc(ctx context.Context, fn func(context.Context, *imports.Options) error) error
 
 	// ModFiles are the go.mod files enclosed in the snapshot's view and known
 	// to the snapshot.

internal/gocommand/invoke.go

@@ -24,6 +24,9 @@ import (
 	exec "golang.org/x/sys/execabs"
 
 	"golang.org/x/tools/internal/event"
+	"golang.org/x/tools/internal/event/keys"
+	"golang.org/x/tools/internal/event/label"
+	"golang.org/x/tools/internal/event/tag"
 )
 
 // An Runner will run go command invocations and serialize
@@ -53,23 +56,38 @@ func (runner *Runner) initialize() {
 // 1.14: go: updating go.mod: existing contents have changed since last read
 var modConcurrencyError = regexp.MustCompile(`go:.*go.mod.*contents have changed`)
 
+// verb is an event label for the go command verb.
+var verb = keys.NewString("verb", "go command verb")
+
+func invLabels(inv Invocation) []label.Label {
+	return []label.Label{verb.Of(inv.Verb), tag.Directory.Of(inv.WorkingDir)}
+}
+
 // Run is a convenience wrapper around RunRaw.
 // It returns only stdout and a "friendly" error.
 func (runner *Runner) Run(ctx context.Context, inv Invocation) (*bytes.Buffer, error) {
+	ctx, done := event.Start(ctx, "gocommand.Runner.Run", invLabels(inv)...)
+	defer done()
+
 	stdout, _, friendly, _ := runner.RunRaw(ctx, inv)
 	return stdout, friendly
 }
 
 // RunPiped runs the invocation serially, always waiting for any concurrent
 // invocations to complete first.
 func (runner *Runner) RunPiped(ctx context.Context, inv Invocation, stdout, stderr io.Writer) error {
+	ctx, done := event.Start(ctx, "gocommand.Runner.RunPiped", invLabels(inv)...)
+	defer done()
+
 	_, err := runner.runPiped(ctx, inv, stdout, stderr)
 	return err
 }
 
 // RunRaw runs the invocation, serializing requests only if they fight over
 // go.mod changes.
 func (runner *Runner) RunRaw(ctx context.Context, inv Invocation) (*bytes.Buffer, *bytes.Buffer, error, error) {
+	ctx, done := event.Start(ctx, "gocommand.Runner.RunRaw", invLabels(inv)...)
+	defer done()
 	// Make sure the runner is always initialized.
 	runner.initialize()
 

internal/imports/fix.go

@@ -26,6 +26,7 @@ import (
 	"unicode/utf8"
 
 	"golang.org/x/tools/go/ast/astutil"
+	"golang.org/x/tools/internal/event"
 	"golang.org/x/tools/internal/gocommand"
 	"golang.org/x/tools/internal/gopathwalk"
 )
@@ -543,7 +544,7 @@ func (p *pass) addCandidate(imp *ImportInfo, pkg *packageInfo) {
 var fixImports = fixImportsDefault
 
 func fixImportsDefault(fset *token.FileSet, f *ast.File, filename string, env *ProcessEnv) error {
-	fixes, err := getFixes(fset, f, filename, env)
+	fixes, err := getFixes(context.Background(), fset, f, filename, env)
 	if err != nil {
 		return err
 	}
@@ -553,7 +554,7 @@ func fixImportsDefault(fset *token.FileSet, f *ast.File, filename string, env *P
 
 // getFixes gets the import fixes that need to be made to f in order to fix the imports.
 // It does not modify the ast.
-func getFixes(fset *token.FileSet, f *ast.File, filename string, env *ProcessEnv) ([]*ImportFix, error) {
+func getFixes(ctx context.Context, fset *token.FileSet, f *ast.File, filename string, env *ProcessEnv) ([]*ImportFix, error) {
 	abs, err := filepath.Abs(filename)
 	if err != nil {
 		return nil, err
@@ -607,7 +608,7 @@ func getFixes(fset *token.FileSet, f *ast.File, filename string, env *ProcessEnv
 
 	// Go look for candidates in $GOPATH, etc. We don't necessarily load
 	// the real exports of sibling imports, so keep assuming their contents.
-	if err := addExternalCandidates(p, p.missingRefs, filename); err != nil {
+	if err := addExternalCandidates(ctx, p, p.missingRefs, filename); err != nil {
 		return nil, err
 	}
 
@@ -1055,7 +1056,10 @@ type scanCallback struct {
 	exportsLoaded func(pkg *pkg, exports []string)
 }
 
-func addExternalCandidates(pass *pass, refs references, filename string) error {
+func addExternalCandidates(ctx context.Context, pass *pass, refs references, filename string) error {
+	ctx, done := event.Start(ctx, "imports.addExternalCandidates")
+	defer done()
+
 	var mu sync.Mutex
 	found := make(map[string][]pkgDistance)
 	callback := &scanCallback{

internal/imports/imports.go

@@ -11,6 +11,7 @@ package imports
 import (
 	"bufio"
 	"bytes"
+	"context"
 	"fmt"
 	"go/ast"
 	"go/format"
@@ -23,6 +24,7 @@ import (
 	"strings"
 
 	"golang.org/x/tools/go/ast/astutil"
+	"golang.org/x/tools/internal/event"
 )
 
 // Options is golang.org/x/tools/imports.Options with extra internal-only options.
@@ -66,14 +68,17 @@ func Process(filename string, src []byte, opt *Options) (formatted []byte, err e
 //
 // Note that filename's directory influences which imports can be chosen,
 // so it is important that filename be accurate.
-func FixImports(filename string, src []byte, opt *Options) (fixes []*ImportFix, err error) {
+func FixImports(ctx context.Context, filename string, src []byte, opt *Options) (fixes []*ImportFix, err error) {
+	ctx, done := event.Start(ctx, "imports.FixImports")
+	defer done()
+
 	fileSet := token.NewFileSet()
 	file, _, err := parse(fileSet, filename, src, opt)
 	if err != nil {
 		return nil, err
 	}
 
-	return getFixes(fileSet, file, filename, opt.Env)
+	return getFixes(ctx, fileSet, file, filename, opt.Env)
 }
 
 // ApplyFixes applies all of the fixes to the file and formats it. extraMode

internal/imports/mod.go

@@ -19,6 +19,7 @@ import (
 	"strings"
 
 	"golang.org/x/mod/module"
+	"golang.org/x/tools/internal/event"
 	"golang.org/x/tools/internal/gocommand"
 	"golang.org/x/tools/internal/gopathwalk"
 )
@@ -424,6 +425,9 @@ func (r *ModuleResolver) loadPackageNames(importPaths []string, srcDir string) (
 }
 
 func (r *ModuleResolver) scan(ctx context.Context, callback *scanCallback) error {
+	ctx, done := event.Start(ctx, "imports.ModuleResolver.scan")
+	defer done()
+
 	if err := r.init(); err != nil {
 		return err
 	}