[fix](profile) populate inverted index metrics for SEARCH() query path#62121
Open
airborne12 wants to merge 2 commits intoapache:masterfrom
Open
[fix](profile) populate inverted index metrics for SEARCH() query path#62121airborne12 wants to merge 2 commits intoapache:masterfrom
airborne12 wants to merge 2 commits intoapache:masterfrom
Conversation
SEARCH() uses query_v2 engine bypassing InvertedIndexReader::query(), causing all inverted index profile metrics to be zero. This patch fixes three independent issues: 1. Query-level timers: Add SCOPED_RAW_TIMER instrumentation in function_search.cpp for inverted_index_query_timer, searcher_open/search/init/exec timers, and cache hit/miss counters. 2. FileCache IO attribution: Fix IOContext propagation in compound reader so that file_cache_stats and is_inverted_index flag reach CachedRemoteFileReader. Store io_ctx in DorisCompoundReader and propagate to CSIndexInput on openInput(); copy _io_ctx in CSIndexInput clone constructor. 3. Profile counter visibility: Change inverted index counter registration from default level=2 to level=1 so they survive profile pruning.
Contributor
|
Thank you for your contribution to Apache Doris. Please clearly describe your PR:
|
Member
Author
|
run buildall |
TPC-H: Total hot run time: 28971 ms |
TPC-DS: Total hot run time: 178632 ms |
Member
Author
|
run buildall |
TPC-H: Total hot run time: 28691 ms |
TPC-DS: Total hot run time: 178379 ms |
BE UT Coverage ReportIncrement line coverage Increment coverage report
|
Contributor
BE Regression && UT Coverage ReportIncrement line coverage Increment coverage report
|
Contributor
BE Regression && UT Coverage ReportIncrement line coverage Increment coverage report
|
Member
Author
|
/review |
![github-actions[bot]](https://avatars.githubusercontent.com/in/15368?s=60&v=4){kind=small}
Contributor
There was a problem hiding this comment.
Findings:
be/src/exprs/function/function_search.cpp:inverted_index_searcher_cache_hitis incremented whenFieldReaderResolverreuses its per-query_cache. That cache is distinct fromInvertedIndexSearcherCache, so repeated clauses on the same field will report a cache hit even when the global searcher cache missed.be/src/exprs/function/function_search.cpp: the SEARCH DSL-cache fast path still returns beforeinverted_index_query_timeris started, and it never updatesinverted_index_query_cache_hit/miss. Cached SEARCH queries will therefore keep showingInvertedIndexQueryTime: 0andInvertedIndexQueryCacheHit/Miss: 0.
Critical checkpoints:
- Goal of the task: Partially achieved. The PR fixes open/search timing visibility and IO-context propagation, but SEARCH query-cache metrics are still incomplete and one cache-hit counter is now overstated.
- Modification size/focus: Yes, the patch is small and focused.
- Concurrency: No new lock-order or thread-safety issue found in the touched code; the reported issue is metric semantics, not synchronization.
- Lifecycle/static initialization:
DorisCompoundReaderIO-context propagation looks lifecycle-safe; no static-initialization risk found. - Configuration changes: None.
- Compatibility changes: None.
- Parallel code paths: Not fully aligned. MATCH counts only real
InvertedIndexSearcherCachehits and times the whole query including cache handling, while SEARCH still diverges on cached paths. - Special conditional checks: No additional issue found.
- Test coverage: Insufficient for this change. I did not find SEARCH-path tests that assert query timer/cache counters, which is why these regressions slipped through.
- Observability: Improved, but still incomplete on cached SEARCH queries.
- Transaction/persistence: Not applicable.
- Data writes/modifications: Not applicable.
- FE-BE variable passing: Not applicable.
- Performance review: No additional hot-path concern beyond the incorrect metric accounting above.
- Other issues: None beyond the findings listed above.
| auto cache_it = _cache.find(binding_key); | ||
| if (cache_it != _cache.end()) { | ||
| *binding = cache_it->second; | ||
| if (_context->stats) { |
Contributor
There was a problem hiding this comment.
_cache here is the resolver's per-query binding cache, not InvertedIndexSearcherCache. Incrementing inverted_index_searcher_cache_hit on this fast path changes the metric's meaning and double-counts hits when the same field is referenced multiple times in one SEARCH() evaluation. On a cold segment, the first clause will record the real miss at the later cache-open path, and a second clause on the same field will record a synthetic hit here even though the global searcher cache was never consulted.
| @@ -434,6 +447,11 @@ Status FunctionSearch::evaluate_inverted_index_with_search_param( | |||
| } | |||
Contributor
There was a problem hiding this comment.
This timer still starts after the SEARCH DSL-cache lookup/return path above. When dsl_cache->lookup() returns a bitmap, the function exits before reaching this scope, so InvertedIndexQueryTime remains 0 on query-cache hits. The same fast path also never updates inverted_index_query_cache_hit/miss, so cached SEARCH queries are still invisible in the profile even after this patch.
This file contains hidden or 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
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
3 participants
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.
What problem does this PR solve?
Issue Number: close #xxx
Related PR: #xxx
Problem Summary:
SEARCH() function uses the query_v2 engine, which bypasses
InvertedIndexReader::query(). This causes all inverted index profile metrics to report zero, making it impossible to diagnose SEARCH() performance issues from query profiles.Three independent problems were identified and fixed:
1. Query-level timers not populated (function_search.cpp)
The MATCH path populates
inverted_index_query_timer,searcher_open_timer,searcher_search_timer, etc. viaSCOPED_RAW_TIMERininverted_index_reader.cpp. The SEARCH path bypasses this entirely —FieldReaderResolver::resolve()opens the index andevaluate_inverted_index_with_search_param()executes the query without any timer instrumentation.Fix: Add
SCOPED_RAW_TIMERat corresponding points infunction_search.cpp:inverted_index_query_timeraround the entire evaluationinverted_index_searcher_open_timeraround searcher cache miss (directory open)inverted_index_searcher_search_timeraround query build + executioninverted_index_searcher_search_init_timeraroundbuild_query_recursive()inverted_index_searcher_search_exec_timeraroundcollect_multi_segment_doc_set/top_k()inverted_index_searcher_cache_hit/misscounters inresolve()2. FileCache IO not attributed to inverted index (inverted_index_compound_reader)
CSIndexInputclone constructor did not copy_io_ctx, causing cloned inputs to read withoutfile_cache_stats— soInvertedIndexBytesScannedFromRemote/Cacheetc. stayed zero. Additionally,DorisCompoundReader::openInput()created newCSIndexInputwithout setting_io_ctx, so query_v2 scorer reads lacked proper IO context.Fix:
_io_ctxinCSIndexInputclone constructor_io_ctxinDorisCompoundReaderand propagate it to newCSIndexInputinopenInput()3. Profile counters pruned by level (olap_scan_operator.cpp)
All inverted index counters were registered with default
level=2viaADD_TIMER/ADD_COUNTER. The profile display system prunes level-2 leaf counters whenprofile_level < 2, making them invisible in query profiles. The FileCache counters usedADD_CHILD_TIMER_WITH_LEVEL(..., 1)and were visible.Fix: Register inverted index counters with
level=1viaADD_TIMER_WITH_LEVEL/ADD_COUNTER_WITH_LEVEL.Release note
None
Check List (For Author)
Test
InvertedIndexBytesScannedFromRemote: 1.15 KB,InvertedIndexNumRemoteIOTotal: 1,InvertedIndexRemoteIOUseTimer: 46.919msInvertedIndexBytesScannedFromCache: 1.15 KB,InvertedIndexNumLocalIOTotal: 1InvertedIndexQueryTime: 51.155ms,InvertedIndexSearcherOpenTime: 49.196ms,InvertedIndexSearcherSearchTime: 51.60ms,InvertedIndexSearcherCacheMiss: 1Behavior changed:
Does this need documentation?
Check List (For Reviewer who merge this PR)