x/net/trace support for Searcher List and Search

This adds support for the trace package. When visiting `/debug/requests` you are
presented with useful log and timing information of the requests handled by
shardedSearcher and indexData.

Change-Id: I31c7445f918237495a6089d15899d1a2d99312da

cmd/zoekt-webserver/main.go

@@ -29,6 +29,8 @@ import (
 	"strings"
 	"time"
 
+	"golang.org/x/net/trace"
+
 	"github.com/google/zoekt/build"
 	"github.com/google/zoekt/shards"
 	"github.com/google/zoekt/web"
@@ -184,6 +186,8 @@ func main() {
 		handler.HandleFunc("/debug/pprof/profile", pprof.Profile)
 		handler.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
 		handler.HandleFunc("/debug/pprof/trace", pprof.Trace)
+		handler.HandleFunc("/debug/requests/", trace.Traces)
+		handler.HandleFunc("/debug/events/", trace.Events)
 	}
 
 	watchdogAddr := "http://" + *listen

eval.go

@@ -23,6 +23,8 @@ import (
 	"strings"
 	"unicode/utf8"
 
+	"golang.org/x/net/trace"
+
 	"github.com/google/zoekt/query"
 )
 
@@ -599,7 +601,7 @@ func (o *SearchOptions) SetDefaults() {
 	}
 }
 
-func (d *indexData) Search(ctx context.Context, q query.Q, opts *SearchOptions) (*SearchResult, error) {
+func (d *indexData) Search(ctx context.Context, q query.Q, opts *SearchOptions) (sr *SearchResult, err error) {
 	copyOpts := *opts
 	opts = &copyOpts
 	opts.SetDefaults()
@@ -610,7 +612,22 @@ func (d *indexData) Search(ctx context.Context, q query.Q, opts *SearchOptions)
 		return &res, nil
 	}
 
+	tr := trace.New("indexData.Search", d.file.Name())
+	tr.LazyPrintf("opts: %+v", opts)
+	defer func() {
+		if sr != nil {
+			tr.LazyPrintf("num files: %d", len(sr.Files))
+			tr.LazyPrintf("stats: %+v", sr.Stats)
+		}
+		if err != nil {
+			tr.LazyPrintf("error: %v", err)
+			tr.SetError()
+		}
+		tr.Finish()
+	}()
+
 	q = d.simplify(q)
+	tr.LazyLog(q, true)
 	if c, ok := q.(*query.Const); ok && !c.Value {
 		return &res, nil
 	}
@@ -945,8 +962,22 @@ func (d *indexData) gatherBranches(docID uint32, mt matchTree, known map[matchTr
 	return branches
 }
 
-func (d *indexData) List(ctx context.Context, q query.Q) (*RepoList, error) {
+func (d *indexData) List(ctx context.Context, q query.Q) (rl *RepoList, err error) {
+	tr := trace.New("indexData.List", d.file.Name())
+	defer func() {
+		if rl != nil {
+			tr.LazyPrintf("repos size: %d", len(rl.Repos))
+			tr.LazyPrintf("crashes: %d", rl.Crashes)
+		}
+		if err != nil {
+			tr.LazyPrintf("error: %v", err)
+			tr.SetError()
+		}
+		tr.Finish()
+	}()
+
 	q = d.simplify(q)
+	tr.LazyLog(q, true)
 	c, ok := q.(*query.Const)
 
 	if !ok {

shards/shards.go

@@ -24,6 +24,7 @@ import (
 	"sort"
 	"time"
 
+	"golang.org/x/net/trace"
 	"golang.org/x/sync/semaphore"
 
 	"github.com/google/zoekt"
@@ -101,7 +102,22 @@ func (ss *shardedSearcher) Close() {
 	}
 }
 
-func (ss *shardedSearcher) Search(ctx context.Context, pat query.Q, opts *zoekt.SearchOptions) (*zoekt.SearchResult, error) {
+func (ss *shardedSearcher) Search(ctx context.Context, pat query.Q, opts *zoekt.SearchOptions) (sr *zoekt.SearchResult, err error) {
+	tr := trace.New("shardedSearcher.Search", "")
+	tr.LazyLog(pat, true)
+	tr.LazyPrintf("opts: %+v", opts)
+	defer func() {
+		if sr != nil {
+			tr.LazyPrintf("num files: %d", len(sr.Files))
+			tr.LazyPrintf("stats: %+v", sr.Stats)
+		}
+		if err != nil {
+			tr.LazyPrintf("error: %v", err)
+			tr.SetError()
+		}
+		tr.Finish()
+	}()
+
 	start := time.Now()
 	type res struct {
 		sr  *zoekt.SearchResult
@@ -119,6 +135,7 @@ func (ss *shardedSearcher) Search(ctx context.Context, pat query.Q, opts *zoekt.
 		return aggregate, err
 	}
 	defer ss.runlock()
+	tr.LazyPrintf("acquired lock")
 	aggregate.Wait = time.Now().Sub(start)
 	start = time.Now()
 
@@ -189,7 +206,21 @@ func (ss *shardedSearcher) Search(ctx context.Context, pat query.Q, opts *zoekt.
 	return aggregate, nil
 }
 
-func (ss *shardedSearcher) List(ctx context.Context, r query.Q) (*zoekt.RepoList, error) {
+func (ss *shardedSearcher) List(ctx context.Context, r query.Q) (rl *zoekt.RepoList, err error) {
+	tr := trace.New("shardedSearcher.List", "")
+	tr.LazyLog(r, true)
+	defer func() {
+		if rl != nil {
+			tr.LazyPrintf("repos size: %d", len(rl.Repos))
+			tr.LazyPrintf("crashes: %d", rl.Crashes)
+		}
+		if err != nil {
+			tr.LazyPrintf("error: %v", err)
+			tr.SetError()
+		}
+		tr.Finish()
+	}()
+
 	type res struct {
 		rl  *zoekt.RepoList
 		err error
@@ -199,10 +230,12 @@ func (ss *shardedSearcher) List(ctx context.Context, r query.Q) (*zoekt.RepoList
 		return nil, err
 	}
 	defer ss.runlock()
+	tr.LazyPrintf("acquired lock")
 
 	shards := ss.getShards()
 	shardCount := len(shards)
 	all := make(chan res, shardCount)
+	tr.LazyPrintf("shardCount: %d", len(shards))
 
 	for _, s := range shards {
 		go func(s zoekt.Searcher) {