Trace grouping details and timing on content nodes

[dainiusjocas]

Grouping on content nodes was hardly visible in the query trace. Nothing specific to grouping was traced, and passes served from a cached grouping session produced no content node trace at all. This adds grouping details and timing to the trace at level 6, which is what trace.explainLevel=1 / vespa query --profile gives on the content nodes. The field names are fixed so that vespa inspect profile can use them later. The tracedoctor is not changed in this PR.

What is traced

A grouping entry for each pass, from both the first pass (ResultProcessor::makeReply) and continued passes (handleGroupingSession):

{ "tag": "grouping",
  "continued_session": false, "session_cached": true,
  "continue_ms": 0.31, "serialize_ms": 0.04,
  "merge_ms": 0.42, "merge_count": 3, "prune_ms": 0.05,
  "groupings": [
    { "id": 0, "first_level": 0, "last_level": 0, "top_n": -1, "summary_hits": 3,
      "from_session": true, "session_done": false, "time_ms": 0.12,
      "levels": [
        { "max_groups": 10, "precision": 30, "groups": 27, "session_groups": 27 },
        { "max_groups": -1, "precision": -1, "groups": 0,  "session_groups": 412 } ] } ] }

Pass level:

• continued_session: the pass was served from a cached grouping session, without matching. session_cached: the session was kept for later passes.
• continue_ms: time spent producing the result for the pass. This includes the per-grouping time_ms and serialize_ms (time spent serializing the result).
• merge_ms, merge_count, prune_ms (first pass only, and only when more than one thread was used): time spent in and number of merges of grouping results across threads, and time spent pruning the merged result. merge_ms is a sum over merges that may have run in parallel, not wall clock time.

Per grouping:

• top_n, max_groups, precision are request limits. They are always present and use -1 for no limit.
• summary_hits: number of document hits from hits aggregations (e.g. each(output(summary()))) in the returned result. It is not the number of documents that were grouped.
• from_session: the result was produced from the full result kept by the grouping session. This is true on every pass of a grouping that needs more than one pass, including the first. It is false when the grouping completed in a single pass (all levels requested at once, or no session id), in which case hits were aggregated directly into the request. When it is false, session_done, time_ms and session_groups are left out.
• Per level: groups is the number of groups returned in this pass. session_groups is the number of groups in the session's full result at the start of the pass, before this pass pruned it to the groups the container asked for. That pruning shows up in the next pass's session_groups.
• time_ms: time spent pruning the session's full result and merging it into the request for this grouping.

Each match thread's trace also gets a grouping_timing entry with aggregate_ms: the time the thread spent aggregating hits into its groupings, with sorting excluded.

Implementation

• The new searchcore/grouping/grouping_pass_details.{h,cpp} holds GroupingPassDetails (per grouping) and GroupingPassTrace (per pass), the group counting, and the slime rendering. The field conventions are documented in the header.
• GroupingSession::continueExecution takes an optional GroupingPassTrace*. When it is null, nothing is counted and the clock is not read.
• The clock is only read when tracing at level 6, in the match threads, the thread merges and the final step. Merge time accumulates into the merge target, whichever thread runs the merge. This is not a data race: the merge director hands each pair of sources to one thread and synchronizes between merge steps, and the totals are read after the threads are joined. The reasoning is in a comment at the accumulation.

Testing

• grouping_test: a three-pass session checks the counts in each pass (including the session's result shrinking after pruning) and the rendered JSON. A test without a session id checks from_session false and that the session-only fields are left out.
• matching_test: checks the real trace for a first pass that caches the session (summary_hits 3 out of 9 matched documents), a continued pass served from it, no output at trace level 5, and a 4-thread pass (merge_count 3, from_session false). It also checks that continue_ms covers the per-grouping times plus serialize_ms.

Both suites pass (14 and 69 tests), and searchcore_proton builds without warnings.

I confirm that this contribution is made under the terms of the license found in the root directory of this repository's source tree and that I have the authority necessary to make this contribution on behalf of its copyright owner.

🤖 Generated with Claude Code