You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@doris.apache.org by ai...@apache.org on 2026/04/07 14:02:42 UTC
(doris) branch master updated: [fix](profile) populate inverted index metrics for SEARCH() query path (#62121)
This is an automated email from the ASF dual-hosted git repository.
airborne pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/doris.git
The following commit(s) were added to refs/heads/master by this push:
new 361bbed335a [fix](profile) populate inverted index metrics for SEARCH() query path (#62121)
361bbed335a is described below
commit 361bbed335a5c9b5ee19d89fd5014414a61fd0d9
Author: Jack <ji...@selectdb.com>
AuthorDate: Tue Apr 7 22:02:33 2026 +0800
[fix](profile) populate inverted index metrics for SEARCH() query path (#62121)
### 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.
Four 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. via
`SCOPED_RAW_TIMER` in `inverted_index_reader.cpp`. The SEARCH path
bypasses this entirely — `FieldReaderResolver::resolve()` opens the
index and `evaluate_inverted_index_with_search_param()` executes the
query without any timer instrumentation.
Fix: Add `SCOPED_RAW_TIMER` at corresponding points in
`function_search.cpp`:
- `inverted_index_query_timer` around the entire evaluation (placed
before DSL cache lookup so cache-hit path is also timed)
- `inverted_index_searcher_open_timer` around searcher cache miss
(directory open)
- `inverted_index_searcher_search_timer` around query build + execution
- `inverted_index_searcher_search_init_timer` around
`build_query_recursive()`
- `inverted_index_searcher_search_exec_timer` around
`collect_multi_segment_doc_set/top_k()`
- `inverted_index_searcher_cache_hit/miss` counters in `resolve()`
- `inverted_index_lookup_timer` around both DSL cache and searcher cache
lookups
- `inverted_index_query_cache_hit/miss` counters on DSL cache lookup
**2. io_ctx dangling pointer in cached IndexSearcher
(function_search.cpp)**
`FieldReaderResolver::resolve()` opens the index directory with the
caller's `io_ctx`, builds an IndexSearcher, and inserts it into the
global `InvertedIndexSearcherCache`. The cached searcher's underlying
`DorisCompoundReader` main stream retains a raw pointer to the caller's
`io_ctx`. When the originating scan context is destroyed, this pointer
dangles — any subsequent cache hit from a different query would read
through a stale `io_ctx`, causing use-after-free (caught by ASAN).
Fix: After building the IndexSearcher and before inserting into cache,
clear the main stream's `io_ctx` via `stream->setIoContext(nullptr)`.
Subsequent query-phase reads receive the caller's `io_ctx` through
CLucene API parameters (`termDocs`/`termPositions`/`terms`) — the same
pattern used by the MATCH path in
`InvertedIndexReader::create_index_searcher()`.
**3. Profile counters pruned by level (olap_scan_operator.cpp)**
All inverted index counters were registered with default `level=2` via
`ADD_TIMER`/`ADD_COUNTER`. The profile display system prunes level-2
leaf counters when `profile_level < 2`, making them invisible in query
profiles. The FileCache counters used `ADD_CHILD_TIMER_WITH_LEVEL(...,
1)` and were visible.
Fix: Register inverted index counters with `level=1` via
`ADD_TIMER_WITH_LEVEL`/`ADD_COUNTER_WITH_LEVEL`.
**4. Cache control and metric accuracy issues (function_search.cpp)**
Code review identified several metric and cache control issues:
- DSL query-cache hit path returned early before
`inverted_index_query_timer` scope, resulting in
`InvertedIndexQueryTime=0` for warm queries.
- Searcher cache lookup was unconditional, ignoring
`enable_inverted_index_searcher_cache` session variable. A second query
with cache disabled could silently hit the cache.
- Resolver local `_cache` hit (same field referenced multiple times
within one DSL) was incorrectly counted as
`inverted_index_searcher_cache_hit`, inflating the metric.
- `InvertedIndexLookupTimer` was not instrumented in the SEARCH path.
Fix:
- Move `inverted_index_query_timer` before DSL cache lookup so cache-hit
fast path is also timed.
- Gate searcher cache lookup on `enable_inverted_index_searcher_cache`
(matching MATCH path in `InvertedIndexReader::handle_searcher_cache`).
Insert remains unconditional for consistency.
- Remove false `inverted_index_searcher_cache_hit++` from resolver local
`_cache` hit.
- Add `SCOPED_RAW_TIMER` for `inverted_index_lookup_timer` around both
DSL and searcher cache lookups.
- Record `inverted_index_query_cache_hit/miss` on DSL cache lookup
result.
- Add regression tests: DSL query-cache hit path, searcher cache
disabled with two runs.
---
be/src/exec/operator/olap_scan_operator.cpp | 40 +--
be/src/exprs/function/function_search.cpp | 113 ++++++--
.../inverted/inverted_index_compound_reader.cpp | 2 +-
.../inverted_index_compound_reader_test.cpp | 57 ++++
.../search/test_search_inverted_index_profile.out | 22 ++
.../test_search_inverted_index_profile.groovy | 302 +++++++++++++++++++++
6 files changed, 499 insertions(+), 37 deletions(-)
diff --git a/be/src/exec/operator/olap_scan_operator.cpp b/be/src/exec/operator/olap_scan_operator.cpp
index ccdd82bc5f1..33130245099 100644
--- a/be/src/exec/operator/olap_scan_operator.cpp
+++ b/be/src/exec/operator/olap_scan_operator.cpp
@@ -238,33 +238,37 @@ Status OlapScanLocalState::_init_profile() {
_statistics_collect_timer = ADD_TIMER(_scanner_profile, "StatisticsCollectTime");
_inverted_index_filter_counter =
- ADD_COUNTER(_segment_profile, "RowsInvertedIndexFiltered", TUnit::UNIT);
- _inverted_index_filter_timer = ADD_TIMER(_segment_profile, "InvertedIndexFilterTime");
+ ADD_COUNTER_WITH_LEVEL(_segment_profile, "RowsInvertedIndexFiltered", TUnit::UNIT, 1);
+ _inverted_index_filter_timer =
+ ADD_TIMER_WITH_LEVEL(_segment_profile, "InvertedIndexFilterTime", 1);
_inverted_index_query_cache_hit_counter =
- ADD_COUNTER(_segment_profile, "InvertedIndexQueryCacheHit", TUnit::UNIT);
+ ADD_COUNTER_WITH_LEVEL(_segment_profile, "InvertedIndexQueryCacheHit", TUnit::UNIT, 1);
_inverted_index_query_cache_miss_counter =
- ADD_COUNTER(_segment_profile, "InvertedIndexQueryCacheMiss", TUnit::UNIT);
- _inverted_index_query_timer = ADD_TIMER(_segment_profile, "InvertedIndexQueryTime");
+ ADD_COUNTER_WITH_LEVEL(_segment_profile, "InvertedIndexQueryCacheMiss", TUnit::UNIT, 1);
+ _inverted_index_query_timer =
+ ADD_TIMER_WITH_LEVEL(_segment_profile, "InvertedIndexQueryTime", 1);
_inverted_index_query_null_bitmap_timer =
- ADD_TIMER(_segment_profile, "InvertedIndexQueryNullBitmapTime");
+ ADD_TIMER_WITH_LEVEL(_segment_profile, "InvertedIndexQueryNullBitmapTime", 1);
_inverted_index_query_bitmap_copy_timer =
- ADD_TIMER(_segment_profile, "InvertedIndexQueryBitmapCopyTime");
+ ADD_TIMER_WITH_LEVEL(_segment_profile, "InvertedIndexQueryBitmapCopyTime", 1);
_inverted_index_searcher_open_timer =
- ADD_TIMER(_segment_profile, "InvertedIndexSearcherOpenTime");
+ ADD_TIMER_WITH_LEVEL(_segment_profile, "InvertedIndexSearcherOpenTime", 1);
_inverted_index_searcher_search_timer =
- ADD_TIMER(_segment_profile, "InvertedIndexSearcherSearchTime");
+ ADD_TIMER_WITH_LEVEL(_segment_profile, "InvertedIndexSearcherSearchTime", 1);
_inverted_index_searcher_search_init_timer =
- ADD_TIMER(_segment_profile, "InvertedIndexSearcherSearchInitTime");
+ ADD_TIMER_WITH_LEVEL(_segment_profile, "InvertedIndexSearcherSearchInitTime", 1);
_inverted_index_searcher_search_exec_timer =
- ADD_TIMER(_segment_profile, "InvertedIndexSearcherSearchExecTime");
- _inverted_index_searcher_cache_hit_counter =
- ADD_COUNTER(_segment_profile, "InvertedIndexSearcherCacheHit", TUnit::UNIT);
- _inverted_index_searcher_cache_miss_counter =
- ADD_COUNTER(_segment_profile, "InvertedIndexSearcherCacheMiss", TUnit::UNIT);
+ ADD_TIMER_WITH_LEVEL(_segment_profile, "InvertedIndexSearcherSearchExecTime", 1);
+ _inverted_index_searcher_cache_hit_counter = ADD_COUNTER_WITH_LEVEL(
+ _segment_profile, "InvertedIndexSearcherCacheHit", TUnit::UNIT, 1);
+ _inverted_index_searcher_cache_miss_counter = ADD_COUNTER_WITH_LEVEL(
+ _segment_profile, "InvertedIndexSearcherCacheMiss", TUnit::UNIT, 1);
_inverted_index_downgrade_count_counter =
- ADD_COUNTER(_segment_profile, "InvertedIndexDowngradeCount", TUnit::UNIT);
- _inverted_index_analyzer_timer = ADD_TIMER(_segment_profile, "InvertedIndexAnalyzerTime");
- _inverted_index_lookup_timer = ADD_TIMER(_segment_profile, "InvertedIndexLookupTimer");
+ ADD_COUNTER_WITH_LEVEL(_segment_profile, "InvertedIndexDowngradeCount", TUnit::UNIT, 1);
+ _inverted_index_analyzer_timer =
+ ADD_TIMER_WITH_LEVEL(_segment_profile, "InvertedIndexAnalyzerTime", 1);
+ _inverted_index_lookup_timer =
+ ADD_TIMER_WITH_LEVEL(_segment_profile, "InvertedIndexLookupTimer", 1);
_output_index_result_column_timer = ADD_TIMER(_segment_profile, "OutputIndexResultColumnTime");
_filtered_segment_counter = ADD_COUNTER(_segment_profile, "NumSegmentFiltered", TUnit::UNIT);
diff --git a/be/src/exprs/function/function_search.cpp b/be/src/exprs/function/function_search.cpp
index de09e85c561..6c96da46c5b 100644
--- a/be/src/exprs/function/function_search.cpp
+++ b/be/src/exprs/function/function_search.cpp
@@ -37,9 +37,11 @@
#include "core/data_type/data_type_string.h"
#include "exprs/function/simple_function_factory.h"
#include "exprs/vexpr_context.h"
+#include "runtime/runtime_profile.h"
#include "storage/index/index_file_reader.h"
#include "storage/index/index_query_context.h"
#include "storage/index/inverted/analyzer/analyzer.h"
+#include "storage/index/inverted/inverted_index_compound_reader.h"
#include "storage/index/inverted/inverted_index_iterator.h"
#include "storage/index/inverted/inverted_index_parser.h"
#include "storage/index/inverted/inverted_index_reader.h"
@@ -62,6 +64,7 @@
#include "storage/segment/variant/nested_group_provider.h"
#include "storage/segment/variant/variant_column_reader.h"
#include "storage/types.h"
+#include "util/debug_points.h"
#include "util/string_util.h"
#include "util/thrift_util.h"
@@ -265,16 +268,31 @@ Status FieldReaderResolver::resolve(const std::string& field_name,
"index file reader is null for field '{}'", field_name);
}
- // Use InvertedIndexSearcherCache to avoid re-opening index files repeatedly
+ // Use InvertedIndexSearcherCache to avoid re-opening index files repeatedly,
+ // respecting the enable_inverted_index_searcher_cache session variable.
auto index_file_key =
index_file_reader->get_index_file_cache_key(&inverted_reader->get_index_meta());
InvertedIndexSearcherCache::CacheKey searcher_cache_key(index_file_key);
InvertedIndexCacheHandle searcher_cache_handle;
- bool cache_hit = InvertedIndexSearcherCache::instance()->lookup(searcher_cache_key,
- &searcher_cache_handle);
+
+ bool searcher_cache_enabled =
+ _context->runtime_state != nullptr &&
+ _context->runtime_state->query_options().enable_inverted_index_searcher_cache;
+
+ bool cache_hit = false;
+ if (searcher_cache_enabled) {
+ int64_t lookup_dummy = 0;
+ SCOPED_RAW_TIMER(_context->stats ? &_context->stats->inverted_index_lookup_timer
+ : &lookup_dummy);
+ cache_hit = InvertedIndexSearcherCache::instance()->lookup(searcher_cache_key,
+ &searcher_cache_handle);
+ }
std::shared_ptr<lucene::index::IndexReader> reader_holder;
if (cache_hit) {
+ if (_context->stats) {
+ _context->stats->inverted_index_searcher_cache_hit++;
+ }
auto searcher_variant = searcher_cache_handle.get_index_searcher();
auto* searcher_ptr = std::get_if<FulltextIndexSearcherPtr>(&searcher_variant);
if (searcher_ptr != nullptr && *searcher_ptr != nullptr) {
@@ -285,7 +303,13 @@ Status FieldReaderResolver::resolve(const std::string& field_name,
}
if (!reader_holder) {
+ if (_context->stats) {
+ _context->stats->inverted_index_searcher_cache_miss++;
+ }
// Cache miss: open directory, build IndexSearcher, insert into cache
+ int64_t dummy_timer = 0;
+ SCOPED_RAW_TIMER(_context->stats ? &_context->stats->inverted_index_searcher_open_timer
+ : &dummy_timer);
RETURN_IF_ERROR(
index_file_reader->init(config::inverted_index_read_buffer_size, _context->io_ctx));
auto directory = DORIS_TRY(
@@ -297,6 +321,26 @@ Status FieldReaderResolver::resolve(const std::string& field_name,
DORIS_TRY(index_searcher_builder->get_index_searcher(directory.get()));
auto reader_size = index_searcher_builder->get_reader_size();
+ // Initialization reads are done. Clear io_ctx on the main stream so the
+ // cached searcher does not carry a stale reference. Subsequent query-phase
+ // reads receive the caller's io_ctx through the CLucene API parameters
+ // (termDocs/termPositions/terms) — the same pattern used by the MATCH path
+ // in InvertedIndexReader::create_index_searcher().
+ auto* stream = static_cast<DorisCompoundReader*>(directory.get())->getDorisIndexInput();
+ DBUG_EXECUTE_IF(
+ "FieldReaderResolver.resolve.io_ctx", ({
+ const auto* cur_io_ctx = (const io::IOContext*)stream->getIoContext();
+ if (cur_io_ctx->file_cache_stats) {
+ if (cur_io_ctx->file_cache_stats != &_context->stats->file_cache_stats) {
+ LOG(FATAL) << "search: io_ctx file_cache_stats mismatch: "
+ << cur_io_ctx->file_cache_stats << " vs "
+ << &_context->stats->file_cache_stats;
+ }
+ }
+ }));
+ stream->setIoContext(nullptr);
+ stream->setIndexFile(false);
+
auto* cache_value = new InvertedIndexSearcherCache::CacheValue(std::move(searcher_result),
reader_size, UnixMillis());
InvertedIndexSearcherCache::instance()->insert(searcher_cache_key, cache_value,
@@ -395,6 +439,13 @@ Status FunctionSearch::evaluate_inverted_index_with_search_param(
return Status::OK();
}
+ // Track overall query time (equivalent to inverted_index_query_timer in MATCH path).
+ // Must be declared before the DSL cache lookup so that cache-hit fast paths are
+ // also covered by the timer.
+ int64_t query_timer_dummy = 0;
+ OlapReaderStatistics* outer_stats = index_query_context ? index_query_context->stats : nullptr;
+ SCOPED_RAW_TIMER(outer_stats ? &outer_stats->inverted_index_query_timer : &query_timer_dummy);
+
// DSL result cache: reuse InvertedIndexQueryCache with SEARCH_DSL_QUERY type
auto* dsl_cache = enable_cache ? InvertedIndexQueryCache::instance() : nullptr;
std::string seg_prefix;
@@ -410,9 +461,19 @@ Status FunctionSearch::evaluate_inverted_index_with_search_param(
dsl_sig};
cache_usable = true;
InvertedIndexQueryCacheHandle dsl_cache_handle;
- if (dsl_cache->lookup(dsl_cache_key, &dsl_cache_handle)) {
+ bool dsl_hit = false;
+ {
+ int64_t lookup_dummy = 0;
+ SCOPED_RAW_TIMER(outer_stats ? &outer_stats->inverted_index_lookup_timer
+ : &lookup_dummy);
+ dsl_hit = dsl_cache->lookup(dsl_cache_key, &dsl_cache_handle);
+ }
+ if (dsl_hit) {
auto cached_bitmap = dsl_cache_handle.get_bitmap();
if (cached_bitmap) {
+ if (outer_stats) {
+ outer_stats->inverted_index_query_cache_hit++;
+ }
// Also retrieve cached null bitmap for three-valued SQL logic
// (needed by compound operators NOT, OR, AND in VCompoundPred)
auto null_cache_key = InvertedIndexQueryCache::CacheKey {
@@ -431,6 +492,9 @@ Status FunctionSearch::evaluate_inverted_index_with_search_param(
return Status::OK();
}
}
+ if (outer_stats) {
+ outer_stats->inverted_index_query_cache_miss++;
+ }
}
}
@@ -542,11 +606,19 @@ Status FunctionSearch::evaluate_inverted_index_with_search_param(
minimum_should_match = search_param.minimum_should_match;
}
+ auto* stats = context->stats;
+ int64_t dummy_timer = 0;
+ SCOPED_RAW_TIMER(stats ? &stats->inverted_index_searcher_search_timer : &dummy_timer);
+
query_v2::QueryPtr root_query;
std::string root_binding_key;
- RETURN_IF_ERROR(build_query_recursive(search_param.root, context, resolver, &root_query,
- &root_binding_key, default_operator,
- minimum_should_match));
+ {
+ int64_t init_dummy = 0;
+ SCOPED_RAW_TIMER(stats ? &stats->inverted_index_searcher_search_init_timer : &init_dummy);
+ RETURN_IF_ERROR(build_query_recursive(search_param.root, context, resolver, &root_query,
+ &root_binding_key, default_operator,
+ minimum_should_match));
+ }
if (root_query == nullptr) {
LOG(INFO) << "search: Query tree resolved to empty query, dsl:"
<< search_param.original_dsl;
@@ -577,17 +649,22 @@ Status FunctionSearch::evaluate_inverted_index_with_search_param(
}
std::shared_ptr<roaring::Roaring> roaring = std::make_shared<roaring::Roaring>();
- if (enable_scoring && !is_asc && top_k > 0) {
- bool use_wand = index_query_context->runtime_state != nullptr &&
- index_query_context->runtime_state->query_options()
- .enable_inverted_index_wand_query;
- query_v2::collect_multi_segment_top_k(weight, exec_ctx, root_binding_key, top_k, roaring,
- index_query_context->collection_similarity, use_wand);
- } else {
- query_v2::collect_multi_segment_doc_set(
- weight, exec_ctx, root_binding_key, roaring,
- index_query_context ? index_query_context->collection_similarity : nullptr,
- enable_scoring);
+ {
+ int64_t exec_dummy = 0;
+ SCOPED_RAW_TIMER(stats ? &stats->inverted_index_searcher_search_exec_timer : &exec_dummy);
+ if (enable_scoring && !is_asc && top_k > 0) {
+ bool use_wand = index_query_context->runtime_state != nullptr &&
+ index_query_context->runtime_state->query_options()
+ .enable_inverted_index_wand_query;
+ query_v2::collect_multi_segment_top_k(
+ weight, exec_ctx, root_binding_key, top_k, roaring,
+ index_query_context->collection_similarity, use_wand);
+ } else {
+ query_v2::collect_multi_segment_doc_set(
+ weight, exec_ctx, root_binding_key, roaring,
+ index_query_context ? index_query_context->collection_similarity : nullptr,
+ enable_scoring);
+ }
}
VLOG_DEBUG << "search: Query completed, matched " << roaring->cardinality() << " documents";
diff --git a/be/src/storage/index/inverted/inverted_index_compound_reader.cpp b/be/src/storage/index/inverted/inverted_index_compound_reader.cpp
index b6d379c4133..6768aced7de 100644
--- a/be/src/storage/index/inverted/inverted_index_compound_reader.cpp
+++ b/be/src/storage/index/inverted/inverted_index_compound_reader.cpp
@@ -412,4 +412,4 @@ void DorisCompoundReader::initialize(const io::IOContext* io_ctx) {
}
} // namespace doris::segment_v2
-#include "common/compile_check_end.h"
\ No newline at end of file
+#include "common/compile_check_end.h"
diff --git a/be/test/storage/segment/inverted_index_compound_reader_test.cpp b/be/test/storage/segment/inverted_index_compound_reader_test.cpp
index 2fd921b2c9e..eaef09a6ba2 100644
--- a/be/test/storage/segment/inverted_index_compound_reader_test.cpp
+++ b/be/test/storage/segment/inverted_index_compound_reader_test.cpp
@@ -35,6 +35,7 @@
#include "gtest/gtest_pred_impl.h"
#include "io/fs/local_file_system.h"
+#include "io/io_common.h"
#include "runtime/exec_env.h"
#include "storage/index/index_file_reader.h"
#include "storage/index/index_file_writer.h"
@@ -999,4 +1000,60 @@ TEST_F(DorisCompoundReaderTest, OpenInputFromRAMDirectory) {
reader.close();
}
+// Verify that after initialize() + setIoContext(nullptr) (the cache-safe
+// transition), the main stream's io_ctx is cleared and sub-streams created
+// via openInput() do NOT carry stale io_ctx pointers. This is the pattern
+// used by both MATCH and SEARCH paths before inserting an IndexSearcher
+// into the global InvertedIndexSearcherCache.
+TEST_F(DorisCompoundReaderTest, InitializeThenClearIoCtxForCacheSafety) {
+ std::string index_path = kTestDir + "/test_io_ctx_lifecycle.idx";
+ std::vector<std::string> file_names = {"segments.gen", "posting.dat"};
+ std::vector<int64_t> lengths = {30, 60};
+
+ CL_NS(store)::IndexInput* index_input =
+ create_mock_index_input(index_path, file_names, lengths);
+
+ DorisCompoundReader reader(index_input, 4096, nullptr);
+
+ // --- Phase 1: initialization (simulates index open with a query's io_ctx) ---
+ io::IOContext io_ctx;
+ io_ctx.reader_type = ReaderType::READER_QUERY;
+ reader.initialize(&io_ctx);
+
+ auto* stream = reader.getDorisIndexInput();
+ auto* ctx_after_init = (const io::IOContext*)stream->getIoContext();
+ // Main stream should carry the io_ctx during initialization reads
+ EXPECT_EQ(ctx_after_init->reader_type, ReaderType::READER_QUERY);
+
+ // --- Phase 2: cache-safe transition (mirrors create_index_searcher) ---
+ stream->setIoContext(nullptr);
+ stream->setIndexFile(false);
+
+ auto* ctx_after_clear = (const io::IOContext*)stream->getIoContext();
+ // Main stream io_ctx should be reset to defaults
+ EXPECT_EQ(ctx_after_clear->reader_type, ReaderType::UNKNOWN);
+ EXPECT_EQ(ctx_after_clear->file_cache_stats, nullptr);
+
+ // --- Phase 3: verify sub-streams don't inherit stale io_ctx ---
+ CLuceneError err;
+ lucene::store::IndexInput* sub_input = nullptr;
+ EXPECT_TRUE(reader.openInput("posting.dat", sub_input, err, 4096));
+ EXPECT_NE(sub_input, nullptr);
+
+ // CSIndexInput._io_ctx should be nullptr (not set by openInput on master)
+ // This means readInternal() will skip setIoContext on the base stream,
+ // allowing query-phase reads to use their own io_ctx through the
+ // CLucene API parameter chain (termDocs/termPositions/terms).
+ // We verify this indirectly: cloning should also have nullptr _io_ctx.
+ lucene::store::IndexInput* cloned = sub_input->clone();
+ EXPECT_NE(cloned, nullptr);
+
+ sub_input->close();
+ cloned->close();
+ _CLLDELETE(sub_input);
+ _CLLDELETE(cloned);
+
+ reader.close();
+}
+
} // namespace doris::segment_v2
\ No newline at end of file
diff --git a/regression-test/data/search/test_search_inverted_index_profile.out b/regression-test/data/search/test_search_inverted_index_profile.out
new file mode 100644
index 00000000000..bf3abe806cb
--- /dev/null
+++ b/regression-test/data/search/test_search_inverted_index_profile.out
@@ -0,0 +1,22 @@
+-- This file is automatically generated. You may need to update it when you get
+-- temporary file 'regression-test/data/search/test_search_inverted_index_profile.out'.
+-- !io_ctx_miss --
+2
+5
+7
+
+-- !io_ctx_hit --
+2
+5
+7
+
+-- !io_ctx_multi --
+1
+2
+3
+4
+5
+6
+7
+8
+
diff --git a/regression-test/suites/search/test_search_inverted_index_profile.groovy b/regression-test/suites/search/test_search_inverted_index_profile.groovy
new file mode 100644
index 00000000000..6e0b4c92a5e
--- /dev/null
+++ b/regression-test/suites/search/test_search_inverted_index_profile.groovy
@@ -0,0 +1,302 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you under the Apache License, Version 2.0 (the
+// "License"); you may not use this file except in compliance
+// with the License. You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing,
+// software distributed under the License is distributed on an
+// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+// KIND, either express or implied. See the License for the
+// specific language governing permissions and limitations
+// under the License.
+
+import java.util.regex.Pattern
+
+suite("test_search_inverted_index_profile", "nonConcurrent") {
+ def tableName = "test_search_ii_profile"
+
+ sql "DROP TABLE IF EXISTS ${tableName}"
+ sql """
+ CREATE TABLE ${tableName} (
+ id INT,
+ title VARCHAR(200),
+ content TEXT,
+ INDEX idx_title(title) USING INVERTED PROPERTIES("parser" = "english"),
+ INDEX idx_content(content) USING INVERTED PROPERTIES("parser" = "english")
+ ) ENGINE=OLAP
+ DUPLICATE KEY(id)
+ DISTRIBUTED BY HASH(id) BUCKETS 1
+ PROPERTIES (
+ "replication_num" = "1",
+ "disable_auto_compaction" = "true"
+ )
+ """
+
+ sql """INSERT INTO ${tableName} VALUES
+ (1, 'apple banana cherry', 'red fruit sweet delicious'),
+ (2, 'banana grape mango', 'yellow fruit tropical summer'),
+ (3, 'cherry plum peach', 'stone fruit summer garden'),
+ (4, 'apple grape kiwi', 'green fruit fresh morning'),
+ (5, 'mango pineapple coconut', 'tropical fruit exotic island'),
+ (6, 'apple cherry plum', 'mixed fruit salad party'),
+ (7, 'banana coconut papaya', 'smoothie blend tropical drink'),
+ (8, 'grape cherry apple', 'wine fruit tart autumn')
+ """
+ sql "sync"
+
+ // Helper: extract a numeric counter value from profile string
+ def extractCounter = { String profileStr, String counterName ->
+ // Profile HTML uses for spacing
+ def pattern = Pattern.compile("${counterName}:(?: |\\s)*(\\d+)")
+ def matcher = pattern.matcher(profileStr)
+ if (matcher.find()) {
+ return Long.parseLong(matcher.group(1))
+ }
+ return -1L
+ }
+
+ // =========================================================================
+ // Test 1: SEARCH() profile metrics are populated on cache miss
+ //
+ // Disable both caches so every query triggers a full index open + search.
+ // Verify that InvertedIndexQueryTime, InvertedIndexSearcherOpenTime,
+ // InvertedIndexSearcherSearchTime, and cache miss counter are all > 0.
+ // =========================================================================
+ sql """ set enable_profile = true """
+ sql """ set profile_level = 2 """
+ sql """ set enable_sql_cache = false """
+ sql """ set enable_inverted_index_searcher_cache = false """
+ sql """ set enable_inverted_index_query_cache = false """
+ sql """ set enable_common_expr_pushdown = true """
+ sql """ set enable_common_expr_pushdown_for_inverted_index = true """
+
+ def queryId1 = "search_profile_miss_${System.currentTimeMillis()}"
+ try {
+ profile("${queryId1}") {
+ run {
+ sql """/* ${queryId1} */ SELECT id FROM ${tableName}
+ WHERE search('title:apple') ORDER BY id"""
+ }
+ check { profileString, exception ->
+ if (exception != null) throw exception
+ log.info("=== Cache-miss profile ===")
+
+ def queryTime = extractCounter(profileString, "InvertedIndexQueryTime")
+ def openTime = extractCounter(profileString, "InvertedIndexSearcherOpenTime")
+ def searchTime = extractCounter(profileString, "InvertedIndexSearcherSearchTime")
+ def searchInitTime = extractCounter(profileString, "InvertedIndexSearcherSearchInitTime")
+ def searchExecTime = extractCounter(profileString, "InvertedIndexSearcherSearchExecTime")
+ def cacheMiss = extractCounter(profileString, "InvertedIndexSearcherCacheMiss")
+ def cacheHit = extractCounter(profileString, "InvertedIndexSearcherCacheHit")
+
+ log.info("InvertedIndexQueryTime: {}", queryTime)
+ log.info("InvertedIndexSearcherOpenTime: {}", openTime)
+ log.info("InvertedIndexSearcherSearchTime: {}", searchTime)
+ log.info("InvertedIndexSearcherSearchInitTime: {}", searchInitTime)
+ log.info("InvertedIndexSearcherSearchExecTime: {}", searchExecTime)
+ log.info("InvertedIndexSearcherCacheMiss: {}", cacheMiss)
+ log.info("InvertedIndexSearcherCacheHit: {}", cacheHit)
+
+ assertTrue(queryTime > 0,
+ "InvertedIndexQueryTime should be > 0 for SEARCH(), got ${queryTime}")
+ assertTrue(searchTime > 0,
+ "InvertedIndexSearcherSearchTime should be > 0, got ${searchTime}")
+ assertTrue(cacheMiss > 0,
+ "InvertedIndexSearcherCacheMiss should be > 0 (cache disabled), got ${cacheMiss}")
+ }
+ }
+ } catch (IllegalStateException e) {
+ if (e.message?.contains("HttpCliAction failed")) {
+ log.warn("Profile HTTP request failed, skipping: {}", e.message)
+ } else {
+ throw e
+ }
+ }
+
+ // =========================================================================
+ // Test 2: SEARCH() cache hit — re-enable searcher cache, run twice.
+ // First run is a cache miss (populates cache), second run is a cache hit.
+ // Verify the second profile shows cache hit > 0 and open time == 0.
+ // =========================================================================
+ sql """ set enable_inverted_index_searcher_cache = true """
+ sql """ set enable_inverted_index_query_cache = false """
+
+ // First run: populate searcher cache
+ sql """SELECT /*+SET_VAR(enable_common_expr_pushdown=true) */
+ id FROM ${tableName} WHERE search('title:cherry') ORDER BY id"""
+
+ // Second run: should hit searcher cache
+ def queryId2 = "search_profile_hit_${System.currentTimeMillis()}"
+ try {
+ profile("${queryId2}") {
+ run {
+ sql """/* ${queryId2} */ SELECT id FROM ${tableName}
+ WHERE search('title:cherry') ORDER BY id"""
+ }
+ check { profileString, exception ->
+ if (exception != null) throw exception
+ log.info("=== Cache-hit profile ===")
+
+ def cacheHit = extractCounter(profileString, "InvertedIndexSearcherCacheHit")
+ def cacheMiss = extractCounter(profileString, "InvertedIndexSearcherCacheMiss")
+ def openTime = extractCounter(profileString, "InvertedIndexSearcherOpenTime")
+ def searchTime = extractCounter(profileString, "InvertedIndexSearcherSearchTime")
+
+ log.info("InvertedIndexSearcherCacheHit: {}", cacheHit)
+ log.info("InvertedIndexSearcherCacheMiss: {}", cacheMiss)
+ log.info("InvertedIndexSearcherOpenTime: {}", openTime)
+ log.info("InvertedIndexSearcherSearchTime: {}", searchTime)
+
+ assertTrue(cacheHit > 0,
+ "InvertedIndexSearcherCacheHit should be > 0 on second run, got ${cacheHit}")
+ assertTrue(searchTime > 0,
+ "InvertedIndexSearcherSearchTime should still be > 0 on cache hit, got ${searchTime}")
+ }
+ }
+ } catch (IllegalStateException e) {
+ if (e.message?.contains("HttpCliAction failed")) {
+ log.warn("Profile HTTP request failed, skipping: {}", e.message)
+ } else {
+ throw e
+ }
+ }
+
+ // =========================================================================
+ // Test 3: io_ctx safety — debug point verifies no stale io_ctx on the
+ // main stream after IndexSearcher creation (cache miss path).
+ // Then run a second query that hits the cache and confirm correct results.
+ // If the old dangling-pointer bug existed, ASAN would catch UAF here.
+ // =========================================================================
+ sql """ set enable_inverted_index_searcher_cache = true """
+ sql """ set enable_inverted_index_query_cache = false """
+
+ try {
+ GetDebugPoint().enableDebugPointForAllBEs("FieldReaderResolver.resolve.io_ctx")
+
+ // First query: cache miss, debug point validates io_ctx consistency
+ qt_io_ctx_miss """ SELECT /*+SET_VAR(enable_common_expr_pushdown=true) */
+ id FROM ${tableName} WHERE search('content:tropical') ORDER BY id """
+
+ // Second query: cache hit, reuses the cached searcher
+ // If io_ctx was stale, this would crash under ASAN
+ qt_io_ctx_hit """ SELECT /*+SET_VAR(enable_common_expr_pushdown=true) */
+ id FROM ${tableName} WHERE search('content:tropical') ORDER BY id """
+
+ // Third query: different DSL but same field — exercises resolver cache
+ qt_io_ctx_multi """ SELECT /*+SET_VAR(enable_common_expr_pushdown=true) */
+ id FROM ${tableName} WHERE search('content:tropical OR content:fruit') ORDER BY id """
+ } finally {
+ GetDebugPoint().disableDebugPointForAllBEs("FieldReaderResolver.resolve.io_ctx")
+ }
+
+ // =========================================================================
+ // Test 4: DSL query-cache hit — enable query cache, run same DSL twice.
+ // First run populates the DSL cache (miss), second run hits it.
+ // Verify InvertedIndexQueryCacheHit > 0, InvertedIndexQueryTime > 0,
+ // and InvertedIndexLookupTime > 0 on the cache-hit path.
+ // =========================================================================
+ sql """ set enable_inverted_index_searcher_cache = true """
+ sql """ set enable_inverted_index_query_cache = true """
+
+ // First run: populate DSL cache
+ sql """SELECT /*+SET_VAR(enable_common_expr_pushdown=true) */
+ id FROM ${tableName} WHERE search('title:banana') ORDER BY id"""
+
+ // Second run: should hit DSL cache
+ def queryId4 = "search_profile_dsl_hit_${System.currentTimeMillis()}"
+ try {
+ profile("${queryId4}") {
+ run {
+ sql """/* ${queryId4} */ SELECT id FROM ${tableName}
+ WHERE search('title:banana') ORDER BY id"""
+ }
+ check { profileString, exception ->
+ if (exception != null) throw exception
+ log.info("=== DSL cache-hit profile ===")
+
+ def queryCacheHit = extractCounter(profileString, "InvertedIndexQueryCacheHit")
+ def queryTime = extractCounter(profileString, "InvertedIndexQueryTime")
+ def lookupTime = extractCounter(profileString, "InvertedIndexLookupTime")
+
+ log.info("InvertedIndexQueryCacheHit: {}", queryCacheHit)
+ log.info("InvertedIndexQueryTime: {}", queryTime)
+ log.info("InvertedIndexLookupTime: {}", lookupTime)
+
+ assertTrue(queryCacheHit > 0,
+ "InvertedIndexQueryCacheHit should be > 0 on DSL cache hit, got ${queryCacheHit}")
+ assertTrue(queryTime > 0,
+ "InvertedIndexQueryTime should be > 0 even on DSL cache hit, got ${queryTime}")
+ }
+ }
+ } catch (IllegalStateException e) {
+ if (e.message?.contains("HttpCliAction failed")) {
+ log.warn("Profile HTTP request failed, skipping: {}", e.message)
+ } else {
+ throw e
+ }
+ }
+
+ // =========================================================================
+ // Test 5: searcher cache disabled — run same DSL twice with searcher cache
+ // off (but query cache also off so DSL cache cannot mask the problem).
+ // Both runs must show cache miss and zero cache hits, proving the switch
+ // is actually respected and a second run does not silently hit the cache.
+ // =========================================================================
+ sql """ set enable_inverted_index_searcher_cache = false """
+ sql """ set enable_inverted_index_query_cache = false """
+
+ // First run: cache miss (searcher cache disabled, nothing to hit)
+ sql """SELECT /*+SET_VAR(enable_common_expr_pushdown=true) */
+ id FROM ${tableName} WHERE search('title:grape') ORDER BY id"""
+
+ // Second run: should STILL be a cache miss because searcher cache is disabled
+ def queryId5 = "search_profile_no_cache_${System.currentTimeMillis()}"
+ try {
+ profile("${queryId5}") {
+ run {
+ sql """/* ${queryId5} */ SELECT id FROM ${tableName}
+ WHERE search('title:grape') ORDER BY id"""
+ }
+ check { profileString, exception ->
+ if (exception != null) throw exception
+ log.info("=== Searcher cache disabled (2nd run) profile ===")
+
+ def cacheHit = extractCounter(profileString, "InvertedIndexSearcherCacheHit")
+ def cacheMiss = extractCounter(profileString, "InvertedIndexSearcherCacheMiss")
+
+ log.info("InvertedIndexSearcherCacheHit: {}", cacheHit)
+ log.info("InvertedIndexSearcherCacheMiss: {}", cacheMiss)
+
+ assertTrue(cacheHit == 0,
+ "InvertedIndexSearcherCacheHit should be 0 when cache disabled, got ${cacheHit}")
+ assertTrue(cacheMiss > 0,
+ "InvertedIndexSearcherCacheMiss should be > 0 when cache disabled, got ${cacheMiss}")
+ }
+ }
+ } catch (IllegalStateException e) {
+ if (e.message?.contains("HttpCliAction failed")) {
+ log.warn("Profile HTTP request failed, skipping: {}", e.message)
+ } else {
+ throw e
+ }
+ }
+
+ // =========================================================================
+ // Test 6: SEARCH vs MATCH consistency — same data, same predicate logic,
+ // both should return identical results.
+ // =========================================================================
+ def search_result = sql """
+ SELECT /*+SET_VAR(enable_common_expr_pushdown=true) */
+ id FROM ${tableName} WHERE search('title:apple') ORDER BY id
+ """
+ def match_result = sql """
+ SELECT id FROM ${tableName} WHERE title MATCH_ANY 'apple' ORDER BY id
+ """
+ assertEquals(search_result, match_result,
+ "SEARCH('title:apple') and MATCH_ANY 'apple' should return identical rows")
+}
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org