internal/lsp: add additional instrumentation around package loading

Add some additional logging to help debug golang/go#53586

For golang/go#53586

Change-Id: I0574fb01be47b265cd6e412855794bc2cb836dff
Reviewed-on: https://go-review.googlesource.com/c/tools/+/414854
gopls-CI: kokoro <noreply+kokoro@google.com>
Reviewed-by: Alan Donovan <adonovan@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Robert Findley <rfindley@google.com>
Auto-Submit: Robert Findley <rfindley@google.com>

internal/lsp/cache/load.go

@@ -15,6 +15,7 @@ import (
 	"path/filepath"
 	"sort"
 	"strings"
+	"sync/atomic"
 	"time"
 
 	"golang.org/x/tools/go/packages"
@@ -28,12 +29,17 @@ import (
 	"golang.org/x/tools/internal/span"
 )
 
+var loadID uint64 // atomic identifier for loads
+
 // load calls packages.Load for the given scopes, updating package metadata,
 // import graph, and mapped files with the result.
 //
 // The resulting error may wrap the moduleErrorMap error type, representing
 // errors associated with specific modules.
 func (s *snapshot) load(ctx context.Context, allowNetwork bool, scopes ...interface{}) (err error) {
+	id := atomic.AddUint64(&loadID, 1)
+	eventName := fmt.Sprintf("go/packages.Load #%d", id) // unique name for logging
+
 	var query []string
 	var containsDir bool // for logging
 
@@ -138,9 +144,9 @@ func (s *snapshot) load(ctx context.Context, allowNetwork bool, scopes ...interf
 		return ctx.Err()
 	}
 	if err != nil {
-		event.Error(ctx, "go/packages.Load", err, tag.Snapshot.Of(s.ID()), tag.Directory.Of(cfg.Dir), tag.Query.Of(query), tag.PackageCount.Of(len(pkgs)))
+		event.Error(ctx, eventName, err, tag.Snapshot.Of(s.ID()), tag.Directory.Of(cfg.Dir), tag.Query.Of(query), tag.PackageCount.Of(len(pkgs)))
 	} else {
-		event.Log(ctx, "go/packages.Load", tag.Snapshot.Of(s.ID()), tag.Directory.Of(cfg.Dir), tag.Query.Of(query), tag.PackageCount.Of(len(pkgs)))
+		event.Log(ctx, eventName, tag.Snapshot.Of(s.ID()), tag.Directory.Of(cfg.Dir), tag.Query.Of(query), tag.PackageCount.Of(len(pkgs)))
 	}
 	if len(pkgs) == 0 {
 		if err == nil {
@@ -168,7 +174,7 @@ func (s *snapshot) load(ctx context.Context, allowNetwork bool, scopes ...interf
 		}
 
 		if !containsDir || s.view.Options().VerboseOutput {
-			event.Log(ctx, "go/packages.Load",
+			event.Log(ctx, eventName,
 				tag.Snapshot.Of(s.ID()),
 				tag.Package.Of(pkg.ID),
 				tag.Files.Of(pkg.CompiledGoFiles))
@@ -209,6 +215,8 @@ func (s *snapshot) load(ctx context.Context, allowNetwork bool, scopes ...interf
 		loadedIDs = append(loadedIDs, id)
 	}
 
+	event.Log(ctx, fmt.Sprintf("%s: updating metadata for %d packages", eventName, len(updates)))
+
 	s.mu.Lock()
 
 	// invalidate the reverse transitive closure of packages that have changed.

internal/lsp/source/completion/completion.go

@@ -441,7 +441,7 @@ func Completion(ctx context.Context, snapshot source.Snapshot, fh source.FileHan
 		items, surrounding, innerErr := packageClauseCompletions(ctx, snapshot, fh, protoPos)
 		if innerErr != nil {
 			// return the error for GetParsedFile since it's more relevant in this situation.
-			return nil, nil, fmt.Errorf("getting file for Completion: %w (package completions: %v)", err, innerErr)
+			return nil, nil, fmt.Errorf("getting file %s for Completion: %w (package completions: %v)", fh.URI(), err, innerErr)
 		}
 		return items, surrounding, nil
 	}