feat: expose ANN search stage timings by Gabriel39 · Pull Request #9602 · lance-format/lance

Gabriel39 · 2026-09-29T08:04:49Z

ANN execution statistics expose prefilter construction and comparison counts but leave other scan time unexplained, particularly for cache-resident searches. Add coarse stage timers so consumers can distinguish index opening, partition loading/preparation, filter readiness, CPU dispatch wait, partition search, query-calculator preparation, fused distance/TopK work, and result materialization.

Record partition-load time on cache hits as well as misses, and forward timings through local and execution-plan collectors. Export operator-qualified baseline elapsed times so ANN, sort/merge, take, and vector-distance work remain distinguishable in execution summaries and native callbacks.

Instrumentation is per partition or batch, never per candidate. Candidate filtering, distance evaluation, and heap updates remain fused where supported. Timers measure cumulative wall durations; nested and concurrent stages overlap and must not be added to reconstruct query latency. Existing metric names and collector implementations remain compatible.

Expose the timing map on Python ScanStatistics.all_times, including its type declaration and representation. Document nanosecond units and overlapping stage semantics. Callback regressions cover ordinary scans and both filtered and unfiltered ANN searches.

Extend the segment-prefilter execution matrix to assert both exact results and stage timings. Extend the cold/warm ANN regression to require computation timings even when the warm scan performs no index I/O. Add collector tests for accumulation and forwarding.

Validation: 138 prefilter tests, 1111 index tests (one existing ignored test), 187 KNN tests, 181 lance-datafusion tests, and four collector tests passed. Workspace Clippy (--all --tests --benches -- -D warnings) and formatting checks passed. This builds on the merged #9599 and does not change prefilter eligibility or search semantics.

Python review follow-up validation: the new assertions first failed in three cases with a missing all_times attribute, then all seven selected callback/ANN/cache-statistics cases passed after rebuilding the extension. Pre-commit checks and Python-binding Clippy (cargo clippy --locked --all-targets -- -D warnings) passed. A standalone Pyright check reports an existing unresolved .lance import; the unchanged baseline produces the same error.

Parallel preparation review follow-up: time partition loading, prefilter readiness, and per-partition prefilter construction in search_in_partition, ending before CPU dispatch and scoring. Add direct-entry-point regressions for both search paths on cold and warm caches, asserting preparation includes loading and results remain unchanged. The parallel case failed before the fix and passed afterward; checking only nonzero time would miss the bug because DataFusion rounds zero-duration updates up to 1ns.

Validation for this follow-up: all 189 KNN tests passed; the serial index suite passed 1111 tests with one existing ignored test; workspace Clippy and formatting passed. Two parallel index-suite runs each hit an intermittent existing HNSW-SQ distance-boundary assertion (actual 10 rows versus expected 9, on different distance cases); the four focused HNSW-SQ tests and the full serial suite passed unchanged.

claude

Claude Code Review

This pull request is from a fork — automated review is disabled. A repository maintainer can comment @claude review to run a one-time review.

lance-gatekeeper

⚠️ Gate recommendation: approve with a non-blocking risk.

The coarse timers cover the ANN search paths, including cache-resident work, and keep the existing search behavior. The timing map reaches Rust summaries and Java scan callbacks. Python ScanStatistics does not expose all_times, so Python callback consumers cannot access these timings until the binding forwards that map.

lance-gatekeeper

✅ Gate recommendation: approve.

The Python callback now forwards all_times, resolving the gap in my earlier review. Filtered and unfiltered ANN callback tests both expose search and operator timings. The coarse timers remain on the existing search paths.

yanghua

LGTM with a minor comment.

yanghua · 2026-09-29T09:51:32Z

        let part_entry = self.load_partition(partition_id, true, metrics).await?;
-        pre_filter.wait_for_ready().await?;
+        {
+            let _wait_timer = IndexTimer::new(metrics, IndexTiming::PrefilterWait);
+            pre_filter.wait_for_ready().await?;
+        }
        let pre_filter =
            Self::prefilter_for_partition(&self.index_cache, partition_id, &part_entry, pre_filter)
                .await?;


