internal/lsp/debug: hook runtime/trace into event spans

Existing spans defined within gopls are leveraged to add runtime/trace
tasks, regions, and logging.

This made it easier to understand gopls' execution, though we still have
relatively sparse logging (arguably because we're conscious of the fact
that logs are reflected back to the LSP client). Add a new log package
with the concept of log level to facilitate excluding trace logs from
the LSP.

Add a little bit of additional instrumentation to demonstrate the usage
of the new package.

Change-Id: Id337be806484201103e30bfe2c8c62c7d7c363c7
Reviewed-on: https://go-review.googlesource.com/c/tools/+/275252
Run-TryBot: Robert Findley <rfindley@google.com>
gopls-CI: kokoro <noreply+kokoro@google.com>
TryBot-Result: Go Bot <gobot@golang.org>
Reviewed-by: Heschi Kreinick <heschi@google.com>
Trust: Robert Findley <rfindley@google.com>

internal/lsp/debug/log/log.go

@@ -0,0 +1,43 @@
+// Copyright 2020 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+// Package log provides helper methods for exporting log events to the
+// internal/event package.
+package log
+
+import (
+	"context"
+	"fmt"
+
+	"golang.org/x/tools/internal/event"
+	"golang.org/x/tools/internal/event/label"
+	"golang.org/x/tools/internal/lsp/debug/tag"
+)
+
+// Level parameterizes log severity.
+type Level int
+
+const (
+	_ Level = iota
+	Error
+	Warning
+	Info
+	Debug
+	Trace
+)
+
+// Log exports a log event labeled with level l.
+func (l Level) Log(ctx context.Context, msg string) {
+	event.Log(ctx, msg, tag.Level.Of(int(l)))
+}
+
+// Logf formats and exports a log event labeled with level l.
+func (l Level) Logf(ctx context.Context, format string, args ...interface{}) {
+	l.Log(ctx, fmt.Sprintf(format, args...))
+}
+
+// LabeledLevel extracts the labeled log l
+func LabeledLevel(lm label.Map) Level {
+	return Level(tag.Level.Get(lm))
+}

internal/lsp/debug/serve.go

