fork of https://github.com/sourcegraph/zoekt
fix tracing (#627)
In #187 we collapsed the spans which caused all the LazyPrintf in defer
statements to be dropped.
In this PR I revert #187, deduplicate trace logs (EG we logged "num
files" and `opts` in multiple places) and log `stats` in streaming
search.
Test plan:
I confirmed locally that the logs show up as expected.
author
Stefan Hengl
committer
GitHub
date
(Jul 28, 2023, 6:39 PM +0200)
commit
9c20a034
9c20a034e01451ae943c46a584c713c57ed4e8b1
parent
0f6564bd
0f6564bdb9e8307d8edf66688434e05d3bf14b95
+23
-31
+16
-4
shards/eval.go
+16
-4
shards/eval.go
···
5
5
6
6
"github.com/sourcegraph/zoekt"
7
7
"github.com/sourcegraph/zoekt/query"
8
+
"github.com/sourcegraph/zoekt/stream"
8
9
"github.com/sourcegraph/zoekt/trace"
9
10
)
10
11
···
43
44
tr, ctx := trace.New(ctx, "typeRepoSearcher.StreamSearch", "")
44
45
tr.LazyLog(q, true)
45
46
tr.LazyPrintf("opts: %+v", opts)
47
+
var stats *zoekt.Stats
46
48
defer func() {
49
+
tr.LazyPrintf("stats: %+v", stats)
47
50
if err != nil {
48
51
tr.LazyPrintf("error: %v", err)
49
52
tr.SetError(err)
···
56
59
return err
57
60
}
58
61
62
+
if opts.Trace {
63
+
stats = &zoekt.Stats{}
64
+
return s.Streamer.StreamSearch(ctx, q, opts, stream.SenderFunc(func(event *zoekt.SearchResult) {
65
+
stats.Add(event.Stats)
66
+
sender.Send(event)
67
+
}))
68
+
}
69
+
59
70
return s.Streamer.StreamSearch(ctx, q, opts, sender)
60
71
}
61
72
62
-
func (s *typeRepoSearcher) List(ctx context.Context, r query.Q, opts *zoekt.ListOptions) (rl *zoekt.RepoList, err error) {
73
+
func (s *typeRepoSearcher) List(ctx context.Context, q query.Q, opts *zoekt.ListOptions) (rl *zoekt.RepoList, err error) {
63
74
tr, ctx := trace.New(ctx, "typeRepoSearcher.List", "")
64
-
tr.LazyLog(r, true)
75
+
tr.LazyLog(q, true)
65
76
tr.LazyPrintf("opts: %s", opts)
66
77
defer func() {
67
78
if rl != nil {
68
79
tr.LazyPrintf("repos size: %d", len(rl.Repos))
69
80
tr.LazyPrintf("crashes: %d", rl.Crashes)
70
81
tr.LazyPrintf("minimal size : %d", len(rl.Minimal))
82
+
tr.LazyPrintf("stats: %+v", rl.Stats)
71
83
}
72
84
if err != nil {
73
85
tr.LazyPrintf("error: %v", err)
···
76
88
tr.Finish()
77
89
}()
78
90
79
-
r, err = s.eval(ctx, r)
91
+
q, err = s.eval(ctx, q)
80
92
if err != nil {
81
93
return nil, err
82
94
}
83
95
84
-
return s.Streamer.List(ctx, r, opts)
96
+
return s.Streamer.List(ctx, q, opts)
85
97
}
86
98
87
99
func (s *typeRepoSearcher) eval(ctx context.Context, q query.Q) (query.Q, error) {
-8
shards/shards.go
-8
shards/shards.go
···
487
487
func (ss *shardedSearcher) Search(ctx context.Context, q query.Q, opts *zoekt.SearchOptions) (sr *zoekt.SearchResult, err error) {
488
488
tr, ctx := trace.New(ctx, "shardedSearcher.Search", "")
489
489
defer func() {
490
-
if sr != nil {
491
-
tr.LazyPrintf("num files: %d", len(sr.Files))
492
-
tr.LazyPrintf("stats: %+v", sr.Stats)
493
-
}
494
490
tr.Finish()
495
491
}()
496
492
ctx, cancel := context.WithCancel(ctx)
···
618
614
// SearchResults it returns/streams out before calling done.
619
615
func streamSearch(ctx context.Context, proc *process, q query.Q, opts *zoekt.SearchOptions, shards []*rankedShard, sender zoekt.Sender) (done func(), err error) {
620
616
tr, ctx := trace.New(ctx, "shardedSearcher.streamSearch", "")
621
-
tr.LazyLog(q, true)
622
-
tr.LazyPrintf("opts: %+v", opts)
623
617
overallStart := time.Now()
624
618
metricSearchRunning.Inc()
625
619
defer func() {
···
897
891
898
892
func (ss *shardedSearcher) List(ctx context.Context, r query.Q, opts *zoekt.ListOptions) (rl *zoekt.RepoList, err error) {
899
893
tr, ctx := trace.New(ctx, "shardedSearcher.List", "")
900
-
tr.LazyLog(r, true)
901
-
tr.LazyPrintf("opts: %s", opts)
902
894
metricListRunning.Inc()
903
895
defer func() {
904
896
metricListRunning.Dec()
+7
-19
trace/trace.go
+7
-19
trace/trace.go
···
31
31
32
32
// New returns a new Trace with the specified family and title.
33
33
func (t Tracer) New(ctx context.Context, family, title string) (*Trace, context.Context) {
34
-
// In Zoekt child OpenTracing Spans don't really make much sense since all
35
-
// our spans are either middleware which just wrap an actual search, or the
36
-
// actual search. So we only create a new span if there is no parent.
37
-
parent := TraceFromContext(ctx)
38
-
var span opentracing.Span
39
-
if parent != nil {
40
-
span = parent.span
41
-
span.LogFields(log.String("child.family", family), log.String("child.title", title))
42
-
} else {
43
-
span, ctx = StartSpanFromContextWithTracer(
44
-
ctx,
45
-
t.Tracer,
46
-
family,
47
-
opentracing.Tag{Key: "title", Value: title},
48
-
)
49
-
}
50
-
34
+
span, ctx := StartSpanFromContextWithTracer(
35
+
ctx,
36
+
t.Tracer,
37
+
family,
38
+
opentracing.Tag{Key: "title", Value: title},
39
+
)
51
40
tr := nettrace.New(family, title)
52
41
trace := &Trace{span: span, trace: tr, family: family}
53
-
if parent != nil {
42
+
if parent := TraceFromContext(ctx); parent != nil {
54
43
tr.LazyPrintf("parent: %s", parent.family)
55
44
trace.family = parent.family + " > " + family
56
45
}
57
-
58
46
return trace, ContextWithTrace(ctx, trace)
59
47
}
60
48