diff --git a/client/go/internal/cli/cmd/inspect.go b/client/go/internal/cli/cmd/inspect.go index baa9d469b455..8212cc95fa9c 100644 --- a/client/go/internal/cli/cmd/inspect.go +++ b/client/go/internal/cli/cmd/inspect.go @@ -23,20 +23,34 @@ func inspectProfile(cli *CLI, opts *inspectProfileOptions) error { if !root.Valid() { return fmt.Errorf("profile file '%s' does not contain valid JSON", opts.profileFile) } - var cnt int - var maxTime float64 - var maxTrace *tracedoctor.ProtonTrace = nil - for _, trace := range tracedoctor.FindProtonTraces(root.Field("trace")) { - cnt++ - if trace.DurationMs > maxTime { - maxTime = trace.DurationMs - maxTrace = trace + list := tracedoctor.FindProtonTraces(root.Field("trace")) + if len(list) == 0 { + return fmt.Errorf("could not locate any searches in profile(%s)", opts.profileFile) + } + var mp int = -1 + for i, p := range list { + if mp < 0 || p.DurationMs() > list[mp].DurationMs() { + mp = i + } + } + fmt.Fprintf(cli.Stdout, "found %d searches, slowest search was: %s[%d]: %10.3f ms\n", + len(list), list[mp].DocumentType(), list[mp].DistributionKey(), list[mp].DurationMs()) + threads := list[mp].FindThreadTraces() + if len(threads) == 0 { + return fmt.Errorf("search thread information is missing from profile(%s)", opts.profileFile) + } + var mt int = -1 + for i, t := range threads { + if mt < 0 || t.MatchTimeMs() > threads[mt].MatchTimeMs() { + mt = i } } - if maxTrace != nil { - fmt.Fprintf(cli.Stdout, "found %d searches, slowest search was: %s[%d]: %10.3f ms\n", - cnt, maxTrace.DocumentType, maxTrace.DistributionKey, maxTrace.DurationMs) - return maxTrace.MatchProfiling().Render(cli.Stdout) + fmt.Fprintf(cli.Stdout, "found %d threads, slowest matching was thread #%d: %10.3f ms\n", + len(threads), mt, threads[mt].MatchTimeMs()) + queryPerf := list[mp].ExtractQuery() + queryPerf.ImportMatchPerf(threads[mt]) + if err := queryPerf.Render(cli.Stdout); err != nil { + return err } return nil } diff --git a/client/go/internal/cli/cmd/query.go b/client/go/internal/cli/cmd/query.go index deccf6722687..d62ae34062ff 100644 --- a/client/go/internal/cli/cmd/query.go +++ b/client/go/internal/cli/cmd/query.go @@ -118,6 +118,7 @@ func query(cli *CLI, arguments []string, opts *queryOptions, waiter *Waiter) err urlQuery.Set("trace.level", "1") urlQuery.Set("trace.explainLevel", "1") urlQuery.Set("trace.profiling.matching.depth", "100") + urlQuery.Set("presentation.timing", "true") } queryTimeout := urlQuery.Get("timeout") if queryTimeout == "" { diff --git a/client/go/internal/vespa/slime/leaf_test.go b/client/go/internal/vespa/slime/leaf_test.go index 25fc5c433190..2cd89cd0c156 100644 --- a/client/go/internal/vespa/slime/leaf_test.go +++ b/client/go/internal/vespa/slime/leaf_test.go @@ -74,3 +74,14 @@ func TestData(t *testing.T) { checkLeaf(t, Data([]byte{1, 2, 3}), expectLeaf{mytype: DATA, dataVal: []byte{1, 2, 3}}) checkLeaf(t, Data([]byte{5, 6}), expectLeaf{mytype: DATA, dataVal: []byte{5, 6}}) } + +func TestValidMultiPredicate(t *testing.T) { + a := Invalid + b := Bool(true) + c := Long(42) + assert.False(t, Valid(a, b, c)) + assert.False(t, Valid(b, a, c)) + assert.True(t, Valid(b, c)) + assert.True(t, Valid(c)) + assert.True(t, Valid()) +} diff --git a/client/go/internal/vespa/slime/path.go b/client/go/internal/vespa/slime/path.go index f8c632c13ce9..a99a8907b14d 100644 --- a/client/go/internal/vespa/slime/path.go +++ b/client/go/internal/vespa/slime/path.go @@ -111,9 +111,8 @@ func (p *Path) Clone() *Path { return &Path{slices.Clone(p.list)} } -func Find(value Value, pred func(path *Path, value Value) bool) []*Path { +func Select(value Value, pred func(p *Path, v Value) bool, handle func(p *Path, v Value)) { path := NewPath() - var result []*Path var process func(value Value) perEntry := func(idx int, value Value) { path.Entry(idx) @@ -127,12 +126,19 @@ func Find(value Value, pred func(path *Path, value Value) bool) []*Path { } process = func(value Value) { if pred(path, value) { - result = append(result, path.Clone()) + handle(path, value) return } value.EachEntry(perEntry) value.EachField(perField) } process(value) +} + +func Find(value Value, pred func(path *Path, value Value) bool) []*Path { + var result []*Path + Select(value, pred, func(p *Path, v Value) { + result = append(result, p.Clone()) + }) return result } diff --git a/client/go/internal/vespa/slime/path_test.go b/client/go/internal/vespa/slime/path_test.go index 3e1535cd521f..21a9fa9f0292 100644 --- a/client/go/internal/vespa/slime/path_test.go +++ b/client/go/internal/vespa/slime/path_test.go @@ -105,3 +105,17 @@ func TestFindMultipleFields(t *testing.T) { verifyArray([]verifyValue{verifyLong(9), verifyLong(10)})(t, arr2) verifyArray([]verifyValue{verifyLong(3), verifyLong(4), verifyLong(5)})(t, arr3) } + +func TestSelectProcessing(t *testing.T) { + pred := func(p *Path, v Value) bool { return p.At(-1).WouldSelectField("y") } + handle := func(p *Path, v Value) { + assert.True(t, p.At(-1).WouldSelectField("y")) + if v.NumEntries() == 2 { + verifyArray([]verifyValue{verifyLong(9), verifyLong(10)})(t, v) + } else { + assert.Equal(t, 3, v.NumEntries()) + verifyArray([]verifyValue{verifyLong(3), verifyLong(4), verifyLong(5)})(t, v) + } + } + Select(createComplexValue(t), pred, handle) +} diff --git a/client/go/internal/vespa/tracedoctor/extract.go b/client/go/internal/vespa/tracedoctor/extract.go index bf4cdb98e033..2fd7aeb24480 100644 --- a/client/go/internal/vespa/tracedoctor/extract.go +++ b/client/go/internal/vespa/tracedoctor/extract.go @@ -204,24 +204,10 @@ func (q *queryNode) applySample(sample slime.Value) { } } -type ProtonTrace struct { - DistributionKey int64 - DocumentType string - DurationMs float64 - Root slime.Value - Query slime.Value -} - -func findField(node slime.Value, fieldName string) []*slime.Path { - return slime.Find(node, func(path *slime.Path, value slime.Value) bool { - return path.At(-1).WouldSelectField(fieldName) - }) -} - -func findTagged(node slime.Value, tag string) []*slime.Path { - return slime.Find(node, func(path *slime.Path, value slime.Value) bool { - return value.Field("tag").AsString() == tag - }) +func hasTag(tag string) func(p *slime.Path, v slime.Value) bool { + return func(p *slime.Path, v slime.Value) bool { + return v.Field("tag").AsString() == tag + } } func eachSampleList(list slime.Value, f func(sample slime.Value)) { @@ -235,33 +221,71 @@ func eachSample(prof slime.Value, f func(sample slime.Value)) { eachSampleList(prof.Field("roots"), f) } -func (pt *ProtonTrace) MatchProfiling() *queryNode { - queryRoot := extractQueryNode(pt.Query) - for _, profPath := range findTagged(pt.Root, "match_profiling") { - prof := profPath.Apply(pt.Root) - if prof.Field("profiler").AsString() == "tree" { - eachSample(prof, func(sample slime.Value) { - if sampleType(sample) == "seek" { - queryRoot.applySample(sample) +func (q *queryNode) ImportMatchPerf(t ThreadTrace) { + slime.Select(t.root, hasTag("match_profiling"), func(p *slime.Path, v slime.Value) { + if v.Field("profiler").AsString() == "tree" { + eachSample(v, func(sample slime.Value) { + if sampleType(sample) != "unknown" { + q.applySample(sample) } }) } + }) +} + +type ThreadTrace struct { + root slime.Value +} + +func (t ThreadTrace) MatchTimeMs() float64 { + p := slime.Find(t.root, hasTag("match_profiling")) + if len(p) == 1 { + return p[0].Apply(t.root).Field("total_time_ms").AsDouble() } - return queryRoot + return 0.0 } -func FindProtonTraces(root slime.Value) []*ProtonTrace { - var traces []*ProtonTrace - for _, path := range findField(root, "optimized") { - node := path.Clone().Trim(3).Apply(root) - distKey := node.Field("distribution-key") - docType := node.Field("document-type") - duration := node.Field("duration_ms") - if slime.Valid(distKey, docType, duration) { - traces = append(traces, &ProtonTrace{distKey.AsLong(), - docType.AsString(), - duration.AsDouble(), node, path.Apply(root)}) - } +type ProtonTrace struct { + root slime.Value +} + +func (p ProtonTrace) FindThreadTraces() []ThreadTrace { + var traces []ThreadTrace + slime.Select(p.root, hasTag("query_execution"), func(p *slime.Path, v slime.Value) { + v.Field("threads").EachEntry(func(idx int, v slime.Value) { + traces = append(traces, ThreadTrace{v}) + }) + }) + return traces +} + +func (p ProtonTrace) ExtractQuery() *queryNode { + query := slime.Invalid + plan := slime.Find(p.root, hasTag("query_execution_plan")) + if len(plan) == 1 { + query = plan[0].Apply(p.root).Field("optimized") } + return extractQueryNode(query) +} + +func (p ProtonTrace) DistributionKey() int64 { + return p.root.Field("distribution-key").AsLong() +} + +func (p ProtonTrace) DocumentType() string { + return p.root.Field("document-type").AsString() +} + +func (p ProtonTrace) DurationMs() float64 { + return p.root.Field("duration_ms").AsDouble() +} + +func FindProtonTraces(root slime.Value) []ProtonTrace { + var traces []ProtonTrace + slime.Select(root, func(p *slime.Path, v slime.Value) bool { + return slime.Valid(v.Field("distribution-key"), v.Field("document-type"), v.Field("duration_ms")) + }, func(p *slime.Path, v slime.Value) { + traces = append(traces, ProtonTrace{v}) + }) return traces }