This is an automated email from the ASF dual-hosted git repository.
yiguolei pushed a commit to branch branch-4.1
in repository https://gitbox.apache.org/repos/asf/doris.git
The following commit(s) were added to refs/heads/branch-4.1 by this push:
new 24f3eca6e81 branch-4.1: [fix](profile) populate inverted index metrics
for SEARCH() query path #62121 (#62180)
24f3eca6e81 is described below
commit 24f3eca6e8125bcb52c1d3988dcf3522e66c1180
Author: github-actions[bot]
<41898282+github-actions[bot]@users.noreply.github.com>
AuthorDate: Wed Apr 8 10:48:42 2026 +0800
branch-4.1: [fix](profile) populate inverted index metrics for SEARCH()
query path #62121 (#62180)
Cherry-picked from #62121
Co-authored-by: Jack <[email protected]>
---
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 19e20dc73c0..a80ce982cda 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: [email protected]
For additional commands, e-mail: [email protected]
