Merge pull request #33268 from vespa-engine/havardpe/select-slowest-search-thread

select slowest search thread in vespa inspect profile

Author: toregge

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
 }

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 == "" {

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())
+}

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
 }

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)
+}

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
 }