Fix timing bug with DFS profiling #92421
Merged
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
benwtrent
added
>bug
:Search/Search
|
Hi @benwtrent, I've created a changelog YAML for you. |
|
Pinging @elastic/es-search (Team:Search) |
|
Here is what hybrid-search profile looks like for DFS: {
"profile": {
"shards": [
{
"id": "[JtUlpv_9S4yYUpkimBBw_g][image-index][0]",
"dfs": {
"statistics": {
"type": "statistics",
"description": "collect term statistics",
"time_in_nanos": 359750,
"breakdown": {
"term_statistics": 2833,
"collection_statistics": 42916,
"collection_statistics_count": 2,
"create_weight": 350917,
"term_statistics_count": 1,
"rewrite_count": 0,
"create_weight_count": 1,
"rewrite": 0
}
},
"knn": {
"query": [
{
"type": "BoostQuery",
"description": "(DocAndScore[50])^0.1",
"time_in_nanos": 329293,
"breakdown": {
"set_min_competitive_score_count": 0,
"match_count": 0,
"shallow_advance_count": 0,
"set_min_competitive_score": 0,
"next_doc": 1709,
"match": 0,
"next_doc_count": 4,
"score_count": 4,
"compute_max_score_count": 0,
"compute_max_score": 0,
"advance": 308750,
"advance_count": 3,
"count_weight_count": 0,
"score": 1376,
"build_scorer_count": 6,
"create_weight": 2084,
"shallow_advance": 0,
"count_weight": 0,
"create_weight_count": 1,
"build_scorer": 15374
}
}
],
"rewrite_time": 317792,
"collector": [
{
"name": "SimpleTopScoreDocCollector",
"reason": "search_top_hits",
"time_in_nanos": 21626
}
]
}
},
"searches": [
{
"query": [
{
"type": "BooleanQuery",
"description": "ScoreAndDocQuery (title:mountain title:lake)^0.9",
"time_in_nanos": 827749,
"breakdown": {
"set_min_competitive_score_count": 0,
"match_count": 1,
"shallow_advance_count": 0,
"set_min_competitive_score": 0,
"next_doc": 24666,
"match": 583,
"next_doc_count": 4,
"score_count": 4,
"compute_max_score_count": 0,
"compute_max_score": 0,
"advance": 46250,
"advance_count": 3,
"count_weight_count": 0,
"score": 10666,
"build_scorer_count": 6,
"create_weight": 346459,
"shallow_advance": 0,
"count_weight": 0,
"create_weight_count": 1,
"build_scorer": 399125
},
"children": [
{
"type": "KnnScoreDocQuery",
"description": "ScoreAndDocQuery",
"time_in_nanos": 41460,
"breakdown": {
"set_min_competitive_score_count": 0,
"match_count": 0,
"shallow_advance_count": 4,
"set_min_competitive_score": 0,
"next_doc": 1751,
"match": 0,
"next_doc_count": 3,
"score_count": 4,
"compute_max_score_count": 4,
"compute_max_score": 2958,
"advance": 6084,
"advance_count": 4,
"count_weight_count": 0,
"score": 1750,
"build_scorer_count": 9,
"create_weight": 2500,
"shallow_advance": 4750,
"count_weight": 0,
"create_weight_count": 1,
"build_scorer": 21667
}
},
{
"type": "BoostQuery",
"description": "(title:mountain title:lake)^0.9",
"time_in_nanos": 536040,
"breakdown": {
"set_min_competitive_score_count": 0,
"match_count": 0,
"shallow_advance_count": 4,
"set_min_competitive_score": 0,
"next_doc": 0,
"match": 0,
"next_doc_count": 0,
"score_count": 1,
"compute_max_score_count": 4,
"compute_max_score": 16083,
"advance": 5583,
"advance_count": 2,
"count_weight_count": 0,
"score": 4334,
"build_scorer_count": 5,
"create_weight": 322667,
"shallow_advance": 7208,
"count_weight": 0,
"create_weight_count": 1,
"build_scorer": 180165
},
"children": [
{
"type": "TermQuery",
"description": "title:mountain",
"time_in_nanos": 188875,
"breakdown": {
"set_min_competitive_score_count": 0,
"match_count": 0,
"shallow_advance_count": 0,
"set_min_competitive_score": 0,
"next_doc": 0,
"match": 0,
"next_doc_count": 0,
"score_count": 0,
"compute_max_score_count": 0,
"compute_max_score": 0,
"advance": 0,
"advance_count": 0,
"count_weight_count": 0,
"score": 0,
"build_scorer_count": 3,
"create_weight": 150625,
"shallow_advance": 0,
"count_weight": 0,
"create_weight_count": 1,
"build_scorer": 38250
}
},
{
"type": "TermQuery",
"description": "title:lake",
"time_in_nanos": 283167,
"breakdown": {
"set_min_competitive_score_count": 0,
"match_count": 0,
"shallow_advance_count": 4,
"set_min_competitive_score": 0,
"next_doc": 0,
"match": 0,
"next_doc_count": 0,
"score_count": 1,
"compute_max_score_count": 4,
"compute_max_score": 14042,
"advance": 4292,
"advance_count": 2,
"count_weight_count": 0,
"score": 3792,
"build_scorer_count": 5,
"create_weight": 152041,
"shallow_advance": 5126,
"count_weight": 0,
"create_weight_count": 1,
"build_scorer": 103874
}
}
]
}
]
}
],
"rewrite_time": 190207,
"collector": [
{
"name": "SimpleTopScoreDocCollector",
"reason": "search_top_hits",
"time_in_nanos": 30917
}
]
}
],
"aggregations": [],
"fetch": {
"type": "fetch",
"description": "",
"time_in_nanos": 556500,
"breakdown": {
"load_stored_fields": 204959,
"load_source": 31585,
"load_stored_fields_count": 4,
"next_reader_count": 3,
"load_source_count": 4,
"next_reader": 63584
},
"debug": {
"stored_fields": [
"_id",
"_routing",
"_source"
]
},
"children": [
{
"type": "FetchSourcePhase",
"description": "",
"time_in_nanos": 21584,
"breakdown": {
"process_count": 4,
"process": 20583,
"next_reader": 1001,
"next_reader_count": 3
},
"debug": {
"fast_path": 4
}
},
{
"type": "StoredFieldsPhase",
"description": "",
"time_in_nanos": 15376,
"breakdown": {
"process_count": 4,
"process": 13624,
"next_reader": 1752,
"next_reader_count": 3
}
}
]
}
}
]
}
} |
|
@elasticmachine update branch |
|
@elasticmachine update branch |
benwtrent
added
the
auto-backport-and-merge
💚 Backport successful
|
benwtrent
added a commit
to benwtrent/elasticsearch
that referenced
this pull request
Jan 3, 2023
Introduced in: elastic#90536 Profiling for DFS has had its timing numbers looking weird, additionally, it would trigger some assertion failures because `timer.start()` was called without a `stop()` in between. The key issue was around query `weight` creation. `Weight` creation could be called recursively, thus calling `start` on the timer more than once before calling stop.
elasticsearchmachine
pushed a commit
that referenced
this pull request
Jan 3, 2023
Introduced in: #90536 Profiling for DFS has had its timing numbers looking weird, additionally, it would trigger some assertion failures because `timer.start()` was called without a `stop()` in between. The key issue was around query `weight` creation. `Weight` creation could be called recursively, thus calling `start` on the timer more than once before calling stop.
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Introduced in: #90536
Profiling for DFS has had its timing numbers looking weird, additionally, it would trigger some assertion failures because
timer.start()was called without astop()in between.The key issue was around query
weightcreation.Weightcreation could be called recursively, thus callingstarton the timer more than once before calling stop.