cmd/go: add tracing for querying and downloading from the proxy

This CL adds tracing spans for modload.queryPattern, modload.queryProxy,
modload.QueryPattern, modload.QueryPattern.queryModule,
modload.queryPrefixModules and modfetch.Download.

Updates #38714

Change-Id: I91af3f022a6e18ab8d9c1d9b0ccf4928b6c236bd
Reviewed-on: https://go-review.googlesource.com/c/go/+/249022
Run-TryBot: Michael Matloob <[email protected]>
TryBot-Result: Gobot Gobot <[email protected]>
Reviewed-by: Jay Conrod <[email protected]>

src/cmd/go/internal/modcmd/download.go

@@ -120,7 +120,7 @@ func runDownload(ctx context.Context, cmd *base.Command, args []string) {
 			return
 		}
 		mod := module.Version{Path: m.Path, Version: m.Version}
-		m.Zip, err = modfetch.DownloadZip(mod)
+		m.Zip, err = modfetch.DownloadZip(ctx, mod)
 		if err != nil {
 			m.Error = err.Error()
 			return

src/cmd/go/internal/modfetch/fetch.go

@@ -24,6 +24,7 @@ import (
 	"cmd/go/internal/par"
 	"cmd/go/internal/renameio"
 	"cmd/go/internal/robustio"
+	"cmd/go/internal/trace"
 
 	"golang.org/x/mod/module"
 	"golang.org/x/mod/sumdb/dirhash"
@@ -48,7 +49,7 @@ func Download(ctx context.Context, mod module.Version) (dir string, err error) {
 		err error
 	}
 	c := downloadCache.Do(mod, func() interface{} {
-		dir, err := download(mod)
+		dir, err := download(ctx, mod)
 		if err != nil {
 			return cached{"", err}
 		}
@@ -58,7 +59,10 @@ func Download(ctx context.Context, mod module.Version) (dir string, err error) {
 	return c.dir, c.err
 }
 
-func download(mod module.Version) (dir string, err error) {
+func download(ctx context.Context, mod module.Version) (dir string, err error) {
+	ctx, span := trace.StartSpan(ctx, "modfetch.download "+mod.String())
+	defer span.Done()
+
 	// If the directory exists, and no .partial file exists, the module has
 	// already been completely extracted. .partial files may be created when a
 	// module zip directory is extracted in place instead of being extracted to a
@@ -73,7 +77,7 @@ func download(mod module.Version) (dir string, err error) {
 	// To avoid cluttering the cache with extraneous files,
 	// DownloadZip uses the same lockfile as Download.
 	// Invoke DownloadZip before locking the file.
-	zipfile, err := DownloadZip(mod)
+	zipfile, err := DownloadZip(ctx, mod)
 	if err != nil {
 		return "", err
 	}
@@ -143,6 +147,7 @@ func download(mod module.Version) (dir string, err error) {
 		return "", err
 	}
 
+	ctx, span = trace.StartSpan(ctx, "unzip "+zipfile)
 	if unzipInPlace {
 		if err := ioutil.WriteFile(partialPath, nil, 0666); err != nil {
 			return "", err
@@ -172,6 +177,7 @@ func download(mod module.Version) (dir string, err error) {
 			return "", err
 		}
 	}
+	defer span.Done()
 
 	if !cfg.ModCacheRW {
 		// Make dir read-only only *after* renaming it.
@@ -196,7 +202,7 @@ var downloadZipCache par.Cache
 
 // DownloadZip downloads the specific module version to the
 // local zip cache and returns the name of the zip file.
-func DownloadZip(mod module.Version) (zipfile string, err error) {
+func DownloadZip(ctx context.Context, mod module.Version) (zipfile string, err error) {
 	// The par.Cache here avoids duplicate work.
 	type cached struct {
 		zipfile string
@@ -231,15 +237,18 @@ func DownloadZip(mod module.Version) (zipfile string, err error) {
 		if err := os.MkdirAll(filepath.Dir(zipfile), 0777); err != nil {
 			return cached{"", err}
 		}
-		if err := downloadZip(mod, zipfile); err != nil {
+		if err := downloadZip(ctx, mod, zipfile); err != nil {
 			return cached{"", err}
 		}
 		return cached{zipfile, nil}
 	}).(cached)
 	return c.zipfile, c.err
 }
 
-func downloadZip(mod module.Version, zipfile string) (err error) {
+func downloadZip(ctx context.Context, mod module.Version, zipfile string) (err error) {
+	ctx, span := trace.StartSpan(ctx, "modfetch.downloadZip "+zipfile)
+	defer span.Done()
+
 	// Clean up any remaining tempfiles from previous runs.
 	// This is only safe to do because the lock file ensures that their
 	// writers are no longer active.

src/cmd/go/internal/modfetch/zip_sum_test/zip_sum_test.go

@@ -16,6 +16,7 @@
 package zip_sum_test
 
 import (
+	"context"
 	"crypto/sha256"
 	"encoding/csv"
 	"encoding/hex"
@@ -119,7 +120,7 @@ func TestZipSums(t *testing.T) {
 		name := fmt.Sprintf("%s@%s", strings.ReplaceAll(test.m.Path, "/", "_"), test.m.Version)
 		t.Run(name, func(t *testing.T) {
 			t.Parallel()
-			zipPath, err := modfetch.DownloadZip(test.m)
+			zipPath, err := modfetch.DownloadZip(context.Background(), test.m)
 			if err != nil {
 				if *updateTestData {
 					t.Logf("%s: could not download module: %s (will remove from testdata)", test.m, err)

src/cmd/go/internal/modload/query.go

@@ -19,6 +19,7 @@ import (
 	"cmd/go/internal/modfetch"
 	"cmd/go/internal/search"
 	"cmd/go/internal/str"
+	"cmd/go/internal/trace"
 
 	"golang.org/x/mod/module"
 	"golang.org/x/mod/semver"
@@ -77,6 +78,9 @@ func (queryDisabledError) Error() string {
 }
 
 func queryProxy(ctx context.Context, proxy, path, query, current string, allowed func(module.Version) bool) (*modfetch.RevInfo, error) {
+	ctx, span := trace.StartSpan(ctx, "modload.queryProxy "+path+" "+query)
+	defer span.Done()
+
 	if current != "" && !semver.IsValid(current) {
 		return nil, fmt.Errorf("invalid previous version %q", current)
 	}
@@ -403,6 +407,9 @@ func QueryPackage(ctx context.Context, path, query string, allowed func(module.V
 // the main module and only the version "latest", without checking for other
 // possible modules.
 func QueryPattern(ctx context.Context, pattern, query string, allowed func(module.Version) bool) ([]QueryResult, error) {
+	ctx, span := trace.StartSpan(ctx, "modload.QueryPattern "+pattern+" "+query)
+	defer span.Done()
+
 	base := pattern
 
 	firstError := func(m *search.Match) error {
@@ -470,7 +477,10 @@ func QueryPattern(ctx context.Context, pattern, query string, allowed func(modul
 	}
 
 	err := modfetch.TryProxies(func(proxy string) error {
-		queryModule := func(path string) (r QueryResult, err error) {
+		queryModule := func(ctx context.Context, path string) (r QueryResult, err error) {
+			ctx, span := trace.StartSpan(ctx, "modload.QueryPattern.queryModule ["+proxy+"] "+path)
+			defer span.Done()
+
 			current := findCurrentVersion(path)
 			r.Mod.Path = path
 			r.Rev, err = queryProxy(ctx, proxy, path, query, current, allowed)
@@ -499,7 +509,7 @@ func QueryPattern(ctx context.Context, pattern, query string, allowed func(modul
 		}
 
 		var err error
-		results, err = queryPrefixModules(candidateModules, queryModule)
+		results, err = queryPrefixModules(ctx, candidateModules, queryModule)
 		return err
 	})
 
@@ -543,7 +553,10 @@ type prefixResult struct {
 	err error
 }
 
-func queryPrefixModules(candidateModules []string, queryModule func(path string) (QueryResult, error)) (found []QueryResult, err error) {
+func queryPrefixModules(ctx context.Context, candidateModules []string, queryModule func(ctx context.Context, path string) (QueryResult, error)) (found []QueryResult, err error) {
+	ctx, span := trace.StartSpan(ctx, "modload.queryPrefixModules")
+	defer span.Done()
+
 	// If the path we're attempting is not in the module cache and we don't have a
 	// fetch result cached either, we'll end up making a (potentially slow)
 	// request to the proxy or (often even slower) the origin server.
@@ -556,8 +569,9 @@ func queryPrefixModules(candidateModules []string, queryModule func(path string)
 	var wg sync.WaitGroup
 	wg.Add(len(candidateModules))
 	for i, p := range candidateModules {
+		ctx := trace.StartGoroutine(ctx)
 		go func(p string, r *result) {
-			r.QueryResult, r.err = queryModule(p)
+			r.QueryResult, r.err = queryModule(ctx, p)
 			wg.Done()
 		}(p, &results[i])
 	}