@@ -11,7 +11,7 @@ import (
 	"fmt"
 	"html/template"
 	"io"
-	"log"
+	stdlog "log"
 	"net"
 	"net/http"
 	"net/http/pprof"
@@ -34,15 +34,19 @@ import (
 	"golang.org/x/tools/internal/event/keys"
 	"golang.org/x/tools/internal/event/label"
 	"golang.org/x/tools/internal/lsp/cache"
+	"golang.org/x/tools/internal/lsp/debug/log"
 	"golang.org/x/tools/internal/lsp/debug/tag"
 	"golang.org/x/tools/internal/lsp/protocol"
 	"golang.org/x/tools/internal/lsp/source"
 	errors "golang.org/x/xerrors"
 )
 
-type instanceKeyType int
+type contextKeyType int
 
-const instanceKey = instanceKeyType(0)
+const (
+	instanceKey contextKeyType = iota
+	traceKey
+)
 
 // An Instance holds all debug information associated with a gopls instance.
 type Instance struct {
@@ -373,7 +377,7 @@ func (i *Instance) SetLogFile(logfile string, isDaemon bool) (func(), error) {
 		closeLog = func() {
 			defer f.Close()
 		}
-		log.SetOutput(io.MultiWriter(os.Stderr, f))
+		stdlog.SetOutput(io.MultiWriter(os.Stderr, f))
 		i.LogWriter = f
 	}
 	i.Logfile = logfile
@@ -384,7 +388,7 @@ func (i *Instance) SetLogFile(logfile string, isDaemon bool) (func(), error) {
 // It also logs the port the server starts on, to allow for :0 auto assigned
 // ports.
 func (i *Instance) Serve(ctx context.Context) error {
-	log.SetFlags(log.Lshortfile)
+	stdlog.SetFlags(stdlog.Lshortfile)
 	if i.DebugAddress == "" {
 		return nil
 	}
@@ -396,7 +400,7 @@ func (i *Instance) Serve(ctx context.Context) error {
 
 	port := listener.Addr().(*net.TCPAddr).Port
 	if strings.HasSuffix(i.DebugAddress, ":0") {
-		log.Printf("debug server listening at http://localhost:%d", port)
+		stdlog.Printf("debug server listening at http://localhost:%d", port)
 	}
 	event.Log(ctx, "Debug serving", tag.Port.Of(port))
 	go func() {
@@ -520,15 +524,31 @@ func makeGlobalExporter(stderr io.Writer) event.Exporter {
 				p.WriteEvent(stderr, ev, lm)
 				pMu.Unlock()
 			}
+			level := log.LabeledLevel(lm)
+			// Exclude trace logs from LSP logs.
+			if level < log.Trace {
+				ctx = protocol.LogEvent(ctx, ev, lm, messageType(level))
+			}
 		}
-		ctx = protocol.LogEvent(ctx, ev, lm)
 		if i == nil {
 			return ctx
 		}
 		return i.exporter(ctx, ev, lm)
 	}
 }
 
+func messageType(l log.Level) protocol.MessageType {
+	switch l {
+	case log.Error:
+		return protocol.Error
+	case log.Warning:
+		return protocol.Warning
+	case log.Debug:
+		return protocol.Log
+	}
+	return protocol.Info
+}
+
 func makeInstanceExporter(i *Instance) event.Exporter {
 	exporter := func(ctx context.Context, ev core.Event, lm label.Map) context.Context {
 		if i.ocagent != nil {
@@ -573,6 +593,9 @@ func makeInstanceExporter(i *Instance) event.Exporter {
 		}
 		return ctx
 	}
+	// StdTrace must be above export.Spans below (by convention, export
+	// middleware applies its wrapped exporter last).
+	exporter = StdTrace(exporter)
 	metrics := metric.Config{}
 	registerMetrics(&metrics)
 	exporter = metrics.Exporter(exporter)

internal/lsp/debug/tag/tag.go

@@ -41,6 +41,8 @@ var (
 	DebugAddress = keys.NewString("debug_address", "")
 	GoplsPath    = keys.NewString("gopls_path", "")
 	ClientID     = keys.NewString("client_id", "")
+
+	Level = keys.NewInt("level", "The logging level")
 )
 
 var (

internal/lsp/debug/trace.go

@@ -10,6 +10,7 @@ import (
 	"fmt"
 	"html/template"
 	"net/http"
+	"runtime/trace"
 	"sort"
 	"strings"
 	"sync"
@@ -75,6 +76,48 @@ type traceEvent struct {
 	Tags   string
 }
 
+func StdTrace(exporter event.Exporter) event.Exporter {
+	return func(ctx context.Context, ev core.Event, lm label.Map) context.Context {
+		span := export.GetSpan(ctx)
+		if span == nil {
+			return exporter(ctx, ev, lm)
+		}
+		switch {
+		case event.IsStart(ev):
+			if span.ParentID.IsValid() {
+				region := trace.StartRegion(ctx, span.Name)
+				ctx = context.WithValue(ctx, traceKey, region)
+			} else {
+				var task *trace.Task
+				ctx, task = trace.NewTask(ctx, span.Name)
+				ctx = context.WithValue(ctx, traceKey, task)
+			}
+			// Log the start event as it may contain useful labels.
+			msg := formatEvent(ctx, ev, lm)
+			trace.Log(ctx, "start", msg)
+		case event.IsLog(ev):
+			category := ""
+			if event.IsError(ev) {
+				category = "error"
+			}
+			msg := formatEvent(ctx, ev, lm)
+			trace.Log(ctx, category, msg)
+		case event.IsEnd(ev):
+			if v := ctx.Value(traceKey); v != nil {
+				v.(interface{ End() }).End()
+			}
+		}
+		return exporter(ctx, ev, lm)
+	}
+}
+
+func formatEvent(ctx context.Context, ev core.Event, lm label.Map) string {
+	buf := &bytes.Buffer{}
+	p := export.Printer{}
+	p.WriteEvent(buf, ev, lm)
+	return buf.String()
+}
+
 func (t *traces) ProcessEvent(ctx context.Context, ev core.Event, lm label.Map) context.Context {
 	t.mu.Lock()
 	defer t.mu.Unlock()

internal/lsp/diagnostics.go

@@ -14,6 +14,7 @@ import (
 	"sync"
 
 	"golang.org/x/tools/internal/event"
+	"golang.org/x/tools/internal/lsp/debug/log"
 	"golang.org/x/tools/internal/lsp/debug/tag"
 	"golang.org/x/tools/internal/lsp/mod"
 	"golang.org/x/tools/internal/lsp/protocol"
@@ -74,6 +75,8 @@ func (s *Server) diagnoseDetached(snapshot source.Snapshot) {
 
 func (s *Server) diagnoseSnapshot(snapshot source.Snapshot, changedURIs []span.URI, onDisk bool) {
 	ctx := snapshot.BackgroundContext()
+	ctx, done := event.Start(ctx, "Server.diagnoseSnapshot", tag.Snapshot.Of(snapshot.ID()))
+	defer done()
 
 	delay := snapshot.View().Options().ExperimentalDiagnosticsDelay
 	if delay > 0 {
@@ -99,7 +102,7 @@ func (s *Server) diagnoseSnapshot(snapshot source.Snapshot, changedURIs []span.U
 }
 
 func (s *Server) diagnoseChangedFiles(ctx context.Context, snapshot source.Snapshot, uris []span.URI, onDisk bool) {
-	ctx, done := event.Start(ctx, "Server.diagnoseChangedFiles")
+	ctx, done := event.Start(ctx, "Server.diagnoseChangedFiles", tag.Snapshot.Of(snapshot.ID()))
 	defer done()
 	packages := make(map[source.Package]struct{})
 	for _, uri := range uris {
@@ -140,7 +143,7 @@ func (s *Server) diagnoseChangedFiles(ctx context.Context, snapshot source.Snaps
 // diagnose is a helper function for running diagnostics with a given context.
 // Do not call it directly. forceAnalysis is only true for testing purposes.
 func (s *Server) diagnose(ctx context.Context, snapshot source.Snapshot, forceAnalysis bool) {
-	ctx, done := event.Start(ctx, "Server.diagnose")
+	ctx, done := event.Start(ctx, "Server.diagnose", tag.Snapshot.Of(snapshot.ID()))
 	defer done()
 
 	// Wait for a free diagnostics slot.
@@ -156,6 +159,7 @@ func (s *Server) diagnose(ctx context.Context, snapshot source.Snapshot, forceAn
 	// First, diagnose the go.mod file.
 	modReports, modErr := mod.Diagnostics(ctx, snapshot)
 	if ctx.Err() != nil {
+		log.Trace.Log(ctx, "diagnose cancelled")
 		return
 	}
 	if modErr != nil {
@@ -238,6 +242,8 @@ func (s *Server) diagnose(ctx context.Context, snapshot source.Snapshot, forceAn
 }
 
 func (s *Server) diagnosePkg(ctx context.Context, snapshot source.Snapshot, pkg source.Package, alwaysAnalyze bool) {
+	ctx, done := event.Start(ctx, "Server.diagnosePkg", tag.Snapshot.Of(snapshot.ID()), tag.Package.Of(pkg.ID()))
+	defer done()
 	includeAnalysis := alwaysAnalyze // only run analyses for packages with open files
 	var gcDetailsDir span.URI        // find the package's optimization details, if available
 	for _, pgf := range pkg.CompiledGoFiles() {
@@ -439,8 +445,16 @@ func (s *Server) storeErrorDiagnostics(ctx context.Context, snapshot source.Snap
 
 // publishDiagnostics collects and publishes any unpublished diagnostic reports.
 func (s *Server) publishDiagnostics(ctx context.Context, final bool, snapshot source.Snapshot) {
+	ctx, done := event.Start(ctx, "Server.publishDiagnostics", tag.Snapshot.Of(snapshot.ID()))
+	defer done()
 	s.diagnosticsMu.Lock()
 	defer s.diagnosticsMu.Unlock()
+
+	published := 0
+	defer func() {
+		log.Trace.Logf(ctx, "published %d diagnostics", published)
+	}()
+
 	for uri, r := range s.diagnostics {
 		// Snapshot IDs are always increasing, so we use them instead of file
 		// versions to create the correct order for diagnostics.
@@ -491,6 +505,7 @@ func (s *Server) publishDiagnostics(ctx context.Context, final bool, snapshot so
 			URI:         protocol.URIFromSpanURI(uri),
 			Version:     version,
 		}); err == nil {
+			published++
 			r.publishedHash = hash
 			r.snapshotID = snapshot.ID()
 			for dsource, hash := range reportHashes {
@@ -501,6 +516,7 @@ func (s *Server) publishDiagnostics(ctx context.Context, final bool, snapshot so
 		} else {
 			if ctx.Err() != nil {
 				// Publish may have failed due to a cancelled context.
+				log.Trace.Log(ctx, "publish cancelled")
 				return
 			}
 			event.Error(ctx, "publishReports: failed to deliver diagnostic", err, tag.URI.Of(uri))

internal/lsp/protocol/context.go

@@ -21,18 +21,16 @@ func WithClient(ctx context.Context, client Client) context.Context {
 	return context.WithValue(ctx, clientKey, client)
 }
 
-func LogEvent(ctx context.Context, ev core.Event, tags label.Map) context.Context {
-	if !event.IsLog(ev) {
-		return ctx
-	}
+func LogEvent(ctx context.Context, ev core.Event, lm label.Map, mt MessageType) context.Context {
 	client, ok := ctx.Value(clientKey).(Client)
 	if !ok {
 		return ctx
 	}
 	buf := &bytes.Buffer{}
 	p := export.Printer{}
-	p.WriteEvent(buf, ev, tags)
-	msg := &LogMessageParams{Type: Info, Message: buf.String()}
+	p.WriteEvent(buf, ev, lm)
+	msg := &LogMessageParams{Type: mt, Message: buf.String()}
+	// Handle messages generated via event.Error, which won't have a level Label.
 	if event.IsError(ev) {
 		msg.Type = Error
 	}