P2: Record PartitionPrepare on the parallel partition-search path

When query_parallelism > 1, ANNIvfSubIndexExec reaches search_in_partition, which performs partition loading, waits for the prefilter, and builds the per-partition prefilter. Unlike prepare_partition, however, this path never starts an IndexTiming::PartitionPrepare timer.

As a result, index_partition_prepare_time is populated on the sequential path but remains zero or absent on the common parallel path, even though equivalent preparation work occurs. This makes the metric dependent on the selected execution shape.

Could we wrap this preparation block in a PartitionPrepare timer, or explicitly document that the metric only covers the split/sequential preparation path?

Fixed in 350351e. The parallel path now times partition loading, prefilter readiness, and partition-prefilter construction, with the timer ending before CPU dispatch and scoring. Added cold/warm regressions that call both entry points directly and require preparation time to include loading; the parallel case failed before the fix and both cases now pass. All 189 KNN tests, 1111 serial index tests, workspace Clippy, and formatting passed. The PR description records an intermittent HNSW-SQ boundary assertion observed only in the parallel index-suite runs.

LuciferYang

Two minor, non-blocking notes inline (both LOW). The instrumentation itself looks solid: timers are per-partition/chunk/query with no per-candidate overhead, Search exactly once per partition on all four dispatch paths, and the nested/overlapping-stage semantics are clearly documented. Neither note blocks merge.

LuciferYang · 2026-09-29T11:10:06Z

