Search getting timed out - intermittently

Hi Team,
After ingesting good amount of data in a multi node cluster (1 config server, 3 container and 6 content node), it is observed that requests get timed out on first hit for few and on second hit it retrieves the result.
http://<Http proxy (created on container service @8080)>/search/
Error: code:12, summary:Timed out, message: summary data is incomplete: Timed out for summary data, 1 response is outstanding.
or
Error: code:12, summary:Timed out, source:music, message: BAckend communication timed out in all nodes in a  group (distribution keys: 1,3,5,4,2,0): No Time left to get summaries, query timeout was 499ms
Could you please explain the reason for this behaviour.
Also, where and how are these (query timeout or other NFR's) SLA's set. Can you please guide how and where to set these SLA's.

You can override the request timeout on a per query basis.
The default value of 500ms is configured here https://docs.vespa.ai/en/reference/services-content.html#query-timeout
Also https://docs.vespa.ai/documentation/graceful-degradation.html is relevant.
The overall search request is at least two phased

First protocol phase find the matching documents
Second protocol phase also called summary fetch phase fetches the content of documents for display from the nodes which produces the best hits.

The last protocol phase could timeout if the first took too long time or if the phase itself took too long time.

Thank you for guiding me to setting timeout. Few more observations are stated below.
With client timeout and request timeout is set to 10s, I ran load test for search request and noticed below response

Actual data is not returned for the query eventhough data is present. The response code for it is 200 and response time was within 10s.

Response body
{"root":{"id":"toplevel","relevance":1.0,"fields":{"totalCount":0},"coverage":{"coverage":100,"documents":284302693,"full":true,"nodes":6,"results":2,"resultsFull":2},"children":[{"id":"test","relevance":1.0}]}}
{"root":{"id":"toplevel","relevance":1.0,"fields":{"totalCount":0},"coverage":{"coverage":84,"documents":225926852,"degraded":{"match-phase":false,"timeout":true,"adaptive-timeout":false,"non-ideal-state":false},"full":false,"nodes":6,"results":2,"resultsFull":1},"children":[{"id":"test","relevance":1.0}]}}
I then verified by hittig the search url on other client like browser/postman and was able to get the data.
Is this a valid scenario where we get data on multiple hits even though query is not timed out and document exists.
Also, I did a small test by hitting search url for single document via postman for multiple times and it kept giving below response body on alternate hits, where on one hit I got data and on other hit I did not.
Search url
http://<proxy url on container node service at 8080>/search/
POST
{
"yql":"select * from sources * where album contains "177802091";","timeout": "10s"
}
Hit 1:  Data not available in response body. Query time 1213ms
{
"root": {
"id": "toplevel",
"relevance": 1.0,
"fields": {
"totalCount": 0
},
"coverage": {
"coverage": 100,
"documents": 268564199,
"full": true,
"nodes": 6,
"results": 2,
"resultsFull": 2
},
"children": [
{
"id": "test",
"relevance": 1.0
}
]
}
Hit 2: Data returned in response body. Query time 76ms
{
"root": {
"id": "toplevel",
"relevance": 1.0,
"fields": {
"totalCount": 1
},
"coverage": {
"coverage": 100,
"documents": 294714750,
"full": true,
"nodes": 6,
"results": 2,
"resultsFull": 2
},
"children": [
{
"id": "test",
"relevance": 1.0
},
{
"id": "id:mynamespace:music::177802091",
"relevance": 0.11322686356149855,
"source": "music",
"fields": {
"sddocname": "music",
"documentid": "id:mynamespace:music::177802091",
"artist": "ABCD",
"album": "177802091",
"year": 2001
}
}
]
}
}

The below are the actual cases of timeout where it took more than 10s

{"root":{"id":"toplevel","relevance":1.0,"fields":{"totalCount":0},"coverage":{"coverage":67,"documents":136857508,"degraded":{"match-phase":false,"timeout":true,"adaptive-timeout":false,"non-ideal-state":false},"full":false,"nodes":2,"results":2,"resultsFull":1},"errors":[{"code":12,"summary":"Timed out","source":"music","message":"Backend communication timeout on all nodes in group (distribution-keys: 5, 4, 3)"}],"children":[{"id":"test","relevance":1.0}]}}
{"root":{"id":"toplevel","relevance":1.0,"fields":{"totalCount":1},"coverage":{"coverage":67,"documents":136857508,"degraded":{"match-phase":false,"timeout":true,"adaptive-timeout":false,"non-ideal-state":false},"full":false,"nodes":2,"results":2,"resultsFull":1},"errors":[{"code":12,"summary":"Timed out","source":"music","message":"Backend communication timeout on all nodes in group (distribution-keys: 0, 2, 1)"},{"code":12,"summary":"Timed out","source":"music","message":"No time left to get summaries, query timeout was 10000 ms"}],"children":[{"id":"test","relevance":1.0},{"id":"index:music/1/2877537e5800cef2f56da618","relevance":0.11322686356149855,"source":"music"}]}}

See https://docs.vespa.ai/documentation/graceful-degradation.html, some formatting of your comment would also help us read it.

See https://docs.vespa.ai/documentation/graceful-degradation.html, some formatting of your comment would also help us read it.

Thank you for reply!!!
I went through the mentioned url but my used case is not there.
The issue I am stating is, even if coverage is 100, query returns response well within set query timeout(10s) as 200 OK without the actual data.
{   "root":{       "id":"toplevel",       "relevance":1.0,       "fields":{          "totalCount":0       },       "coverage":{          "coverage":100,          "documents":284302693,          "full":true,          "nodes":6,          "results":2,          "resultsFull":2       },       "children":[          {             "id":"test",             "relevance":1.0          }       ]    } }
Also to verify this behaviour, I just picked one doc and kept hitting. On one hit it returned coverage 100, response 200 OK with no data in response body while on another hit it returned data and trend continued with further hit.
Search url
http://<proxy url on container node service at 8080>/search/
POST
{
"yql":"select * from sources * where album contains "177802091";","timeout": "10s"
}
Hit 1: Data not available in response body. Query time 1213ms
{    "root":{       "id":"toplevel",       "relevance":1.0,       "fields":{          "totalCount":0       },       "coverage":{          "coverage":100,          "documents":268564199,          "full":true,          "nodes":6,          "results":2,          "resultsFull":2       },       "children":[          {             "id":"test",             "relevance":1.0          }       ]    } }
Hit 2: Data returned in response body. Query time 76ms
{    "root":{       "id":"toplevel",       "relevance":1.0,       "fields":{          "totalCount":1       },       "coverage":{          "coverage":100,          "documents":294714750,          "full":true,          "nodes":6,          "results":2,          "resultsFull":2       },       "children":[          {             "id":"test",             "relevance":1.0          },          {             "id":"id:mynamespace:music::177802091",             "relevance":0.11322686356149855,             "source":"music",             "fields":{                "sddocname":"music",                "documentid":"id:mynamespace:music::177802091",                "artist":"ABCD",                "album":"177802091",                "year":2001             }          }       ]    } }

Could you add &tracelevel=3&trace.timestamps to the request? This will enable tracing end to end. You got some odd thing going here, the document searched is off, the first also have totalCount=0. Also notice that you have two results which means federation two two document types?

Could you add &tracelevel=3&trace.timestamps to the request? This will enable tracing end to end. You got some odd thing going here, the document searched is off, the first also have totalCount=0. Also notice that you have two results which means federation two two document types?

Thanks for the suggestion.
The above issue with inconsistent search is observed when we migrated from flat distribution to group distribution.
Updated search query with "tracelevel": 3,"trace.timestamps": "true" and compared both.

Search query with no data - it searched for data 2 times each in distribution-key-3,distribution-key-4,distribution-key-5
and Search query with data - it searched for data 2 times each in distribution-key-0,distribution-key-1,distribution-key-2

below trace is available in response body of search query returing data post Return searcher 'com.yahoo.search.querytransform.NGramSearcher in music

{     "timestamp": 178,     "message": "sc0.num0 fill to dispatch: query=[album:231804170] timeout=9991ms offset=0 hits=10 groupingSessionCache=true sessionId=qrserver.0.1621499804110.6.default grouping=0 :  restrict=[music] summary=[null]" }, {     "timestamp": 178,     "message": "Current state of query tree: WORD[connectedItem=null connectivity=0.0 creator=ORIG explicitSignificance=false fromSegmented=false index=\"album\" isRanked=true origin=null segmentIndex=0 significance=0.0 stemmed=true uniqueID=1 usePositionData=true weight=100 words=true]{\n  \"231804170\"\n}\n" }, {     "timestamp": 178,     "message": "YQL+ representation: select * from sources * where album contains ([{\"stem\": false, \"normalizeCase\": false, \"id\": 1}]\"231804170\") timeout 9991;" }

Below trace available only in response where search did not return data
"message": "Ignoring fill(null): Hits are unfillable: result.hits().getFilled()=null"

4} json body with data and without data. Already pasted in above message.

A query is in two phases: search and fill. If you had provided more information (Like exactly what I asked for instead of an interpretation of the trace) and the cluster configuration before and in between migration it would help.

A query is in two phases: search and fill. If you had provided more information (Like exactly what I asked for instead of an interpretation of the trace) and the cluster configuration before and in between migration it would help.

Below resource config used with flat and group distribution
Container(9) - 1-3core	    8G-8G
Content(6)   - 1-1.5core	16G-32G
Migrated from flat to group distribution and fired /search/
redundancy=2
searchable-copies=2
distribution partitions="1|*"
There is 1 top level group with 2 leaf with 3 nodes each

Search returning no document data
{  "trace": {      "children": [          {              "message": "No query profile is used"          },          {              "message": "Invoking chain 'default' [com.test.vespa.searcher.CustomSearcher@default -> com.yahoo.search.querytransform.WeakAndReplacementSearcher@vespa -> ... -> federation@native]"          },          {              "children": [                  {                      "timestamp": 0,                      "message": "Invoke searcher 'com.test.vespa.searcher.CustomSearcher in default'"                  },                  {                      "timestamp": 0,                      "message": "Invoke searcher 'com.yahoo.search.querytransform.WeakAndReplacementSearcher in vespa'"                  },                  {                      "timestamp": 0,                      "message": "Invoke searcher 'com.yahoo.prelude.statistics.StatisticsSearcher in native'"                  },                  {                      "timestamp": 0,                      "message": "Invoke searcher 'com.yahoo.prelude.querytransform.PhrasingSearcher in vespa'"                  },                  {                      "timestamp": 0,                      "message": "Invoke searcher 'com.yahoo.prelude.searcher.FieldCollapsingSearcher in vespa'"                  },                  {                      "timestamp": 0,                      "message": "Invoke searcher 'com.yahoo.search.yql.MinimalQueryInserter in vespa'"                  },                  {                      "timestamp": 2,                      "message": "Query parsed to: Query currently a placeholder, NullItem encountered."                  },                  {                      "timestamp": 3,                      "message": "YQL+ query parsed: [select * from sources * where album contains \"231804170\" timeout 10000;]"                  },                  {                      "timestamp": 3,                      "message": "Invoke searcher 'com.yahoo.search.yql.FieldFilter in vespa'"                  },                  {                      "timestamp": 3,                      "message": "Invoke searcher 'com.yahoo.prelude.searcher.JuniperSearcher in vespa'"                  },                  {                      "timestamp": 3,                      "message": "Invoke searcher 'com.yahoo.prelude.searcher.PosSearcher in vespa'"                  },                  {                      "timestamp": 3,                      "message": "Invoke searcher 'com.yahoo.prelude.semantics.SemanticSearcher in vespa'"                  },                  {                      "timestamp": 3,                      "message": "Invoke searcher 'com.yahoo.search.grouping.GroupingQueryParser in vespa'"                  },                  {                      "timestamp": 3,                      "message": "Invoke searcher 'com.yahoo.prelude.searcher.BlendingSearcher in vespa'"                  },                  {                      "timestamp": 3,                      "message": "Invoke searcher 'federation in native'"                  },                  {                      "timestamp": 3,                      "message": "Federating to [music]"                  },                  {                      "timestamp": 3,                      "children": [                          {                              "timestamp": 3,                              "message": "Invoke searcher 'com.yahoo.search.querytransform.NGramSearcher in music'"                          },                          {                              "timestamp": 3,                              "message": "Invoke searcher 'com.yahoo.search.querytransform.DefaultPositionSearcher in music'"                          },                          {                              "timestamp": 3,                              "message": "Invoke searcher 'com.yahoo.prelude.querytransform.CJKSearcher in music'"                          },                          {                              "timestamp": 3,                              "message": "Invoke searcher 'com.yahoo.prelude.querytransform.LiteralBoostSearcher in music'"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.search.querytransform.RangeQueryOptimizer in music'"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.search.querytransform.SortingDegrader in music'"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.search.searchers.QueryValidator in music'"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.search.grouping.GroupingValidator in music'"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.search.querytransform.WandSearcher in music'"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.prelude.querytransform.RecallSearcher in music'"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.prelude.querytransform.StemmingSearcher in music'"                          },                          {                              "timestamp": 4,                              "message": "Stemming with language=ENGLISH"                          },                          {                              "timestamp": 4,                              "message": "Stemming: [select * from sources * where album contains ([{\"stem\": false}]\"231804170\") timeout 9996;]"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.prelude.querytransform.NormalizingSearcher in music'"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.search.querytransform.VespaLowercasingSearcher in music'"                          },                          {                              "timestamp": 4,                              "message": "Lowercasing: [select * from sources * where album contains ([{\"stem\": false, \"normalizeCase\": false}]\"231804170\") timeout 9996;]"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.prelude.searcher.ValidateSortingSearcher in music'"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.search.querytransform.BooleanSearcher in music'"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.prelude.searcher.ValidatePredicateSearcher in music'"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.search.searchers.ValidateNearestNeighborSearcher in music'"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.search.grouping.vespa.GroupingExecutor in music'"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.search.searchers.ValidateMatchPhaseSearcher in music'"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.search.yql.FieldFiller in music'"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.search.searchers.InputCheckingSearcher in music'"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.search.searchers.ContainerLatencySearcher in music'"                          },                          {                              "timestamp": 4,                              "message": "Invoke searcher 'com.yahoo.prelude.cluster.ClusterSearcher in music'"                          },                          {                              "timestamp": 4,                              "message": "sc0.num0 search to dispatch: query=[album:231804170] timeout=9996ms offset=0 hits=10 groupingSessionCache=true sessionId=qrserver.0.1621499859145.6.default grouping=0 :  restrict=[music]"                          },                          {                              "timestamp": 83,                              "message": "Current state of query tree: WORD[connectedItem=null connectivity=0.0 creator=ORIG explicitSignificance=false fromSegmented=false index=\"album\" isRanked=true origin=null segmentIndex=0 significance=0.0 stemmed=true uniqueID=1 usePositionData=true weight=100 words=true]{\n  \"231804170\"\n}\n"                          },                          {                              "timestamp": 83,                              "message": "YQL+ representation: select * from sources * where album contains ([{\"stem\": false, \"normalizeCase\": false, \"id\": 1}]\"231804170\") timeout 9996;"                          },                          {                              "timestamp": 83,                              "message": "Dispatching to group 1"                          },                          {                              "timestamp": 165,                              "message": [                                  {                                      "start_time": "2021-05-20 08:37:39.228 UTC",                                      "traces": [                                          {                                              "timestamp_ms": 0.111468,                                              "event": "MTF: Start"                                          },                                          {                                              "timestamp_ms": 0.114742,                                              "event": "MTF: Build query"                                          },                                          {                                              "timestamp_ms": 0.124938,                                              "event": "MTF: reserve handles"                                          },                                          {                                              "timestamp_ms": 0.256819,                                              "event": "MTF: Fetch Postings"                                          },                                          {                                              "timestamp_ms": 0.257771,                                              "event": "MTF: Handle Global Filters"                                          },                                          {                                              "timestamp_ms": 0.258211,                                              "event": "MTF: prepareSharedState"                                          },                                          {                                              "timestamp_ms": 0.276273,                                              "event": "MTF: Complete"                                          },                                          {                                              "timestamp_ms": 0.319368,                                              "tag": "match_threads",                                              "threads": [                                                  {                                                      "traces": [                                                          {                                                              "timestamp_ms": 0.285547,                                                              "event": "Start MatchThread::run"                                                          },                                                          {                                                              "timestamp_ms": 0.301851,                                                              "event": "Start match and first phase rank"                                                          },                                                          {                                                              "timestamp_ms": 0.304358,                                                              "event": "Create result set"                                                          },                                                          {                                                              "timestamp_ms": 0.308008,                                                              "event": "Wait for result processing token"                                                          },                                                          {                                                              "timestamp_ms": 0.308826,                                                              "event": "Start result processing"                                                          },                                                          {                                                              "timestamp_ms": 0.31139,                                                              "event": "Start thread merge"                                                          },                                                          {                                                              "timestamp_ms": 0.311751,                                                              "event": "MatchThread::run Done"                                                          }                                                      ]                                                  }                                              ]                                          }                                      ],                                      "distribution-key": 5,                                      "duration_ms": 0.343535                                  }                              ]                          },                          {                              "timestamp": 1249,                              "message": [                                  {                                      "start_time": "2021-05-20 08:37:39.228 UTC",                                      "traces": [                                          {                                              "timestamp_ms": 0.168117,                                              "event": "MTF: Start"                                          },                                          {                                              "timestamp_ms": 0.170855,                                              "event": "MTF: Build query"                                          },                                          {                                              "timestamp_ms": 0.18185,                                              "event": "MTF: reserve handles"                                          },                                          {                                              "timestamp_ms": 1161.387964,                                              "event": "MTF: Fetch Postings"                                          },                                          {                                              "timestamp_ms": 1161.39158,                                              "event": "MTF: Handle Global Filters"                                          },                                          {                                              "timestamp_ms": 1161.393892,                                              "event": "MTF: prepareSharedState"                                          },                                          {                                              "timestamp_ms": 1161.417017,                                              "event": "MTF: Complete"                                          },                                          {                                              "timestamp_ms": 1161.478695,                                              "tag": "match_threads",                                              "threads": [                                                  {                                                      "traces": [                                                          {                                                              "timestamp_ms": 1161.429288,                                                              "event": "Start MatchThread::run"                                                          },                                                          {                                                              "timestamp_ms": 1161.448799,                                                              "event": "Start match and first phase rank"                                                          },                                                          {                                                              "timestamp_ms": 1161.451626,                                                              "event": "Create result set"                                                          },                                                          {                                                              "timestamp_ms": 1161.4565,                                                              "event": "Wait for result processing token"                                                          },                                                          {                                                              "timestamp_ms": 1161.457309,                                                              "event": "Start result processing"                                                          },                                                          {                                                              "timestamp_ms": 1161.460528,                                                              "event": "Start thread merge"                                                          },                                                          {                                                              "timestamp_ms": 1161.461175,                                                              "event": "MatchThread::run Done"                                                          }                                                      ]                                                  }                                              ]                                          }                                      ],                                      "distribution-key": 4,                                      "duration_ms": 1161.536437                                  }                              ]                          },                          {                              "timestamp": 4287,                              "message": [                                  {                                      "start_time": "2021-05-20 08:37:39.227 UTC",                                      "traces": [                                          {                                              "timestamp_ms": 0.095518,                                              "event": "MTF: Start"                                          },                                          {                                              "timestamp_ms": 0.098023,                                              "event": "MTF: Build query"                                          },                                          {                                              "timestamp_ms": 0.108743,                                              "event": "MTF: reserve handles"                                          },                                          {                                              "timestamp_ms": 4200.431496,                                              "event": "MTF: Fetch Postings"                                          },                                          {                                              "timestamp_ms": 4200.434762,                                              "event": "MTF: Handle Global Filters"                                          },                                          {                                              "timestamp_ms": 4200.437206,                                              "event": "MTF: prepareSharedState"                                          },                                          {                                              "timestamp_ms": 4200.464017,                                              "event": "MTF: Complete"                                          },                                          {                                              "timestamp_ms": 4200.533697,                                              "tag": "match_threads",                                              "threads": [                                                  {                                                      "traces": [                                                          {                                                              "timestamp_ms": 4200.480237,                                                              "event": "Start MatchThread::run"                                                          },                                                          {                                                              "timestamp_ms": 4200.502108,                                                              "event": "Start match and first phase rank"                                                          },                                                          {                                                              "timestamp_ms": 4200.505735,                                                              "event": "Create result set"                                                          },                                                          {                                                              "timestamp_ms": 4200.511155,                                                              "event": "Wait for result processing token"                                                          },                                                          {                                                              "timestamp_ms": 4200.512307,                                                              "event": "Start result processing"                                                          },                                                          {                                                              "timestamp_ms": 4200.516354,                                                              "event": "Start thread merge"                                                          },                                                          {                                                              "timestamp_ms": 4200.516976,                                                              "event": "MatchThread::run Done"                                                          }                                                      ]                                                  }                                              ]                                          }                                      ],                                      "distribution-key": 3,                                      "duration_ms": 4200.571297                                  }                              ]                          },                          {                              "timestamp": 4290,                              "message": "sc0.num0 dispatch response: Result (0 of total 0 hits)"                          },                          {                              "timestamp": 4290,                              "message": "sc0.num0 search to dispatch: query=[album:231804170] timeout=9996ms offset=0 hits=10 groupingSessionCache=true sessionId=qrserver.0.1621499863431.7.default grouping=0 :  restrict=[movie]"                          },                          {                              "timestamp": 4290,                              "message": "Current state of query tree: WORD[connectedItem=null connectivity=0.0 creator=ORIG explicitSignificance=false fromSegmented=false index=\"album\" isRanked=true origin=null segmentIndex=0 significance=0.0 stemmed=true uniqueID=1 usePositionData=true weight=100 words=true]{\n  \"231804170\"\n}\n"                          },                          {                              "timestamp": 4290,                              "message": "YQL+ representation: select * from sources * where album contains ([{\"stem\": false, \"normalizeCase\": false, \"id\": 1}]\"231804170\") timeout 9996;"                          },                          {                              "timestamp": 4290,                              "message": "Dispatching to group 1"                          },                          {                              "timestamp": 4294,                              "message": [                                  {                                      "start_time": "2021-05-20 08:37:43.431 UTC",                                      "traces": [                                          {                                              "timestamp_ms": 0.110595,                                              "event": "MTF: Start"                                          },                                          {                                              "timestamp_ms": 0.113402,                                              "event": "MTF: Build query"                                          },                                          {                                              "timestamp_ms": 0.123532,                                              "event": "MTF: reserve handles"                                          },                                          {                                              "timestamp_ms": 0.13416,                                              "event": "MTF: Fetch Postings"                                          },                                          {                                              "timestamp_ms": 0.13513,                                              "event": "MTF: Handle Global Filters"                                          },                                          {                                              "timestamp_ms": 0.135686,                                              "event": "MTF: prepareSharedState"                                          },                                          {                                              "timestamp_ms": 0.152991,                                              "event": "MTF: Complete"                                          },                                          {                                              "timestamp_ms": 0.191217,                                              "tag": "match_threads",                                              "threads": [                                                  {                                                      "traces": [                                                          {                                                              "timestamp_ms": 0.160109,                                                              "event": "Start MatchThread::run"                                                          },                                                          {                                                              "timestamp_ms": 0.176058,                                                              "event": "Start match and first phase rank"                                                          },                                                          {                                                              "timestamp_ms": 0.179025,                                                              "event": "Create result set"                                                          },                                                          {                                                              "timestamp_ms": 0.184042,                                                              "event": "Wait for result processing token"                                                          },                                                          {                                                              "timestamp_ms": 0.184659,                                                              "event": "Start result processing"                                                          },                                                          {                                                              "timestamp_ms": 0.187608,                                                              "event": "Start thread merge"                                                          },                                                          {                                                              "timestamp_ms": 0.188082,                                                              "event": "MatchThread::run Done"                                                          }                                                      ]                                                  }                                              ]                                          }                                      ],                                      "distribution-key": 4,                                      "duration_ms": 0.210337                                  }                              ]                          },                          {                              "timestamp": 4294,                              "message": [                                  {                                      "start_time": "2021-05-20 08:37:43.434 UTC",                                      "traces": [                                          {                                              "timestamp_ms": 0.087598,                                              "event": "MTF: Start"                                          },                                          {                                              "timestamp_ms": 0.089739,                                              "event": "MTF: Build query"                                          },                                          {                                              "timestamp_ms": 0.099169,                                              "event": "MTF: reserve handles"                                          },                                          {                                              "timestamp_ms": 0.109766,                                              "event": "MTF: Fetch Postings"                                          },                                          {                                              "timestamp_ms": 0.110786,                                              "event": "MTF: Handle Global Filters"                                          },                                          {                                              "timestamp_ms": 0.111511,                                              "event": "MTF: prepareSharedState"                                          },                                          {                                              "timestamp_ms": 0.139636,                                              "event": "MTF: Complete"                                          },                                          {                                              "timestamp_ms": 0.196499,                                              "tag": "match_threads",                                              "threads": [                                                  {                                                      "traces": [                                                          {                                                              "timestamp_ms": 0.148019,                                                              "event": "Start MatchThread::run"                                                          },                                                          {                                                              "timestamp_ms": 0.181089,                                                              "event": "Start match and first phase rank"                                                          },                                                          {                                                              "timestamp_ms": 0.183962,                                                              "event": "Create result set"                                                          },                                                          {                                                              "timestamp_ms": 0.187886,                                                              "event": "Wait for result processing token"                                                          },                                                          {                                                              "timestamp_ms": 0.188803,                                                              "event": "Start result processing"                                                          },                                                          {                                                              "timestamp_ms": 0.192113,                                                              "event": "Start thread merge"                                                          },                                                          {                                                              "timestamp_ms": 0.19259,                                                              "event": "MatchThread::run Done"                                                          }                                                      ]                                                  }                                              ]                                          }                                      ],                                      "distribution-key": 5,                                      "duration_ms": 0.219643                                  }                              ]                          },                          {                              "timestamp": 4294,                              "message": [                                  {                                      "start_time": "2021-05-20 08:37:43.435 UTC",                                      "traces": [                                          {                                              "timestamp_ms": 0.058139,                                              "event": "MTF: Start"                                          },                                          {                                              "timestamp_ms": 0.060203,                                              "event": "MTF: Build query"                                          },                                          {                                              "timestamp_ms": 0.067717,                                              "event": "MTF: reserve handles"                                          },                                          {                                              "timestamp_ms": 0.071384,                                              "event": "MTF: Fetch Postings"                                          },                                          {                                              "timestamp_ms": 0.071764,                                              "event": "MTF: Handle Global Filters"                                          },                                          {                                              "timestamp_ms": 0.072075,                                              "event": "MTF: prepareSharedState"                                          },                                          {                                              "timestamp_ms": 0.077495,                                              "event": "MTF: Complete"                                          },                                          {                                              "timestamp_ms": 0.090319,                                              "tag": "match_threads",                                              "threads": [                                                  {                                                      "traces": [                                                          {                                                              "timestamp_ms": 0.08006,                                                              "event": "Start MatchThread::run"                                                          },                                                          {                                                              "timestamp_ms": 0.08548,                                                              "event": "Start match and first phase rank"                                                          },                                                          {                                                              "timestamp_ms": 0.086572,                                                              "event": "Create result set"                                                          },                                                          {                                                              "timestamp_ms": 0.087784,                                                              "event": "Wait for result processing token"                                                          },                                                          {                                                              "timestamp_ms": 0.088245,                                                              "event": "Start result processing"                                                          },                                                          {                                                              "timestamp_ms": 0.089087,                                                              "event": "Start thread merge"                                                          },                                                          {                                                              "timestamp_ms": 0.089267,                                                              "event": "MatchThread::run Done"                                                          }                                                      ]                                                  }                                              ]                                          }                                      ],                                      "distribution-key": 3,                                      "duration_ms": 0.096921                                  }                              ]                          },                          {                              "timestamp": 4294,                              "message": "sc0.num0 dispatch response: Result (0 of total 0 hits)"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.prelude.cluster.ClusterSearcher in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.search.searchers.ContainerLatencySearcher in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.search.searchers.InputCheckingSearcher in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.search.yql.FieldFiller in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.search.searchers.ValidateMatchPhaseSearcher in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.search.grouping.vespa.GroupingExecutor in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.search.searchers.ValidateNearestNeighborSearcher in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.prelude.searcher.ValidatePredicateSearcher in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.search.querytransform.BooleanSearcher in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.prelude.searcher.ValidateSortingSearcher in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.search.querytransform.VespaLowercasingSearcher in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.prelude.querytransform.NormalizingSearcher in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.prelude.querytransform.StemmingSearcher in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.prelude.querytransform.RecallSearcher in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.search.querytransform.WandSearcher in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.search.grouping.GroupingValidator in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.search.searchers.QueryValidator in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.search.querytransform.SortingDegrader in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.search.querytransform.RangeQueryOptimizer in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.prelude.querytransform.LiteralBoostSearcher in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.prelude.querytransform.CJKSearcher in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.search.querytransform.DefaultPositionSearcher in music'"                          },                          {                              "timestamp": 4295,                              "message": "Return searcher 'com.yahoo.search.querytransform.NGramSearcher in music'"                          }                      ]                  },                  {                      "timestamp": 4295,                      "message": "Return searcher 'federation in native'"                  },                  {                      "timestamp": 4295,                      "message": "Return searcher 'com.yahoo.prelude.searcher.BlendingSearcher in vespa'"                  },                  {                      "timestamp": 4295,                      "message": "Return searcher 'com.yahoo.search.grouping.GroupingQueryParser in vespa'"                  },                  {                      "timestamp": 4295,                      "message": "Return searcher 'com.yahoo.prelude.semantics.SemanticSearcher in vespa'"                  },                  {                      "timestamp": 4295,                      "message": "Return searcher 'com.yahoo.prelude.searcher.PosSearcher in vespa'"                  },                  {                      "timestamp": 4295,                      "message": "Return searcher 'com.yahoo.prelude.searcher.JuniperSearcher in vespa'"                  },                  {                      "timestamp": 4295,                      "message": "Return searcher 'com.yahoo.search.yql.FieldFilter in vespa'"                  },                  {                      "timestamp": 4295,                      "message": "Return searcher 'com.yahoo.search.yql.MinimalQueryInserter in vespa'"                  },                  {                      "timestamp": 4295,                      "message": "Return searcher 'com.yahoo.prelude.searcher.FieldCollapsingSearcher in vespa'"                  },                  {                      "timestamp": 4295,                      "message": "Return searcher 'com.yahoo.prelude.querytransform.PhrasingSearcher in vespa'"                  },                  {                      "timestamp": 4295,                      "message": "Return searcher 'com.yahoo.prelude.statistics.StatisticsSearcher in native'"                  },                  {                      "timestamp": 4295,                      "message": "Return searcher 'com.yahoo.search.querytransform.WeakAndReplacementSearcher in vespa'"                  },                  {                      "timestamp": 4295,                      "message": "Return searcher 'com.test.vespa.searcher.CustomSearcher in default'"                  },                  {                      "timestamp": 4295,                      "message": "Ignoring fill(null): Hits are unfillable: result.hits().getFilled()=null"                  },                  {                      "timestamp": 4297,                      "message": "Query time query 'album:231804170': 4295 ms"                  },                  {                      "timestamp": 4297,                      "message": "Summary fetch time query 'album:231804170': 0 ms"                  }              ]          }      ]  },  "root": {      "id": "toplevel",      "relevance": 1.0,      "fields": {          "totalCount": 0      },      "coverage": {          "coverage": 100,          "documents": 287851704,          "full": true,          "nodes": 6,          "results": 2,          "resultsFull": 2      },      "children": [          {              "id": "test",              "relevance": 1.0          }      ]  } }

Search returning document data
{  "trace": {      "children": [          {              "message": "No query profile is used"          },          {              "message": "Invoking chain 'default' [com.test.vespa.searcher.CustomSearcher@default -> com.yahoo.search.querytransform.WeakAndReplacementSearcher@vespa -> ... -> federation@native]"          },          {              "children": [                  {                      "timestamp": 1,                      "message": "Invoke searcher 'com.test.vespa.searcher.CustomSearcher in default'"                  },                  {                      "timestamp": 1,                      "message": "Invoke searcher 'com.yahoo.search.querytransform.WeakAndReplacementSearcher in vespa'"                  },                  {                      "timestamp": 1,                      "message": "Invoke searcher 'com.yahoo.prelude.statistics.StatisticsSearcher in native'"                  },                  {                      "timestamp": 1,                      "message": "Invoke searcher 'com.yahoo.prelude.querytransform.PhrasingSearcher in vespa'"                  },                  {                      "timestamp": 1,                      "message": "Invoke searcher 'com.yahoo.prelude.searcher.FieldCollapsingSearcher in vespa'"                  },                  {                      "timestamp": 1,                      "message": "Invoke searcher 'com.yahoo.search.yql.MinimalQueryInserter in vespa'"                  },                  {                      "timestamp": 4,                      "message": "Query parsed to: Query currently a placeholder, NullItem encountered."                  },                  {                      "timestamp": 6,                      "message": "YQL+ query parsed: [select * from sources * where album contains \"231804170\" timeout 10000;]"                  },                  {                      "timestamp": 6,                      "message": "Invoke searcher 'com.yahoo.search.yql.FieldFilter in vespa'"                  },                  {                      "timestamp": 6,                      "message": "Invoke searcher 'com.yahoo.prelude.searcher.JuniperSearcher in vespa'"                  },                  {                      "timestamp": 6,                      "message": "Invoke searcher 'com.yahoo.prelude.searcher.PosSearcher in vespa'"                  },                  {                      "timestamp": 6,                      "message": "Invoke searcher 'com.yahoo.prelude.semantics.SemanticSearcher in vespa'"                  },                  {                      "timestamp": 6,                      "message": "Invoke searcher 'com.yahoo.search.grouping.GroupingQueryParser in vespa'"                  },                  {                      "timestamp": 6,                      "message": "Invoke searcher 'com.yahoo.prelude.searcher.BlendingSearcher in vespa'"                  },                  {                      "timestamp": 6,                      "message": "Invoke searcher 'federation in native'"                  },                  {                      "timestamp": 6,                      "message": "Federating to [music]"                  },                  {                      "timestamp": 6,                      "children": [                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.search.querytransform.NGramSearcher in music'"                          },                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.search.querytransform.DefaultPositionSearcher in music'"                          },                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.prelude.querytransform.CJKSearcher in music'"                          },                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.prelude.querytransform.LiteralBoostSearcher in music'"                          },                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.search.querytransform.RangeQueryOptimizer in music'"                          },                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.search.querytransform.SortingDegrader in music'"                          },                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.search.searchers.QueryValidator in music'"                          },                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.search.grouping.GroupingValidator in music'"                          },                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.search.querytransform.WandSearcher in music'"                          },                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.prelude.querytransform.RecallSearcher in music'"                          },                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.prelude.querytransform.StemmingSearcher in music'"                          },                          {                              "timestamp": 6,                              "message": "Stemming with language=ENGLISH"                          },                          {                              "timestamp": 6,                              "message": "Stemming: [select * from sources * where album contains ([{\"stem\": false}]\"231804170\") timeout 9991;]"                          },                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.prelude.querytransform.NormalizingSearcher in music'"                          },                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.search.querytransform.VespaLowercasingSearcher in music'"                          },                          {                              "timestamp": 6,                              "message": "Lowercasing: [select * from sources * where album contains ([{\"stem\": false, \"normalizeCase\": false}]\"231804170\") timeout 9991;]"                          },                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.prelude.searcher.ValidateSortingSearcher in music'"                          },                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.search.querytransform.BooleanSearcher in music'"                          },                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.prelude.searcher.ValidatePredicateSearcher in music'"                          },                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.search.searchers.ValidateNearestNeighborSearcher in music'"                          },                          {                              "timestamp": 6,                              "message": "Invoke searcher 'com.yahoo.search.grouping.vespa.GroupingExecutor in music'"                          },                          {                              "timestamp": 7,                              "message": "Invoke searcher 'com.yahoo.search.searchers.ValidateMatchPhaseSearcher in music'"                          },                          {                              "timestamp": 7,                              "message": "Invoke searcher 'com.yahoo.search.yql.FieldFiller in music'"                          },                          {                              "timestamp": 7,                              "message": "Invoke searcher 'com.yahoo.search.searchers.InputCheckingSearcher in music'"                          },                          {                              "timestamp": 7,                              "message": "Invoke searcher 'com.yahoo.search.searchers.ContainerLatencySearcher in music'"                          },                          {                              "timestamp": 7,                              "message": "Invoke searcher 'com.yahoo.prelude.cluster.ClusterSearcher in music'"                          },                          {                              "timestamp": 7,                              "message": "sc0.num0 search to dispatch: query=[album:231804170] timeout=9991ms offset=0 hits=10 groupingSessionCache=true sessionId=qrserver.0.1621499804110.6.default grouping=0 :  restrict=[music]"                          },                          {                              "timestamp": 80,                              "message": "Current state of query tree: WORD[connectedItem=null connectivity=0.0 creator=ORIG explicitSignificance=false fromSegmented=false index=\"album\" isRanked=true origin=null segmentIndex=0 significance=0.0 stemmed=true uniqueID=1 usePositionData=true weight=100 words=true]{\n  \"231804170\"\n}\n"                          },                          {                              "timestamp": 80,                              "message": "YQL+ representation: select * from sources * where album contains ([{\"stem\": false, \"normalizeCase\": false, \"id\": 1}]\"231804170\") timeout 9991;"                          },                          {                              "timestamp": 80,                              "message": "Dispatching to group 0"                          },                          {                              "timestamp": 168,                              "message": [                                  {                                      "start_time": "2021-05-20 08:36:44.187 UTC",                                      "traces": [                                          {                                              "timestamp_ms": 0.152855,                                              "event": "MTF: Start"                                          },                                          {                                              "timestamp_ms": 0.155789,                                              "event": "MTF: Build query"                                          },                                          {                                              "timestamp_ms": 0.167152,                                              "event": "MTF: reserve handles"                                          },                                          {                                              "timestamp_ms": 0.294386,                                              "event": "MTF: Fetch Postings"                                          },                                          {                                              "timestamp_ms": 0.299497,                                              "event": "MTF: Handle Global Filters"                                          },                                          {                                              "timestamp_ms": 0.300601,                                              "event": "MTF: prepareSharedState"                                          },                                          {                                              "timestamp_ms": 0.32082,                                              "event": "MTF: Complete"                                          },                                          {                                              "timestamp_ms": 0.415666,                                              "tag": "match_threads",                                              "threads": [                                                  {                                                      "traces": [                                                          {                                                              "timestamp_ms": 0.330624,                                                              "event": "Start MatchThread::run"                                                          },                                                          {                                                              "timestamp_ms": 0.3866,                                                              "event": "Start match and first phase rank"                                                          },                                                          {                                                              "timestamp_ms": 0.395256,                                                              "event": "Create result set"                                                          },                                                          {                                                              "timestamp_ms": 0.400452,                                                              "event": "Wait for result processing token"                                                          },                                                          {                                                              "timestamp_ms": 0.401312,                                                              "event": "Start result processing"                                                          },                                                          {                                                              "timestamp_ms": 0.405296,                                                              "event": "Start thread merge"                                                          },                                                          {                                                              "timestamp_ms": 0.40615,                                                              "event": "MatchThread::run Done"                                                          }                                                      ]                                                  }                                              ]                                          }                                      ],                                      "distribution-key": 2,                                      "duration_ms": 0.445282                                  }                              ]                          },                          {                              "timestamp": 168,                              "message": [                                  {                                      "start_time": "2021-05-20 08:36:44.199 UTC",                                      "traces": [                                          {                                              "timestamp_ms": 0.09273,                                              "event": "MTF: Start"                                          },                                          {                                              "timestamp_ms": 0.095727,                                              "event": "MTF: Build query"                                          },                                          {                                              "timestamp_ms": 0.107246,                                              "event": "MTF: reserve handles"                                          },                                          {                                              "timestamp_ms": 0.216757,                                              "event": "MTF: Fetch Postings"                                          },                                          {                                              "timestamp_ms": 0.21762,                                              "event": "MTF: Handle Global Filters"                                          },                                          {                                              "timestamp_ms": 0.218074,                                              "event": "MTF: prepareSharedState"                                          },                                          {                                              "timestamp_ms": 0.234948,                                              "event": "MTF: Complete"                                          },                                          {                                              "timestamp_ms": 0.282672,                                              "tag": "match_threads",                                              "threads": [                                                  {                                                      "traces": [                                                          {                                                              "timestamp_ms": 0.242144,                                                              "event": "Start MatchThread::run"                                                          },                                                          {                                                              "timestamp_ms": 0.262899,                                                              "event": "Start match and first phase rank"                                                          },                                                          {                                                              "timestamp_ms": 0.265617,                                                              "event": "Create result set"                                                          },                                                          {                                                              "timestamp_ms": 0.272281,                                                              "event": "Wait for result processing token"                                                          },                                                          {                                                              "timestamp_ms": 0.273227,                                                              "event": "Start result processing"                                                          },                                                          {                                                              "timestamp_ms": 0.275658,                                                              "event": "Start thread merge"                                                          },                                                          {                                                              "timestamp_ms": 0.276149,                                                              "event": "MatchThread::run Done"                                                          }                                                      ]                                                  }                                              ]                                          }                                      ],                                      "distribution-key": 1,                                      "duration_ms": 0.308025                                  }                              ]                          },                          {                              "timestamp": 168,                              "message": [                                  {                                      "start_time": "2021-05-20 08:36:44.199 UTC",                                      "traces": [                                          {                                              "timestamp_ms": 0.175918,                                              "event": "MTF: Start"                                          },                                          {                                              "timestamp_ms": 0.193536,                                              "event": "MTF: Build query"                                          },                                          {                                              "timestamp_ms": 0.203125,                                              "event": "MTF: reserve handles"                                          },                                          {                                              "timestamp_ms": 0.277553,                                              "event": "MTF: Fetch Postings"                                          },                                          {                                              "timestamp_ms": 0.282154,                                              "event": "MTF: Handle Global Filters"                                          },                                          {                                              "timestamp_ms": 0.283142,                                              "event": "MTF: prepareSharedState"                                          },                                          {                                              "timestamp_ms": 0.302455,                                              "event": "MTF: Complete"                                          },                                          {                                              "timestamp_ms": 0.375627,                                              "tag": "match_threads",                                              "threads": [                                                  {                                                      "traces": [                                                          {                                                              "timestamp_ms": 0.311606,                                                              "event": "Start MatchThread::run"                                                          },                                                          {                                                              "timestamp_ms": 0.34006,                                                              "event": "Start match and first phase rank"                                                          },                                                          {                                                              "timestamp_ms": 0.346841,                                                              "event": "Create result set"                                                          },                                                          {                                                              "timestamp_ms": 0.350986,                                                              "event": "Wait for result processing token"                                                          },                                                          {                                                              "timestamp_ms": 0.35177,                                                              "event": "Start result processing"                                                          },                                                          {                                                              "timestamp_ms": 0.355084,                                                              "event": "Start thread merge"                                                          },                                                          {                                                              "timestamp_ms": 0.355866,                                                              "event": "MatchThread::run Done"                                                          }                                                      ]                                                  }                                              ]                                          }                                      ],                                      "distribution-key": 0,                                      "duration_ms": 0.401691                                  }                              ]                          },                          {                              "timestamp": 175,                              "message": "sc0.num0 dispatch response: Result (1 of total 1 hits)"                          },                          {                              "timestamp": 175,                              "message": "sc0.num0 search to dispatch: query=[album:231804170] timeout=9991ms offset=0 hits=10 groupingSessionCache=true sessionId=qrserver.0.1621499804278.7.default grouping=0 :  restrict=[movie]"                          },                          {                              "timestamp": 175,                              "message": "Current state of query tree: WORD[connectedItem=null connectivity=0.0 creator=ORIG explicitSignificance=false fromSegmented=false index=\"album\" isRanked=true origin=null segmentIndex=0 significance=0.0 stemmed=true uniqueID=1 usePositionData=true weight=100 words=true]{\n  \"231804170\"\n}\n"                          },                          {                              "timestamp": 175,                              "message": "YQL+ representation: select * from sources * where album contains ([{\"stem\": false, \"normalizeCase\": false, \"id\": 1}]\"231804170\") timeout 9991;"                          },                          {                              "timestamp": 175,                              "message": "Dispatching to group 0"                          },                          {                              "timestamp": 176,                              "message": [                                  {                                      "start_time": "2021-05-20 08:36:44.279 UTC",                                      "traces": [                                          {                                              "timestamp_ms": 0.074569,                                              "event": "MTF: Start"                                          },                                          {                                              "timestamp_ms": 0.076338,                                              "event": "MTF: Build query"                                          },                                          {                                              "timestamp_ms": 0.085141,                                              "event": "MTF: reserve handles"                                          },                                          {                                              "timestamp_ms": 0.103952,                                              "event": "MTF: Fetch Postings"                                          },                                          {                                              "timestamp_ms": 0.104679,                                              "event": "MTF: Handle Global Filters"                                          },                                          {                                              "timestamp_ms": 0.105578,                                              "event": "MTF: prepareSharedState"                                          },                                          {                                              "timestamp_ms": 0.118741,                                              "event": "MTF: Complete"                                          },                                          {                                              "timestamp_ms": 0.151589,                                              "tag": "match_threads",                                              "threads": [                                                  {                                                      "traces": [                                                          {                                                              "timestamp_ms": 0.124931,                                                              "event": "Start MatchThread::run"                                                          },                                                          {                                                              "timestamp_ms": 0.139005,                                                              "event": "Start match and first phase rank"                                                          },                                                          {                                                              "timestamp_ms": 0.141562,                                                              "event": "Create result set"                                                          },                                                          {                                                              "timestamp_ms": 0.145353,                                                              "event": "Wait for result processing token"                                                          },                                                          {                                                              "timestamp_ms": 0.146007,                                                              "event": "Start result processing"                                                          },                                                          {                                                              "timestamp_ms": 0.14869,                                                              "event": "Start thread merge"                                                          },                                                          {                                                              "timestamp_ms": 0.149174,                                                              "event": "MatchThread::run Done"                                                          }                                                      ]                                                  }                                              ]                                          }                                      ],                                      "distribution-key": 2,                                      "duration_ms": 0.188608                                  }                              ]                          },                          {                              "timestamp": 176,                              "message": [                                  {                                      "start_time": "2021-05-20 08:36:44.279 UTC",                                      "traces": [                                          {                                              "timestamp_ms": 0.090669,                                              "event": "MTF: Start"                                          },                                          {                                              "timestamp_ms": 0.093912,                                              "event": "MTF: Build query"                                          },                                          {                                              "timestamp_ms": 0.104011,                                              "event": "MTF: reserve handles"                                          },                                          {                                              "timestamp_ms": 0.114433,                                              "event": "MTF: Fetch Postings"                                          },                                          {                                              "timestamp_ms": 0.115236,                                              "event": "MTF: Handle Global Filters"                                          },                                          {                                              "timestamp_ms": 0.11582,                                              "event": "MTF: prepareSharedState"                                          },                                          {                                              "timestamp_ms": 0.131978,                                              "event": "MTF: Complete"                                          },                                          {                                              "timestamp_ms": 0.167233,                                              "tag": "match_threads",                                              "threads": [                                                  {                                                      "traces": [                                                          {                                                              "timestamp_ms": 0.13887,                                                              "event": "Start MatchThread::run"                                                          },                                                          {                                                              "timestamp_ms": 0.154616,                                                              "event": "Start match and first phase rank"                                                          },                                                          {                                                              "timestamp_ms": 0.157367,                                                              "event": "Create result set"                                                          },                                                          {                                                              "timestamp_ms": 0.160822,                                                              "event": "Wait for result processing token"                                                          },                                                          {                                                              "timestamp_ms": 0.161626,                                                              "event": "Start result processing"                                                          },                                                          {                                                              "timestamp_ms": 0.164426,                                                              "event": "Start thread merge"                                                          },                                                          {                                                              "timestamp_ms": 0.164915,                                                              "event": "MatchThread::run Done"                                                          }                                                      ]                                                  }                                              ]                                          }                                      ],                                      "distribution-key": 1,                                      "duration_ms": 0.187303                                  }                              ]                          },                          {                              "timestamp": 176,                              "message": [                                  {                                      "start_time": "2021-05-20 08:36:44.279 UTC",                                      "traces": [                                          {                                              "timestamp_ms": 0.116869,                                              "event": "MTF: Start"                                          },                                          {                                              "timestamp_ms": 0.11963,                                              "event": "MTF: Build query"                                          },                                          {                                              "timestamp_ms": 0.128361,                                              "event": "MTF: reserve handles"                                          },                                          {                                              "timestamp_ms": 0.136636,                                              "event": "MTF: Fetch Postings"                                          },                                          {                                              "timestamp_ms": 0.137368,                                              "event": "MTF: Handle Global Filters"                                          },                                          {                                              "timestamp_ms": 0.138036,                                              "event": "MTF: prepareSharedState"                                          },                                          {                                              "timestamp_ms": 0.153575,                                              "event": "MTF: Complete"                                          },                                          {                                              "timestamp_ms": 0.188641,                                              "tag": "match_threads",                                              "threads": [                                                  {                                                      "traces": [                                                          {                                                              "timestamp_ms": 0.160378,                                                              "event": "Start MatchThread::run"                                                          },                                                          {                                                              "timestamp_ms": 0.176008,                                                              "event": "Start match and first phase rank"                                                          },                                                          {                                                              "timestamp_ms": 0.178395,                                                              "event": "Create result set"                                                          },                                                          {                                                              "timestamp_ms": 0.182184,                                                              "event": "Wait for result processing token"                                                          },                                                          {                                                              "timestamp_ms": 0.182864,                                                              "event": "Start result processing"                                                          },                                                          {                                                              "timestamp_ms": 0.185439,                                                              "event": "Start thread merge"                                                          },                                                          {                                                              "timestamp_ms": 0.185759,                                                              "event": "MatchThread::run Done"                                                          }                                                      ]                                                  }                                              ]                                          }                                      ],                                      "distribution-key": 0,                                      "duration_ms": 0.208396                                  }                              ]                          },                          {                              "timestamp": 176,                              "message": "sc0.num0 dispatch response: Result (0 of total 0 hits)"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.prelude.cluster.ClusterSearcher in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.search.searchers.ContainerLatencySearcher in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.search.searchers.InputCheckingSearcher in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.search.yql.FieldFiller in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.search.searchers.ValidateMatchPhaseSearcher in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.search.grouping.vespa.GroupingExecutor in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.search.searchers.ValidateNearestNeighborSearcher in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.prelude.searcher.ValidatePredicateSearcher in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.search.querytransform.BooleanSearcher in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.prelude.searcher.ValidateSortingSearcher in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.search.querytransform.VespaLowercasingSearcher in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.prelude.querytransform.NormalizingSearcher in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.prelude.querytransform.StemmingSearcher in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.prelude.querytransform.RecallSearcher in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.search.querytransform.WandSearcher in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.search.grouping.GroupingValidator in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.search.searchers.QueryValidator in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.search.querytransform.SortingDegrader in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.search.querytransform.RangeQueryOptimizer in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.prelude.querytransform.LiteralBoostSearcher in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.prelude.querytransform.CJKSearcher in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.search.querytransform.DefaultPositionSearcher in music'"                          },                          {                              "timestamp": 177,                              "message": "Return searcher 'com.yahoo.search.querytransform.NGramSearcher in music'"                          },                          {                              "timestamp": 178,                              "message": "sc0.num0 fill to dispatch: query=[album:231804170] timeout=9991ms offset=0 hits=10 groupingSessionCache=true sessionId=qrserver.0.1621499804110.6.default grouping=0 :  restrict=[music] summary=[null]"                          },                          {                              "timestamp": 178,                              "message": "Current state of query tree: WORD[connectedItem=null connectivity=0.0 creator=ORIG explicitSignificance=false fromSegmented=false index=\"album\" isRanked=true origin=null segmentIndex=0 significance=0.0 stemmed=true uniqueID=1 usePositionData=true weight=100 words=true]{\n  \"231804170\"\n}\n"                          },                          {                              "timestamp": 178,                              "message": "YQL+ representation: select * from sources * where album contains ([{\"stem\": false, \"normalizeCase\": false, \"id\": 1}]\"231804170\") timeout 9991;"                          },                          {                              "timestamp": 178,                              "message": "Not resending query during document summary fetching"                          }                      ]                  },                  {                      "timestamp": 177,                      "message": "Return searcher 'federation in native'"                  },                  {                      "timestamp": 177,                      "message": "Return searcher 'com.yahoo.prelude.searcher.BlendingSearcher in vespa'"                  },                  {                      "timestamp": 177,                      "message": "Return searcher 'com.yahoo.search.grouping.GroupingQueryParser in vespa'"                  },                  {                      "timestamp": 177,                      "message": "Return searcher 'com.yahoo.prelude.semantics.SemanticSearcher in vespa'"                  },                  {                      "timestamp": 177,                      "message": "Return searcher 'com.yahoo.prelude.searcher.PosSearcher in vespa'"                  },                  {                      "timestamp": 177,                      "message": "Return searcher 'com.yahoo.prelude.searcher.JuniperSearcher in vespa'"                  },                  {                      "timestamp": 177,                      "message": "Return searcher 'com.yahoo.search.yql.FieldFilter in vespa'"                  },                  {                      "timestamp": 177,                      "message": "Return searcher 'com.yahoo.search.yql.MinimalQueryInserter in vespa'"                  },                  {                      "timestamp": 177,                      "message": "Return searcher 'com.yahoo.prelude.searcher.FieldCollapsingSearcher in vespa'"                  },                  {                      "timestamp": 177,                      "message": "Return searcher 'com.yahoo.prelude.querytransform.PhrasingSearcher in vespa'"                  },                  {                      "timestamp": 177,                      "message": "Return searcher 'com.yahoo.prelude.statistics.StatisticsSearcher in native'"                  },                  {                      "timestamp": 177,                      "message": "Return searcher 'com.yahoo.search.querytransform.WeakAndReplacementSearcher in vespa'"                  },                  {                      "timestamp": 177,                      "message": "Return searcher 'com.test.vespa.searcher.CustomSearcher in default'"                  },                  {                      "timestamp": 177                  },                  {                      "timestamp": 180,                      "message": "Query time query 'album:231804170': 177 ms"                  },                  {                      "timestamp": 180,                      "message": "Summary fetch time query 'album:231804170': 2 ms"                  }              ]          }      ]  },  "root": {      "id": "toplevel",      "relevance": 1.0,      "fields": {          "totalCount": 1      },      "coverage": {          "coverage": 100,          "documents": 295257617,          "full": true,          "nodes": 6,          "results": 2,          "resultsFull": 2      },      "children": [          {              "id": "test",              "relevance": 1.0          },          {              "id": "id:mynamespace:music::231804170",              "relevance": 0.11322686356149855,              "source": "music",              "fields": {                  "sddocname": "music",                  "documentid": "id:mynamespace:music::231804170",                  "artist": "XXXXX",                  "album": "231804170",                  "year": 1991              }          }      ]  } }

I took the liberty to edit your comment to format the json.

You have two document types (music and album) so there are two search requests searching for album:xxxx in both music and album (federation). Use restrict parameter or select foo from album to avoid searching both.

Also

When dispatching the query to group 0 the document is found and all nodes have roughly same latency
When dispatching the query go group 1 the document is not found  and one node is significantly slower than others - how is album defined? Seems like you are using string from the response.

So here there is inconsistency between the two groups after migrating from flat to grouped setup which I believe you track in https://github.com/vespa-engine/vespa/issues/17903

I took the liberty to edit your comment to format the json.

You have two document types (music and album) so there are two search requests searching for album:xxxx in both music and album (federation). Use restrict parameter or select foo from album to avoid searching both.

Also

When dispatching the query to group 0 the document is found and all nodes have roughly same latency
When dispatching the query go group 1 the document is not found  and one node is significantly slower than others - how is album defined? Seems like you are using string from the response.

So here there is inconsistency between the two groups after migrating from flat to grouped setup which I believe you track in #17903

Hi
Yes, there are two docs music and movie.
music doc has fields artist(string), album(string), year(int)
movie doc has fields cast(string), name(string), year(int)
I have updated the application from  flat to group again. Once data distribution is complete will check for the search consistency again.