From 0248714391a4231dea84e35fc04f8b65a609821e Mon Sep 17 00:00:00 2001 From: Robert Findley Date: Tue, 28 Jun 2022 14:50:14 -0400 Subject: [PATCH] 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 Reviewed-by: Alan Donovan TryBot-Result: Gopher Robot Run-TryBot: Robert Findley Auto-Submit: Robert Findley --- internal/lsp/cache/load.go | 14 +++++++++++--- internal/lsp/source/completion/completion.go | 2 +- 2 files changed, 12 insertions(+), 4 deletions(-) diff --git a/internal/lsp/cache/load.go b/internal/lsp/cache/load.go index db9a06d4de..da0b246c54 100644 --- a/internal/lsp/cache/load.go +++ b/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. diff --git a/internal/lsp/source/completion/completion.go b/internal/lsp/source/completion/completion.go index bb1c68d223..0c1ff3f21b 100644 --- a/internal/lsp/source/completion/completion.go +++ b/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 }