shyjsarah commented on code in PR #75:
URL:
https://github.com/apache/paimon-vector-index/pull/75#discussion_r3763488710
##########
core/src/ivfpq.rs:
##########
@@ -2027,12 +2167,17 @@ fn
search_batch_reader_filter_with_reuse_mode_and_observer<R: SeekRead>(
Vec::new()
};
let mut stable_pq_norms = None;
+ timing.prepare = elapsed_since(prepare_started);
let mut heaps = (0..nq).map(|_| TopKHeap::new(k)).collect::<Vec<_>>();
+ if timing_enabled {
Review Comment:
**[major] End read measurement and emit diagnostics on error paths**
After `begin_read_metrics()`, several fallible operations can return early
through `?`, including `list_payload_len`, streamed reads, `batch_read_end`,
and `read_inverted_list_payloads`. `end_read_metrics()` is only called on the
successful path.
Consequently, failed searches emit no timing diagnostic and leave metrics
enabled on the reader, so later operations continue collecting measurements and
paying instrumentation overhead.
Please use an RAII guard or an equivalent finally-style scope to end
measurement on every exit path. When timing is enabled, it would also be useful
to emit a record with `status=error`, the completed phase timings, I/O metrics,
and a non-sensitive error category.
##########
core/src/ivfpq.rs:
##########
@@ -1883,7 +2000,12 @@ fn
search_batch_reader_filter_with_reuse_mode_and_observer<R: SeekRead>(
mut observe_ephemeral_precomputed_lists: impl FnMut(usize),
#[cfg(test)] distance_table_builds:
Option<&std::sync::atomic::AtomicUsize>,
) -> io::Result<(Vec<i64>, Vec<f32>)> {
+ let timing_enabled =
std::env::var_os("PAIMON_VINDEX_LOG_IVFPQ_TIMING").is_some();
Review Comment:
**[major] Clarify or cover the single-query IVF-PQ search paths**
`PAIMON_VINDEX_LOG_IVFPQ_TIMING` is only checked in the batch
implementation. The JNI `search` and `searchWithRoaringFilter` methods use the
single-query reader path, so those operations never produce IVF-PQ timing
diagnostics.
Please either instrument `search_with_reader_filter` as well, or make the
batch-only scope explicit by renaming the flag and documentation to something
such as `PAIMON_VINDEX_LOG_IVFPQ_BATCH_TIMING`.
##########
java/src/test/java/org/apache/paimon/index/vector/NativeLogBridgeSmokeTest.java:
##########
@@ -0,0 +1,197 @@
+// 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.
+
+package org.apache.paimon.index.vector;
+
+import java.io.ByteArrayOutputStream;
+import java.io.PrintStream;
+import java.util.HashMap;
+import java.util.Map;
+import java.util.Random;
+
+/**
+ * Standalone check that native IVF-PQ timing diagnostics reach SLF4J (via
+ * NativeLogBridge) instead of the raw process stderr.
+ *
+ * <p>Requires the environment variable PAIMON_VINDEX_LOG_IVFPQ_TIMING to be
set
+ * before the JVM starts (the Rust gate reads the process environment); prints
a
+ * skip notice and exits 0 otherwise. Run with slf4j-simple on the classpath:
+ *
+ * <pre>
+ * PAIMON_VINDEX_LOG_IVFPQ_TIMING=1 java -cp ... \
+ * org.apache.paimon.index.vector.NativeLogBridgeSmokeTest
[/path/to/libpaimon_vindex_jni.so]
+ * </pre>
+ */
+public class NativeLogBridgeSmokeTest {
+
+ private static final String TIMING_MARKER = "ivfpq_batch_timing";
+ private static final String[] REQUIRED_TIMING_FIELDS = {
+ "topk",
+ "unique_list_rows",
+ "query_list_pairs",
+ "pq_codes_evaluated",
+ "matched_rows",
+ "read_calls",
+ "requested_bytes",
+ "queries_below_k",
+ "min_hits_per_query",
+ "io_read_ms",
+ "decode_ms"
+ };
+
+ public static void main(String[] args) {
+ if (System.getenv("PAIMON_VINDEX_LOG_IVFPQ_TIMING") == null) {
+ if (Boolean.getBoolean("vindex.smoke.require-timing")) {
+ throw new AssertionError(
+ "PAIMON_VINDEX_LOG_IVFPQ_TIMING must be set in the
process environment "
+ + "when vindex.smoke.require-timing=true");
+ }
+ System.out.println(
+ "SKIP: PAIMON_VINDEX_LOG_IVFPQ_TIMING is not set in the
process environment");
+ return;
+ }
+ VectorIndexNativeLoaderSmokeTest.configureExternalLibrary(args);
+ if (!hasNativeLibrary()) {
+ System.out.println("SKIP: no explicit or bundled JNI library is
available");
+ return;
+ }
+
+ PrintStream originalOut = System.out;
+ PrintStream originalErr = System.err;
+ ByteArrayOutputStream capturedOut = new ByteArrayOutputStream();
+ ByteArrayOutputStream capturedErr = new ByteArrayOutputStream();
+ String out;
+ String err;
+ try {
+ // Capture before the first native/SLF4J use: slf4j-simple logs to
+ // System.err by default and does not cache the stream.
+ System.setOut(new PrintStream(capturedOut, true));
+ System.setErr(new PrintStream(capturedErr, true));
+ runIvfPqBatchSearch();
+ } finally {
+ System.setOut(originalOut);
+ System.setErr(originalErr);
+ out = capturedOut.toString();
+ err = capturedErr.toString();
+ }
+
+ if (out.contains(TIMING_MARKER)) {
+ throw new AssertionError(
+ "timing record leaked to stdout instead of the log
bridge:\n" + out);
+ }
+ if (!err.contains(TIMING_MARKER)) {
Review Comment:
**[major] Assert SLF4J delivery rather than only checking System.err**
This assertion only proves that the marker reaches Java's `System.err`. Both
`slf4j-simple` and the fallback in `NativeLogBridge.log()` write to that
stream, so an exception in the SLF4J call can fall back to
`System.err.println(message)` and still pass this test.
Please use a recording SLF4J binding/appender and assert the logger name,
level, and message directly. The stderr fallback should be exercised separately
by an explicit failure-path test.
##########
core/src/ivfpq.rs:
##########
@@ -2275,29 +2463,59 @@ fn
search_batch_reader_filter_with_reuse_mode_and_observer<R: SeekRead>(
heaps[qi].push(distance, row_id);
}
}
+ timing.scan += elapsed_since(scan_started);
batch_start = batch_end;
}
+ if timing_enabled {
+ let read_metrics = reader.end_read_metrics();
+ timing.io_read = read_metrics.elapsed;
+ // Both batch and streamed reads accumulated I/O plus decode above.
+ timing.decode = timing.decode.saturating_sub(timing.io_read);
+ timing.read_calls = read_metrics.calls;
+ timing.requested_bytes = read_metrics.requested_bytes;
+ }
+ let finalize_started = timing_enabled.then(Instant::now);
let mut result_ids = vec![-1i64; nq * k];
let mut result_dists = vec![f32::MAX; nq * k];
+ timing.min_hits_per_query = k;
for (qi, heap) in heaps.into_iter().enumerate() {
let sorted = heap.into_sorted();
+ if timing_enabled {
+ timing.queries_below_k = timing
+ .queries_below_k
+ .saturating_add(usize::from(sorted.len() < k));
+ timing.min_hits_per_query =
timing.min_hits_per_query.min(sorted.len());
+ }
let base = qi * k;
for (i, &(dist, id)) in sorted.iter().enumerate() {
result_ids[base + i] = id;
result_dists[base + i] = dist;
}
}
+ timing.finalize = elapsed_since(finalize_started);
- if !by_residual &&
std::env::var_os("PAIMON_VINDEX_LOG_IVFPQ_BATCH_REUSE").is_some() {
- use std::io::Write;
+ if timing_enabled {
+ let mut buf = Vec::with_capacity(256);
+ let _ = timing.write_to(
+ &mut buf,
+ elapsed_since(total_started),
+ nq,
+ nprobe,
+ reader.pq.nbits,
+ k,
+ unique_lists.len(),
+ filter.is_some(),
+ );
+ emit_log(LogLevel::Info, String::from_utf8_lossy(&buf).trim_end());
+ }
+ if !by_residual &&
std::env::var_os("PAIMON_VINDEX_LOG_IVFPQ_BATCH_REUSE").is_some() {
Review Comment:
**[minor] Cover the table-reuse emitter in the JNI bridge test**
This is the second diagnostic emitter migrated to `emit_log`, but the smoke
test only enables `PAIMON_VINDEX_LOG_IVFPQ_TIMING` and builds an L2 residual
index. It therefore never enters this `!by_residual` branch.
Please add a forked-JVM case using an inner-product or cosine index with
`PAIMON_VINDEX_LOG_IVFPQ_BATCH_REUSE=1`, and verify that the
`ivfpq_batch_table_reuse` record is delivered through the Java logging bridge.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
