matchiter: capture metric NgramLookups (#608)

This instruments our matchiter code to track how often is calls Get on
the underlying ngram index. We have some queries on long strings which
are going much slower than expected and we suspect it is related to the
work done here.

This change requires a few moving pieces:
- Adding the int to Stats
- Instrumenting places we log/emit Stats
- grpc support
- capturing this work in matchiter code
- updating tests to ensure correctness

The last two points are the meat of this commit, while the rest was
mechanical work. I reworked the TestAndSearch since into TestSearchStats
since it was the only test which had useful assertions on Stats.

I was surprised to see how high the ngram lookup values were for such
simple queries. This makes me more confident in improving our
performance here.

Test Plan: go test

Author: keegancsmith

api.go

@@ -382,6 +382,9 @@ type Stats struct {
 	// Number of candidate matches as a result of searching ngrams.
 	NgramMatches int
 
+	// NgramLookups is the number of times we accessed an ngram in the index.
+	NgramLookups int
+
 	// Wall clock time for queued search.
 	Wait time.Duration
 
@@ -409,6 +412,7 @@ func (s *Stats) Add(o Stats) {
 	s.FilesSkipped += o.FilesSkipped
 	s.MatchCount += o.MatchCount
 	s.NgramMatches += o.NgramMatches
+	s.NgramLookups += o.NgramLookups
 	s.ShardFilesConsidered += o.ShardFilesConsidered
 	s.ShardsScanned += o.ShardsScanned
 	s.ShardsSkipped += o.ShardsSkipped
@@ -438,6 +442,7 @@ func (s *Stats) Zero() bool {
 		s.FilesSkipped > 0 ||
 		s.MatchCount > 0 ||
 		s.NgramMatches > 0 ||
+		s.NgramLookups > 0 ||
 		s.ShardFilesConsidered > 0 ||
 		s.ShardsScanned > 0 ||
 		s.ShardsSkipped > 0 ||

api_proto.go

@@ -297,6 +297,7 @@ func StatsFromProto(p *proto.Stats) Stats {
 		ShardsSkippedFilter:  int(p.GetShardsSkippedFilter()),
 		MatchCount:           int(p.GetMatchCount()),
 		NgramMatches:         int(p.GetNgramMatches()),
+		NgramLookups:         int(p.GetNgramLookups()),
 		Wait:                 p.GetWait().AsDuration(),
 		RegexpsConsidered:    int(p.GetRegexpsConsidered()),
 		FlushReason:          FlushReasonFromProto(p.GetFlushReason()),
@@ -319,6 +320,7 @@ func (s *Stats) ToProto() *proto.Stats {
 		ShardsSkippedFilter:  int64(s.ShardsSkippedFilter),
 		MatchCount:           int64(s.MatchCount),
 		NgramMatches:         int64(s.NgramMatches),
+		NgramLookups:         int64(s.NgramLookups),
 		Wait:                 durationpb.New(s.Wait),
 		RegexpsConsidered:    int64(s.RegexpsConsidered),
 		FlushReason:          s.FlushReason.ToProto(),

cmd/zoekt-webserver/main.go

@@ -594,6 +594,7 @@ func (s *loggedSearcher) log(ctx context.Context, q query.Q, opts *zoekt.SearchO
 		sglog.Int("stat.ShardsSkippedFilter", st.ShardsSkippedFilter),
 		sglog.Int("stat.MatchCount", st.MatchCount),
 		sglog.Int("stat.NgramMatches", st.NgramMatches),
+		sglog.Int("stat.NgramLookups", st.NgramLookups),
 		sglog.Duration("stat.Wait", st.Wait),
 	)
 }

deps.bzl

@@ -1256,13 +1256,7 @@ def go_dependencies():
         sum = "h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY=",
         version = "v0.2.0",
     )
-    go_repository(
-        name = "com_github_kylelemons_godebug",
-        build_file_proto_mode = "disable_global",
-        importpath = "github.com/kylelemons/godebug",
-        sum = "h1:RPNrshWIDI6G2gRW9EHilWtl7Z6Sb1BR0xunSBf0SNc=",
-        version = "v1.1.0",
-    )
+
     go_repository(
         name = "com_github_labstack_echo_v4",
         build_file_proto_mode = "disable_global",

eval.go

@@ -811,7 +811,7 @@ func (d *indexData) regexpToMatchTreeRecursive(r *syntax.Regexp, minTextSize int
 			}
 		}
 		if len(qs) == 0 {
-			return &noMatchTree{"const"}, isEq, false, nil
+			return &noMatchTree{Why: "const"}, isEq, false, nil
 		}
 		return &orMatchTree{qs}, isEq, false, nil
 	case syntax.OpStar:

go.mod

@@ -18,7 +18,6 @@ require (
 	github.com/hashicorp/go-retryablehttp v0.7.2
 	github.com/keegancsmith/rpc v1.3.0
 	github.com/keegancsmith/tmpfriend v0.0.0-20180423180255-86e88902a513
-	github.com/kylelemons/godebug v1.1.0
 	github.com/mxk/go-flowrate v0.0.0-20140419014527-cca7078d478f
 	github.com/opentracing/opentracing-go v1.2.0
 	github.com/peterbourgon/ff/v3 v3.3.0
@@ -34,6 +33,7 @@ require (
 	github.com/uber/jaeger-lib v2.4.1+incompatible
 	github.com/xanzy/go-gitlab v0.80.0
 	github.com/xeipuuv/gojsonschema v1.2.0
+	go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc v0.39.0
 	go.opentelemetry.io/contrib/propagators/jaeger v1.14.0
 	go.opentelemetry.io/contrib/propagators/ot v1.14.0
 	go.opentelemetry.io/otel v1.13.0
@@ -115,7 +115,6 @@ require (
 	github.com/xeipuuv/gojsonreference v0.0.0-20180127040603-bd5ef7bd5415 // indirect
 	github.com/yusufpapurcu/wmi v1.2.2 // indirect
 	go.opencensus.io v0.24.0 // indirect
-	go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc v0.39.0 // indirect
 	go.opentelemetry.io/otel/exporters/otlp/internal/retry v1.13.0 // indirect
 	go.opentelemetry.io/otel/metric v0.36.0 // indirect
 	go.opentelemetry.io/proto/otlp v0.19.0 // indirect

go.sum

@@ -344,8 +344,6 @@ github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
 github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI=
 github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY=
 github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE=
-github.com/kylelemons/godebug v1.1.0 h1:RPNrshWIDI6G2gRW9EHilWtl7Z6Sb1BR0xunSBf0SNc=
-github.com/kylelemons/godebug v1.1.0/go.mod h1:9/0rRGxNHcop5bhtWyNeEfOS8JIWk580+fNqagV/RAw=
 github.com/labstack/echo/v4 v4.5.0/go.mod h1:czIriw4a0C1dFun+ObrXp7ok03xON0N1awStJ6ArI7Y=
 github.com/labstack/gommon v0.3.0/go.mod h1:MULnywXg0yavhxWKc+lOruYdAhDwPK9wf0OL7NoOu+k=
 github.com/lufia/plan9stats v0.0.0-20211012122336-39d0f177ccd0/go.mod h1:zJYVVT2jmtg6P3p1VtQj7WsuWi/y4VnjVBn7F8KPB3I=