Skip to content
Merged
49 changes: 49 additions & 0 deletions be/src/format_v2/table/lance_reader.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -697,6 +697,55 @@ void LanceTableReader::_init_scanner_profile() {
TUnit::UNIT, LANCE_READER_PROFILE, 1)},
};
_lance_time_metrics = {
// Partition stages accumulate across concurrent work and overlap their parent timers.
// DistanceTopK includes fused candidate filtering, scoring, and heap updates.
{"index_open_time", ADD_CHILD_TIMER_WITH_LEVEL(_scanner_profile, "LanceIndexOpenTime",
LANCE_READER_PROFILE, 1)},
{"index_partition_load_time",
ADD_CHILD_TIMER_WITH_LEVEL(_scanner_profile, "LanceIndexPartitionLoadTime",
LANCE_READER_PROFILE, 1)},
{"index_partition_prepare_time",
ADD_CHILD_TIMER_WITH_LEVEL(_scanner_profile, "LanceIndexPartitionPrepareTime",
LANCE_READER_PROFILE, 1)},
{"index_prefilter_wait_time",
ADD_CHILD_TIMER_WITH_LEVEL(_scanner_profile, "LanceIndexPrefilterWaitTime",
LANCE_READER_PROFILE, 1)},
{"index_cpu_queue_wait_time",
ADD_CHILD_TIMER_WITH_LEVEL(_scanner_profile, "LanceIndexCpuQueueWaitTime",
LANCE_READER_PROFILE, 1)},
{"index_search_time",
Comment thread
Gabriel39 marked this conversation as resolved.
ADD_CHILD_TIMER_WITH_LEVEL(_scanner_profile, "LanceIndexSearchTime",
LANCE_READER_PROFILE, 1)},
{"index_query_prepare_time",
ADD_CHILD_TIMER_WITH_LEVEL(_scanner_profile, "LanceIndexQueryPrepareTime",
LANCE_READER_PROFILE, 1)},
{"index_distance_topk_time",
ADD_CHILD_TIMER_WITH_LEVEL(_scanner_profile, "LanceIndexDistanceTopKTime",
LANCE_READER_PROFILE, 1)},
{"index_result_materialize_time",
ADD_CHILD_TIMER_WITH_LEVEL(_scanner_profile, "LanceIndexResultMaterializeTime",
LANCE_READER_PROFILE, 1)},
{"ANNIVFPartitionExec_elapsed_compute",
ADD_CHILD_TIMER_WITH_LEVEL(_scanner_profile, "LanceANNPartitionExecTime",
LANCE_READER_PROFILE, 1)},
{"ANNSubIndexExec_elapsed_compute",
ADD_CHILD_TIMER_WITH_LEVEL(_scanner_profile, "LanceANNSubIndexExecTime",
LANCE_READER_PROFILE, 1)},
{"ANNIvfBatchExec_elapsed_compute",
ADD_CHILD_TIMER_WITH_LEVEL(_scanner_profile, "LanceANNBatchExecTime",
LANCE_READER_PROFILE, 1)},
{"SortExec_elapsed_compute",
ADD_CHILD_TIMER_WITH_LEVEL(_scanner_profile, "LanceSortComputeTime",
LANCE_READER_PROFILE, 1)},
{"SortPreservingMergeExec_elapsed_compute",
ADD_CHILD_TIMER_WITH_LEVEL(_scanner_profile, "LanceSortMergeComputeTime",
LANCE_READER_PROFILE, 1)},
{"TakeExec_elapsed_compute",
ADD_CHILD_TIMER_WITH_LEVEL(_scanner_profile, "LanceTakeExecTime", LANCE_READER_PROFILE,
1)},
{"KNNVectorDistanceExec_elapsed_compute",
ADD_CHILD_TIMER_WITH_LEVEL(_scanner_profile, "LanceVectorDistanceComputeTime",
LANCE_READER_PROFILE, 1)},
// These are wall times in the ANN row-id loader. LoadTime includes input polling
// and set construction; it must not be added to its component timers.
{"prefilter_load_time",
Expand Down
9 changes: 9 additions & 0 deletions be/test/format_v2/table/lance_reader_test.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -912,6 +912,15 @@ TEST(LanceTableReaderVectorSearchTest, MultiVectorScoresFiltersOffsetsAndIndexed
}
EXPECT_TRUE(reader.close().ok());
if (indexed) {
// Warm searches still perform scoring even when every index partition is cached.
for (const char* name :
{"LanceIndexPartitionLoadTime", "LanceIndexCpuQueueWaitTime",
"LanceIndexSearchTime", "LanceIndexQueryPrepareTime",
"LanceIndexDistanceTopKTime", "LanceIndexResultMaterializeTime"}) {
auto* counter = profile.get_counter(name);
ASSERT_NE(nullptr, counter) << name;
EXPECT_GT(counter->value(), 0) << name;

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[P2] Check ANN timer emission without requiring every duration to be positive. The pinned lance-c timing test explicitly allows zero nanoseconds for short or uncontended stages; this four-result indexed scan requires six independent timers to be > 0. A valid zero CPU queue wait or fast stage therefore fails the BE test even when the metrics and results are correct. Assert presence and unit/kind, or use a workload with a guaranteed measurable stage for any positive-value check.

}
// Read metrics after close: lance-c publishes its final execution summary
// when the stream is released, including for an early top-k stop.
for (const char* name : {"LancePrefilterLoads", "LancePrefilterInputRows",
Expand Down
67 changes: 67 additions & 0 deletions docs/lance-ann-profile.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,67 @@
<!--
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.
-->

# Lance ANN profile timings

`FileScannerV2` accumulates scanner initialization, open, block-read, and close
wall time. Range acquisition and split preparation are nested within those
calls, so their counters are not additional time. Scanner worker scheduling
wait is reported separately. `LanceScannerReadTime` measures time spent calling
the Lance scanner, including Rust execution and waits. Doris scanner CPU time
does not include work done on Lance's CPU pool.

The following counters expose the work within an indexed vector search:

| Counter | Scope |
| --- | --- |
| `LanceIndexOpenTime` | Index-handle lookup/open, including metadata reads on a miss. |
| `LanceIVFPartitionRankingTime` | Partition ranking, including its CPU dispatch wait. |
| `LanceIndexPartitionLoadTime` | Partition cache lookup, coalesced-load wait, and read/decode on a miss. Also measured on cache hits. |
| `LanceIndexPartitionPrepareTime` | Partition load and per-partition filter preparation. On the streaming path, shared-filter waiting overlaps loading. |
| `LanceIndexPrefilterWaitTime` | Waiting for the shared prefilter to become ready. This is distinct from building the filter. |
| `LanceIndexCpuQueueWaitTime` | Delay before a dispatched search or result-materialization CPU task starts. |
| `LanceIndexSearchTime` | Search of prepared partitions on the CPU pool, including query preparation and any per-partition result construction. |
| `LanceIndexQueryPrepareTime` | Distance-calculator / lookup-table construction in the IVF flat sub-index (including quantized storage). |
| `LanceIndexDistanceTopKTime` | Candidate filtering, distance evaluation, and heap updates in that sub-index. These operations are fused in fast-scan paths. |
| `LanceIndexResultMaterializeTime` | Converting result heaps into Arrow arrays and batches, excluding final global sorting. |
| `LanceANNPartitionExecTime`, `LanceANNSubIndexExecTime`, `LanceANNBatchExecTime` | Baseline elapsed times reported by the corresponding Lance ANN operators. These include asynchronous waits. |
| `LanceSortComputeTime`, `LanceSortMergeComputeTime` | DataFusion sort / sort-preserving merge operator compute times. |
| `LanceTakeExecTime` | Baseline time reported by Lance's take operator within the scan plan. Doris second-phase row-ID fetch has separate counters. |
| `LanceVectorDistanceComputeTime` | Baseline reported by the vector-distance operator, e.g. refinement or an unindexed tail. |

Timings accumulate across partitions, tasks, and index segments. They are
**nested and may overlap**, so summing them does not reconstruct query wall time.
In particular, partition preparation contains loading; search contains query
preparation and distance/TopK work; ANN operator baselines contain downstream
search stages and waits. A zero counter can mean the corresponding operator or
path was not used. Detailed sub-index timers currently cover IVF flat sub-indices;
other sub-indices are visible through the encompassing search timer.

`LancePrefilterLoadTime` includes `LancePrefilterInputTime` and
`LancePrefilterBuildTime`; do not add these three together. A segment-scoped
search without a predicate can avoid constructing the row-ID allowlist, while
still respecting deletions and fragment visibility. Filter-readiness waiting can
therefore remain nonzero even when the row-ID materialization counters are zero.

For a warm query with no execution I/O and no prefilter materialization, inspect
CPU queue wait, query preparation, distance/TopK, and result/sort timers. For cold
queries, inspect partition load together with execution bytes, requests, and
partition cache misses. Use repeated queries and the operator-level elapsed
times to assess latency; cumulative parallel stage times alone are not a critical
path trace.
35 changes: 14 additions & 21 deletions thirdparty/download-thirdparty.sh
Original file line number Diff line number Diff line change
Expand Up @@ -718,30 +718,23 @@ if [[ " ${TP_ARCHIVES[*]} " =~ " AZURE " ]]; then
echo "Finished patching ${AZURE_SOURCE}"
fi

# Apply Doris lance-c patches as one chain to the pinned release archive.
# Foyer remains a local patch until its cache interface is accepted upstream.
# All search fixes are supplied by the immutable lance-c dependency revision.
if [[ " ${TP_ARCHIVES[*]} " =~ " LANCE_C " ]]; then
cd "${TP_SOURCE_DIR}/${LANCE_C_SOURCE}"
LANCE_C_PATCHED_MARK="${PATCHED_MARK}_community_pr83_prefilter"
# Older source caches carry a different PR #73 and cannot accept this chain incrementally.
if [[ -f "${PATCHED_MARK}" && ! -f "${LANCE_C_PATCHED_MARK}" ]]; then
echo "The lance-c patch chain changed; remove ${TP_SOURCE_DIR}/${LANCE_C_SOURCE} and rebuild."
exit 1
foyer_patch_checksum="$(cksum < "${TP_PATCH_DIR}/lance-c-foyer.patch")"
foyer_patch_marker="${TP_SOURCE_DIR}/${LANCE_C_SOURCE}/${PATCHED_MARK}_foyer"
# A new local patch must also replace previously patched cached sources.
# Empty markers from older builds cannot identify the applied patch version.
if [[ -f "${foyer_patch_marker}" ]] &&
[[ "$(cat "${foyer_patch_marker}")" != "${foyer_patch_checksum}" ]]; then
rm -rf "${TP_SOURCE_DIR}/${LANCE_C_SOURCE}"
"${TAR_CMD}" xzf "${TP_SOURCE_DIR}/${LANCE_C_NAME}" -C "${TP_SOURCE_DIR}/"
fi
if [[ ! -f "${LANCE_C_PATCHED_MARK}" ]]; then
# PR #77 provides Lance v11 for the following community patches. PR #83
# retains PR #79's scalar-segment path when adding multi-vector execution.
# The final patch pins the full-snapshot prefilter fix and its execution metrics.
for lance_patch in pr-74 pr-75-pr-78 pr-77 pr-73 pr-79 pr-80 pr-83 prefilter; do
patch --batch --forward --reject-file=- --fuzz=0 --no-backup-if-mismatch -s \
-p1 <"${TP_PATCH_DIR}/${LANCE_C_SOURCE}-${lance_patch}.patch"
done
touch "${PATCHED_MARK}" "${LANCE_C_PATCHED_MARK}"
fi
# Cached sources may carry the earlier prefilter pin; upgrade FTS metrics independently.
if [[ ! -f "${PATCHED_MARK}_prefilter_fts" ]]; then
cd "${TP_SOURCE_DIR}/${LANCE_C_SOURCE}"
if [[ ! -f "${PATCHED_MARK}_foyer" ]]; then
patch --batch --forward --reject-file=- --fuzz=0 --no-backup-if-mismatch -s \
-p1 <"${TP_PATCH_DIR}/${LANCE_C_SOURCE}-prefilter-fts.patch"
touch "${PATCHED_MARK}_prefilter_fts"
-p1 <"${TP_PATCH_DIR}/lance-c-foyer.patch"
printf '%s\n' "${foyer_patch_checksum}" > "${PATCHED_MARK}_foyer"
fi
cd -
echo "Finished patching ${LANCE_C_SOURCE}"
Expand Down
Loading
Loading