[BUG] Profile timings incorrect for concurrent segments #18534
Description
Describe the bug
When running a query with the profile flag, sometimes the duration of a timer is really (incorrectly) large. This occurs in ConcurrentQueryProfileBreakdown:224. What's happening is a timer for a particular leaf has not been called yet (count = 0), but it still tries to add that duration to the map. When the min/maxes are computed later on across slices, one of these slices' value is 0 so the start time is set to 0 making the duration whatever the end nanoTime() is. Logic needs to be added to skip adding it to the map if there's no invocation of the timer.
Related component
Search:Query Insights
To Reproduce
- Run
./gradlew runlocally. - Run the first tutorial linked here with profile enabled, but before you run the query make sure to enable concurrent search mode:
curl -XPUT "http://localhost:9200/electronics/_settings" -H 'Content-Type: application/json' -d'
{
"index.search.concurrent_segment_search.mode": "all"
}
'
- See that certain timers have incorrectly large values. For example:
"next_doc": 221024744949916,
"advance": 221024744964625,
"score": 221024744964166,
Expected behavior
All of these values should be 0 if the timer was never invoked.
Additional Details
Screenshots
"profile": {
"shards": [
{
"id": "[vdRZ_0eZTRKvrWF7ThQN7Q][electronics][0]",
"inbound_network_time_in_millis": 0,
"outbound_network_time_in_millis": 0,
"searches": [
{
"query": [
{
"type": "BooleanQuery",
"description": "#brand:BrandA #category:Smartphone",
"time_in_nanos": 447834,
"max_slice_time_in_nanos": 265000,
"min_slice_time_in_nanos": 86292,
"avg_slice_time_in_nanos": 175646,
"breakdown": {
"max_match": 0,
"set_min_competitive_score_count": 0,
"match_count": 0,
"avg_score_count": 0,
"shallow_advance_count": 0,
"next_doc": 221024744967000,
"min_build_scorer": 86292,
"score_count": 1,
"compute_max_score_count": 0,
"advance": 0,
"min_set_min_competitive_score": 0,
"min_advance": 0,
"score": 221024744964166,
"avg_set_min_competitive_score_count": 0,
"min_match_count": 0,
"avg_score": 166,
"max_next_doc_count": 2,
"max_compute_max_score_count": 0,
"avg_shallow_advance": 0,
"max_shallow_advance_count": 0,
"set_min_competitive_score": 0,
"min_build_scorer_count": 1,
"next_doc_count": 2,
"min_match": 0,
"avg_next_doc": 15146,
"compute_max_score": 0,
"min_set_min_competitive_score_count": 0,
"max_build_scorer": 227166,
"avg_match_count": 0,
"avg_advance": 0,
"build_scorer_count": 3,
"avg_build_scorer_count": 1,
"max_score_count": 1,
"avg_match": 0,
"avg_compute_max_score": 0,
"max_advance": 0,
"avg_build_scorer": 156729,
"max_set_min_competitive_score_count": 0,
"advance_count": 0,
"max_build_scorer_count": 2,
"shallow_advance": 0,
"min_compute_max_score": 0,
"max_match_count": 0,
"create_weight_count": 1,
"build_scorer": 227166,
"min_score": 0,
"max_next_doc": 30292,
"create_weight": 22917,
"avg_next_doc_count": 1,
"max_score": 333,
"min_compute_max_score_count": 0,
"min_score_count": 0,
"min_advance_count": 0
},
"children": [
{
"type": "TermQuery",
"description": "brand:BrandA",
"time_in_nanos": 422750,
"max_slice_time_in_nanos": 239250,
"min_slice_time_in_nanos": 54000,
"avg_slice_time_in_nanos": 146625,
"breakdown": {
"max_match": 0,
"set_min_competitive_score_count": 0,
"match_count": 0,
"avg_score_count": 0,
"shallow_advance_count": 0,
"next_doc": 221024744949916,
"min_build_scorer": 54000,
"score_count": 0,
"compute_max_score_count": 0,
"advance": 0,
"min_set_min_competitive_score": 0,
"min_advance": 0,
"score": 0,
"avg_set_min_competitive_score_count": 0,
"min_match_count": 0,
"avg_score": 0,
"max_next_doc_count": 2,
"min_build_scorer_count": 1,
"next_doc_count": 2,
"min_match": 0,
"avg_next_doc": 6104,
"compute_max_score": 0,
"min_set_min_competitive_score_count": 0,
"max_build_scorer": 111750,
"avg_match_count": 0,
"avg_advance": 0,
"build_scorer_count": 4,
"avg_build_scorer_count": 2,
"min_next_doc_count": 0,
"min_shallow_advance_count": 0,
"max_score_count": 0,
"avg_match": 0,
"avg_build_scorer": 82875,
"max_set_min_competitive_score_count": 0,
"advance_count": 0,
"max_build_scorer_count": 3,
"shallow_advance": 0,
"min_compute_max_score": 0,
"max_match_count": 0,
"create_weight_count": 1,
"build_scorer": 111917,
"max_set_min_competitive_score": 0,
"max_compute_max_score": 0,
"min_shallow_advance": 0,
"min_score": 0,
"max_next_doc": 12208,
"create_weight": 5334,
"avg_next_doc_count": 1,
"max_score": 0,
"min_compute_max_score_count": 0,
"min_score_count": 0,
"min_advance_count": 0
}
},
{
"type": "TermQuery",
"description": "category:Smartphone",
"time_in_nanos": 425209,
"max_slice_time_in_nanos": 184584,
"min_slice_time_in_nanos": 18250,
"avg_slice_time_in_nanos": 101417,
"breakdown": {
"max_match": 0,
"set_min_competitive_score_count": 0,
"match_count": 0,
"avg_score_count": 0,
"shallow_advance_count": 0,
"next_doc": 0,
"min_build_scorer": 18250,
"score_count": 0,
"compute_max_score_count": 0,
"advance": 221024744964625,
"min_set_min_competitive_score": 0,
"next_doc_count": 0,
"min_match": 0,
"avg_next_doc": 0,
"compute_max_score": 0,
"min_set_min_competitive_score_count": 0,
"max_build_scorer": 60834,
"avg_match_count": 0,
"avg_advance": 7250,
"build_scorer_count": 4,
"avg_build_scorer_count": 2,
"min_next_doc_count": 0,
"min_shallow_advance_count": 0,
"max_score_count": 0,
"avg_match": 0,
"avg_compute_max_score": 0,
"max_advance": 14500,
"avg_shallow_advance_count": 0,
"avg_set_min_competitive_score": 0,
"avg_compute_max_score_count": 0,
"avg_build_scorer": 39542,
"max_set_min_competitive_score_count": 0,
"advance_count": 2,
"max_build_scorer_count": 3,
"shallow_advance": 0,
"min_compute_max_score": 0,
"max_match_count": 0,
"create_weight_count": 1,
"build_scorer": 66334,
"max_set_min_competitive_score": 0,
"max_compute_max_score": 0,
"min_shallow_advance": 0,
"match": 0,
"max_shallow_advance": 0,
"avg_advance_count": 1,
"min_next_doc": 0,
"max_advance_count": 2,
"min_score": 0,
"max_next_doc": 0,
"create_weight": 1667,
}
}
]
}
],
"rewrite_time": 73708,
"collector": [
{
"name": "SimpleTopDocsCollectorManager",
"reason": "search_top_hits",
"time_in_nanos": 93542,
"reduce_time_in_nanos": 24625,
"max_slice_time_in_nanos": 7168,
"min_slice_time_in_nanos": 1667,
"avg_slice_time_in_nanos": 4417,
"slice_count": 2
}
]
}
],
"aggregations": []
}
]
}
Host/Environment (please complete the following information):
- OS: MacOS Sequoia 15.5
- running most recent version of
mainbranch