airborne12 opened a new pull request, #62301:
URL: https://github.com/apache/doris/pull/62301
### What problem does this PR solve?
Issue Number: close #xxx
Related PR: #xxx
Problem Summary:
The SEARCH path
(`FunctionSearch::evaluate_inverted_index_with_search_param`) currently lays
out its profile sub-timers in a way that breaks two invariants that already
hold in the MATCH path (`FullTextIndexReader::query`):
```
(a) InvertedIndexQueryTime ≈ InvertedIndexSearcherOpenTime
+ InvertedIndexSearcherSearchTime
(b) InvertedIndexSearcherSearchTime ≈ InvertedIndexSearcherSearchInitTime
+ InvertedIndexSearcherSearchExecTime
```
Observed on a production SEARCH query scanning 237 segments (cumulative):
```
InvertedIndexFilterTime: 1min1sec
InvertedIndexQueryTime: 8sec617ms
InvertedIndexSearcherOpenTime: 5sec698ms
InvertedIndexSearcherSearchTime: 8sec612ms
InvertedIndexSearcherSearchInitTime:5sec704ms
InvertedIndexSearcherSearchExecTime:62.42us
```
- **(a) fails:** `SearchTime + OpenTime = 14310ms`, far exceeds `QueryTime =
8617ms`. Root cause: `OpenTime` is scoped inside
`FieldReaderResolver::resolve`, which is called from `build_query_recursive`,
which was itself wrapped by `SearchInitTime` → `SearchTime`. So OpenTime was
**nested inside SearchTime**, not a sibling, and adding them as siblings
double-counts the open phase.
- **(b) fails:** `SearchTime − SearchInitTime − SearchExecTime ≈ 2.9 s` of
completely untimed work. Root cause: `weight->scorer(...)` — which is where
per-term posting-list iterators are actually opened — lived between the old
SearchInitTime (only wrapping `build_query_recursive`) and SearchExecTime (only
wrapping the result-collection loop), so it was not attributed to any sub-timer.
This PR restructures the execution path in
`evaluate_inverted_index_with_search_param` to mirror the MATCH path semantics:
`QueryTime` wraps everything; inside `QueryTime`, `OpenTime` and `SearchTime`
are siblings; inside `SearchTime`, `SearchInitTime` and `SearchExecTime` are
siblings.
**Changes in `be/src/exprs/function/function_search.cpp`:**
- Move `build_query_recursive(...)` **outside** the `search_timer` scope. It
still opens searchers via `FieldReaderResolver::resolve`, so `OpenTime`
accumulates as before — it is simply no longer nested inside `SearchTime`.
- Redefine `SearchInitTime` to wrap `Query::weight(...)` — the SEARCH analog
of `query->add(query_info)` in MATCH: preparing the executable query structure.
- Extend `SearchExecTime` to wrap the `collect_multi_segment_*` iteration
(where `weight->scorer(...)` opens posting-list iterators) **plus** the lazy
null-bitmap fetch that follows.
- Move `InvertedIndexResultBitmap` construction, `mask_out_null()`, and the
DSL cache insert **outside** `SearchTime` — still inside `QueryTime` —
mirroring how `FullTextIndexReader::query` does `cache->insert(...)` only after
`match_index_search` returns.
**Complementary diagnostic in
`SegmentIterator::_get_row_ranges_by_column_conditions`:**
`InvertedIndexFilterTime` now has three sibling child timers so that
`FilterTime ≈ ApplyColPred + ApplyExpr + PostFilter` holds by construction,
making the `FilterTime ↔ QueryTime` gap always explainable from the profile
alone:
- `InvertedIndexApplyColPredTime` — wraps `_apply_inverted_index()`
- `InvertedIndexApplyExprTime` — wraps `_apply_index_expr()` (contains
`InvertedIndexQueryTime`)
- `InvertedIndexPostFilterTime` — wraps post-filter bitmap `&=` + per-column
`_check_all_conditions_passed_inverted_index_for_column`
**Also in `be/src/exprs/vsearch.cpp`
(`VSearchExpr::evaluate_inverted_index`):**
- Demote the per-segment `LOG(INFO)` / `LOG(WARNING)` on benign early-exit
paths to `VLOG_DEBUG`. At production scan rates these add measurable cumulative
wall-clock to `FilterTime` while contributing nothing useful at INFO level.
- Pass the result bitmap to `set_index_result_for_expr` via `std::move` to
avoid a per-segment deep copy of the underlying roaring bitmap.
**Verification:**
After the fix, small-test profile now shows:
```
QueryTime: 603.740us
OpenTime: 297.914us \_ sum = 452.68us ≈ QueryTime (drift
~fixed overhead)
SearchTime: 154.771us /
SearchInitTime: 74.950us \_ sum = 151.19us ≈ SearchTime (2.3%
drift)
SearchExecTime: 76.236us /
```
Projected on the production profile: `QueryTime ≈ OpenTime (5.7s) +
SearchTime (2.9s) ≈ 8.6s`, invariant (a) restored; `SearchTime ≈ SearchInitTime
(2.9s) + SearchExecTime (~4ms)`, invariant (b) restored; the 2.9 s of
previously-untimed scorer construction is now attributed to `SearchInitTime`.
### Release note
Fix `InvertedIndexSearcher*Time` profile sub-timer hierarchy in the
`search()` function path so that `QueryTime ≈ OpenTime + SearchTime` and
`SearchTime ≈ SearchInitTime + SearchExecTime`, matching MATCH-path semantics.
Also add three sub-timers (`InvertedIndexApplyColPredTime`,
`InvertedIndexApplyExprTime`, `InvertedIndexPostFilterTime`) under
`InvertedIndexFilterTime` so that the filter block's wall time is fully
attributed.
### Check List (For Author)
- Test
- [ ] Regression test
- [x] Unit Test
- [x] Manual test (add detailed scripts or steps below)
- [ ] No need to test or manual test. Explain why:
- [ ] This is a refactor/code format and no logic has been changed.
- [ ] Previous test can cover this change.
- [ ] No code files have been changed.
- [ ] Other reason
Unit test added:
`be/test/storage/segment/segment_iterator_filter_sub_timer_test.cpp` — pins
both invariants by running `SCOPED_RAW_TIMER` on the `OlapReaderStatistics`
fields in the same nesting shape as the production code and asserting `parent ≥
sum(children)` with a sub-ms drift bound. Any future regression that re-nests
`OpenTime` inside `SearchTime` or drops a sub-timer around the
scorer-construction phase will flip these assertions.
Manual test: rebuilt BE, deployed to a local cloud-sim cluster, ran
`SELECT id FROM t_search_metrics WHERE search('content:doris') ORDER BY id`
with `enable_profile=true profile_level=2`, verified the new counters appear
and that `QueryTime ≈ OpenTime + SearchTime` and `SearchTime ≈ SearchInitTime +
SearchExecTime`.
- Behavior changed:
- [x] No.
- [ ] Yes.
This PR only changes profile-timer scope placement and two non-functional
micro-optimizations (LOG → VLOG_DEBUG, one `std::move`). The query result is
unchanged.
- Does this need documentation?
- [x] No.
- [ ] Yes.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
