[Concurrent Segment Search] Query profile stats with concurrent execution of query phase

[sohami]

With current model of concurrent search, seems like we add time take by different slices to reflect the time taken by a collector. This may not be the true reflection of time taken by that collector. We should explore and see if instead it would make sense to expose max/min/average latency across different slices execution of a collector. For more context see #1500

[ticheng-aws]

Taking a look.

[ticheng-aws]

Background

Currently, with the model of concurrent search, collectors portion of the profile response shows the time each collection type has taken and returns it as the cumulative summary in the reduce phase. In the below comparison, the concurrent search collector time_in_nanos is close to the non-concurrent search case, which does not truly reflect the time taken by that collector. We expect the perceived time may be smaller than profilers reported here.

Figure 1. Profile response comparison of non-concurrent search and multi-slices concurrent search

Proposed Solution

Introduce reduce_time_in_nanos, segment_slice_count, and profiled time stats collector field

To show high-level concurrent execution details, we bring min_time_in_nanos, max_time_in_nanos, and segment_slice_count etc. fields into the query response. With these new fields, users can quickly determine query performance and skew issues.

Definition of existing collector fields

1. name: A more friendly representation of the collector's class name.
2. reason: A "hint" to help provide some context about this collector.
3. time_in_nanos: The total elapsed time for this collector. In the concurrent search case, this is the total time across all slices (i.e. max(slice_end_time) - min(slice_start_time))
4. children: A list of children collectors "embedded" inside this collector.

Definition of new collector fields with concurrent execution

1. reduce_time_in_nanos: The elapsed time in the reduce phase.
2. min_slice_time_in_nanos: The minimum slice time for this collector manager.
3. max_slice_time_in_nanos: The maximum slice time for this collector manager.
4. avg_slice_time_in_nanos: The average slice time for this collector manager.
5. segment_slice_count: The segment slice count for this collector manager.

Sample query response

Non-concurrent search

...
    "collector":
    [
        {
            "name": "SimpleTopScoreDocCollector",
            "reason": "search_top_hits",
            "time_in_nanos": 572294
        }
    ]
...

Concurrent search with 5 segment slices

...
    "collector":
    [
        {
            "name": "SimpleTopDocsCollectorManager",
            "reason": "search_top_hits",
            "time_in_nanos": 2392039,
            "reduce_time_in_nanos": 2134,
            "max_slice_time_in_nanos": 852913,
            "min_slice_time_in_nanos": 2922,
            "avg_slice_time_in_nanos": 532936,
            "segment_slice_count": 5
        }
    ]
...

A more complex query response with children collectors

Non-concurrent search

...
    "collector":
    [
        {
            "name": "MultiCollector",
            "reason": "search_terminate_after_count",
            "time_in_nanos": 3053199,
            "children":
            [
                {
                    "name": "SimpleTopScoreDocCollector",
                    "reason": "search_top_hits",
                    "time_in_nanos": 815462
                }
            ]
        }
    ]
...

Concurrent search with 2 segment slices

...
    "collector":
    [
        {
            "name": "EarlyTerminatingCollectorManager",
            "reason": "search_terminate_after_count",
            "time_in_nanos": 3653709,
            "reduce_time_in_nanos": 3663,
            "max_slice_time_in_nanos": 1873465,
            "min_slice_time_in_nanos": 1780244,
            "avg_slice_time_in_nanos": 1798228,
            "segment_slice_count": 2,
            "children":
            [
                {
                    "name": "SimpleTopDocsCollectorManager",
                    "reason": "search_top_hits",
                    "time_in_nanos": 1777069,
                    "reduce_time_in_nanos": 9125,
                    "max_slice_time_in_nanos": 919295,
                    "min_slice_time_in_nanos": 857774,
                    "avg_slice_time_in_nanos": 895690,
                    "segment_slice_count": 2
                }
            ]
        }
    ]
...

Alternatives

Expand collector manager with concurrent execution

Instead of exposing min/max/avg latency across segment slices execution of a collector manager, we list out all the collectors response from the collector manager. In this approach, users get the raw/origin data, which is more flexible for analysis. However, this will cause more manual statistics from the wordy query response. Especially, with complex query, the nested response could be very long.

Sample query response

Non-concurrent search

...
    "collector":
    [
        {
            "name": "SimpleTopScoreDocCollector",
            "reason": "search_top_hits",
            "time_in_nanos": 8655262
        }
    ]
...

Concurrent search with 5 segment slices

...
    "collectorManager":
    [
        {
            "name": "SimpleTopScoreDocCollector",
            "reason": "search_top_hits",
            "time_in_nanos": 1529196
        },
        {
            "name": "SimpleTopScoreDocCollector",
            "reason": "search_top_hits",
            "time_in_nanos": 15563
        },
        {
            "name": "SimpleTopScoreDocCollector",
            "reason": "search_top_hits",
            "time_in_nanos": 12830
        },
        {
            "name": "SimpleTopScoreDocCollector",
            "reason": "search_top_hits",
            "time_in_nanos": 7086899
        },
        {
            "name": "SimpleTopScoreDocCollector",
            "reason": "search_top_hits",
            "time_in_nanos": 10774
        }
    ]
...

[ticheng-aws]

Tagging @sohami @yigithub @jed326 @andrross @reta for feedback. Thank you.

[sohami]

@ticheng-aws Thanks for sharing the proposal. Couple of questions:

1. Nit: segment_slice_count wondering if we should just name it as slice_count instead ?
2. Also what is the difference between time_in_nanos and max_slice_time_in_nanos for concurrent case ?
3. I am assuming that for non concurrent case, we will keep the profile same as today and the new fields will be added for concurrent use case only ?

[ticheng-aws]

Hi @sohami, thank you for asking.

1. slice_count sounds good to me.
2. In concurrent scenarios, time_in_nanos is the total time across all slices, while max_slice_time_in_nanos denotes the maximum collector elapsed time within a collector manager. The different between these two values implies that complete concurrency was not achieved, which can be helpful in fine-tuning the top-level and slice threadpool configuration.
3. Yes, we will maintain the same profile as today in the non-concurrent search case.

[reta]

@ticheng-aws sounds as a good improvement, thank you

< slice_count sounds good to me.

I think we could introduce leaf_count stat for non-concurrent search case as well, to expose the number of leafs (subreader) the collector has to go over? WDYT?

[sohami]

@ticheng-aws sounds as a good improvement, thank you

< slice_count sounds good to me.

I think we could introduce leaf_count stat for non-concurrent search case as well, to expose the number of leafs (subreader) the collector has to go over? WDYT?

@reta leaf_count will be essentially the segment count and that will be available from the cat segments API. Generally, I would expect the profile API is used in the controlled setup where users want to analyze the search operation taking the longest time to optimize their search request. So along with information from profile option, they can fetch different index/node level stats to understand the issue better ?

[reta]

Thanks @sohami , sure, it was just a suggestion, I was thinking since you are improving the profile APIs adding leaf_count (== segment count) would help to see more complete picture in one place, instead of using yet another APIs to fetch this information.

[ticheng-aws]

I agree. Duplicating the information is unnecessary since users can already fetch it through the CAT segments API. Thanks @reta and @sohami for your valuable input.