+        if let Some(elapsed) = metrics.elapsed_compute() {
+            *counts
+                .all_times
+                .entry(format!("{}_elapsed_compute", node.name()))


collect_execution_metrics recurses the whole plan tree and folds each operator's elapsed_compute into all_times under format!("{}_elapsed_compute", node.name()). node.name() is a fixed per-type string, and a vector-search plan often has two TakeExec and two CoalesceBatchesExec nodes, so their times += into the same TakeExec_elapsed_compute and you can't tell which Take was slow.

These are tracing-only debug metrics and never touch query results, so per-type aggregation is a defensible reading (and it matches the existing iter_times/iter_counts behavior of this same function, which also aggregates by metric name). The doc comment above (Operator baseline times use <ExecutionPlan::name()>_elapsed_compute keys) reads as one key per operator instance, though; a note that same-type nodes collapse into one key would remove the ambiguity. Non-blocking.

LuciferYang · 2026-09-29T11:10:10Z


 impl MetricsCollector for LocalMetricsCollector {
+    fn record_timing(&self, stage: IndexTiming, duration: Duration) {
+        self.timings[stage as usize].fetch_add(duration.as_nanos() as usize, Ordering::Relaxed);


record_timing stores duration.as_nanos() (a u128) as usize. On a 64-bit target this is fine: a single stage would need >584 years to overflow. On 32-bit, usize is 32 bits and nanoseconds truncate at ~4.29 s, so a stage longer than that wraps to anywhere from a few ms to a few hundred ms.

This isn't unique to this line: DataFusion's Time::add_duration truncates the same way, and the pipeline is usize end to end (Time::value() → all_times → ScanStatistics.all_times). Widening only timings wouldn't help, since dump_into funnels the value back through Time, where it truncates again. Lance runs 64-bit in practice, so this can stay as-is — flagging only as a latent note; a real fix would widen the whole chain. Non-blocking.

Unfiltered ANN searches scoped to complete index segments can build redundant row-ID allowlists. Pin all Lance crates to the merged development-branch revision `68c12dfd7efe02f90ad2d7f3a239a7eb64884e57`, containing lance-format/lance#9599, the PQ scoring fix in lance-format/lance#9537, and ANN stage timings in lance-format/lance#9602. Align the direct OpenDAL dependency with Lance. The complete-segment fast path preserves predicate, partial-coverage, deletion, stable-row-ID, and unindexed-tail behavior. The C API regression checks exact results and prefilter materialization counters across 16 combinations. The PQ regression compares unfiltered and all-row-filtered results for L2, Cosine, and Dot. Verify that stage timings cross the existing dynamic statistics callback with the nanosecond unit. A reported zero duration is valid for short or uncontended stages, so the callback test checks metric presence and type without requiring every value to be positive. The C ABI is unchanged. Timers accumulate concurrent work and may overlap; they are not additive query latency. The materializing cases also require both prefilter build/load timers to be present with the nanosecond unit. A temporary mutation removing the build timer failed as expected; the final test passed across all 16 combinations. All 443 regular tests, Clippy, and formatting were rerun for this test-only follow-up. Validation on Linux x86_64 with Rust 1.98.1: - `cargo test --locked`: all 443 tests passed, including 361 C API tests. - `cargo test --locked --test compile_and_run_test -- --ignored`: all three opt-in tests passed. These compile and execute real C and C++ API consumers against the shared library, plus a C consumer against the static archive. The static test verifies that both ordinary and shared-runtime OSS opens reach a local HTTP server from fresh processes, without relying on whole-archive linking. - `cargo clippy --locked --all-targets -- -D warnings` and `cargo fmt --all --check` passed. The native result above is local Linux validation; macOS remains covered by the existing PR CI job. No production-data latency measurement is claimed.

…68613) Unfiltered ANN searches scoped to complete index segments can spend time materializing redundant row-ID allowlists. Update lance-c to an immutable upstream revision containing the merged Lance development-branch fix lance-format/lance#9599 and ANN diagnostics from lance-format/lance#9602, through lance-format/lance-c#89. Keep all master changes in `thirdparty/`. Remove the superseded local lance-c patch chain and retain the Foyer cache integration while its interface remains outside upstream main. The upstream revision also carries the merged lance-format/lance#9537 PQ scoring change and ANN stage timing diagnostics; no Doris FE or BE code changes are included here. The prefilter fast path requires complete visible coverage of every selected segment and no predicate. Partial coverage and predicates retain row-ID prefiltering, while deletions and unindexed fallback remain effective. Pin lance-c `9bd730add2ac70316c1d642b8459011e2dd92022`, using the merged Lance #9602 revision `68c12dfd7efe02f90ad2d7f3a239a7eb64884e57`. This includes parallel-path partition-preparation timing. The upstream callback regression checks timer presence and nanosecond units while accepting valid zero durations. The Foyer wrapper caches immutable ObjectMeta and Attributes independently of HTTP response extensions, avoiding repeated HEAD requests on warm range reads. It does not replay transport extensions from cached metadata. The HTTP regression checks HEAD/GET counts, returned bytes/ranges/metadata, fresh dataset scopes, and explicit HEAD bypass. Generate the retained Foyer patch from source commit `24c7ca4bcb9422c113b0d3e07e4efe1173b0bc9f` relative to the pinned lance-c baseline. The header records both revisions and the regeneration command. The source is submitted as zhangstar333/lance-c#3 against the branch behind lance-format/lance-c#73, on top of merged source-alignment PR #2. Doris consumes the exact reviewed source revision while that supplementary PR awaits merge. Scope metadata, size, and block keys to a random namespace for each live underlying object-store instance. The wrapping API omits a complete stable backend identity; identical bucket/path names alone cannot distinguish S3-compatible endpoints. Weak identity records preserve sharing for the same live store without retaining it, while new stores and process restarts start cold. A fresh Dataset open that creates a new store consequently needs to warm its own cache. This deliberately reduces reuse across instances to prevent returning another origin's data; it does not claim unchanged cache-hit rates or production latency. Avoid inserting an unchanged size entry into the WriteOnInsertion hybrid cache: look up both tiers first and populate only absent or invalid size records. Regression tests cover real HTTP endpoints sharing bucket/path/ETag, batched data and NotFound isolation, replaced origins after disk recovery, weak-reference lifetime, and actual disk-write bytes. Five warm range reads wrote 40 KB before the fix and zero bytes after it in the regression. Fingerprint the patch in the downloader so existing source trees refresh after updates, including legacy empty markers. Identical patches reuse cached sources. Check platform definitions under nounset with simulated Darwin x86_64/arm64, and make the optional ADBC source guard safe when unset on master. Downloader lifecycle and platform handling remain downstream in Doris. Validation: 461 regular Rust tests passed on the final source; Rust formatting and diff checks passed. GNU patch and git apply checks passed, and all 87 tracked source files match the recorded source commit. Downloader tests passed on master, branch-4.1, and the downstream hotfix branch for fresh extraction, idempotence, re-extraction, generic markers, legacy/mismatched Foyer markers, and patch failure. Shell syntax and simulated macOS initialization passed. All three opt-in native consumer tests passed: C calls, C++ calls, and static OSS HTTP transport. Full Doris builds and BE integration execution remain in PR CI.

…nch-4.1) (#68615) Unfiltered ANN searches scoped to complete index segments can materialize redundant row-ID allowlists, and the existing scan profile leaves the remaining search work unexplained. Update the upstream dependency and expose ANN stage timings on `branch-4.1`. This includes the dependency integration from #68613: adopt the merged lance-format/lance#9599 and lance-format/lance#9602 through lance-format/lance-c#89, retain the merged lance-format/lance#9537 PQ scoring fix, remove superseded local lance-c patches, and retain only the Foyer cache integration. Add BE profile counters for index opening, partition loading/preparation, prefilter readiness, CPU queue wait, partition search, query lookup-table preparation, fused distance/TopK work, and result materialization. Export operator baselines for ANN, sort/merge, take, and vector-distance work. Extend the existing indexed multivector regression to check that stage timers reach the Doris profile, alongside existing result and prefilter assertions. Timings accumulate across concurrent work and overlap parent stages. Distance/TopK includes candidate filtering in fused paths; these counters must not be summed to reconstruct wall time. `docs/lance-ann-profile.md` documents the boundaries, supported paths, and relationship to the existing scanner and prefilter timers. The BE changes add observability; the prefilter optimization itself remains in the upstream dependency. Pin lance-c `9bd730add2ac70316c1d642b8459011e2dd92022`, using the merged Lance #9602 revision `68c12dfd7efe02f90ad2d7f3a239a7eb64884e57`. This includes parallel-path partition-preparation timing. The upstream callback regression checks timer presence and nanosecond units while accepting valid zero durations. The Foyer wrapper caches immutable ObjectMeta and Attributes independently of HTTP response extensions, avoiding repeated HEAD requests on warm range reads. It does not replay transport extensions from cached metadata. The HTTP regression checks HEAD/GET counts, returned bytes/ranges/metadata, fresh dataset scopes, and explicit HEAD bypass. Generate the retained Foyer patch from source commit `24c7ca4bcb9422c113b0d3e07e4efe1173b0bc9f` relative to the pinned lance-c baseline. The header records both revisions and the regeneration command. The source is submitted as zhangstar333/lance-c#3 against the branch behind lance-format/lance-c#73, on top of merged source-alignment PR #2. Doris consumes the exact reviewed source revision while that supplementary PR awaits merge. Scope metadata, size, and block keys to a random namespace for each live underlying object-store instance. The wrapping API omits a complete stable backend identity; identical bucket/path names alone cannot distinguish S3-compatible endpoints. Weak identity records preserve sharing for the same live store without retaining it, while new stores and process restarts start cold. A fresh Dataset open that creates a new store consequently needs to warm its own cache. This deliberately reduces reuse across instances to prevent returning another origin's data; it does not claim unchanged cache-hit rates or production latency. Avoid inserting an unchanged size entry into the WriteOnInsertion hybrid cache: look up both tiers first and populate only absent or invalid size records. Regression tests cover real HTTP endpoints sharing bucket/path/ETag, batched data and NotFound isolation, replaced origins after disk recovery, weak-reference lifetime, and actual disk-write bytes. Five warm range reads wrote 40 KB before the fix and zero bytes after it in the regression. Fingerprint the patch in the downloader so existing source trees refresh after updates, including legacy empty markers. Identical patches reuse cached sources. Check platform definitions under nounset with simulated Darwin x86_64/arm64, and make the optional ADBC source guard safe when unset on master. Downloader lifecycle and platform handling remain downstream in Doris. Validation: 461 regular Rust tests passed on the final source; Rust formatting and diff checks passed. GNU patch and git apply checks passed, and all 87 tracked source files match the recorded source commit. Downloader tests passed on master, branch-4.1, and the downstream hotfix branch for fresh extraction, idempotence, re-extraction, generic markers, legacy/mismatched Foyer markers, and patch failure. Shell syntax and simulated macOS initialization passed. All three opt-in native consumer tests passed: C calls, C++ calls, and static OSS HTTP transport. Full Doris builds and BE integration execution remain in PR CI.

feat(index): expose coarse ANN execution timings

7d85901

claude Bot reviewed Sep 29, 2026

View reviewed changes

github-actions Bot added A-index Vector index, linalg, tokenizer enhancement New feature or request labels Sep 29, 2026

lance-gatekeeper Bot reviewed Sep 29, 2026

View reviewed changes

lance-gatekeeper Bot added K-approved Latest Gatekeeper recommendation permits acceptance. K-risk Latest Gatekeeper recommendation includes a non-blocking risk. labels Sep 29, 2026

This was referenced Sep 29, 2026

perf: avoid redundant prefilters for complete ANN segments lance-format/lance-c#89

Merged

[improvement](lance) Adopt upstream segment prefilter optimization apache/doris#68613

Merged

fix: expose execution timings in Python scan statistics

709f9fb

github-actions Bot added the A-python Python bindings label Sep 29, 2026

lance-gatekeeper Bot removed K-risk Latest Gatekeeper recommendation includes a non-blocking risk. K-approved Latest Gatekeeper recommendation permits acceptance. labels Sep 29, 2026

Gabriel39 mentioned this pull request Sep 29, 2026

[improvement](lance) Add ANN prefilter optimization and profiles (branch-4.1) apache/doris#68615

Merged

lance-gatekeeper Bot reviewed Sep 29, 2026

View reviewed changes

lance-gatekeeper Bot added the K-approved Latest Gatekeeper recommendation permits acceptance. label Sep 29, 2026

yanghua approved these changes Sep 29, 2026

View reviewed changes

fix: record preparation timing for parallel IVF searches

350351e

lance-gatekeeper Bot removed the K-approved Latest Gatekeeper recommendation permits acceptance. label Sep 29, 2026

LuciferYang reviewed Sep 29, 2026

View reviewed changes

yanghua merged commit 68c12df into lance-format:main Sep 29, 2026
39 of 40 checks passed

Navigation Menu

Repository navigation

feat: expose ANN search stage timings - #9602

feat: expose ANN search stage timings#9602
yanghua merged 3 commits into
lance-format:mainfrom
Gabriel39:dev/ann-search-profile

Gabriel39 commented Sep 29, 2026 •

edited

Loading

Uh oh!

claude Bot left a comment

Uh oh!

lance-gatekeeper Bot left a comment

Uh oh!

lance-gatekeeper Bot left a comment

Uh oh!

yanghua left a comment

Uh oh!

yanghua Sep 29, 2026

Uh oh!

Gabriel39 Sep 29, 2026

Uh oh!

LuciferYang left a comment

Uh oh!

LuciferYang Sep 29, 2026

Uh oh!

LuciferYang Sep 29, 2026

Uh oh!

Uh oh!

Reviewers

Uh oh!

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Conversation

Gabriel39 commented Sep 29, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

claude Bot left a comment

Choose a reason for hiding this comment

Claude Code Review

Uh oh!

lance-gatekeeper Bot left a comment

Choose a reason for hiding this comment

Uh oh!

lance-gatekeeper Bot left a comment

Choose a reason for hiding this comment

Uh oh!

yanghua left a comment

Choose a reason for hiding this comment

Uh oh!

yanghua Sep 29, 2026

Choose a reason for hiding this comment

Uh oh!

Gabriel39 Sep 29, 2026

Choose a reason for hiding this comment

Uh oh!

LuciferYang left a comment

Choose a reason for hiding this comment

Uh oh!

LuciferYang Sep 29, 2026

Choose a reason for hiding this comment

Uh oh!

LuciferYang Sep 29, 2026

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Reviewers

Uh oh!

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Gabriel39 commented Sep 29, 2026 •

edited

Loading