Fix HNSW InfoStream duplicate times and add per-chunk completion logging (#15967)

Signed-off-by: prithvi <prithvisivasankar@gmail.com>

Author: iprithv

lucene/CHANGES.txt

@@ -148,6 +148,10 @@ Optimizations
 
 Bug Fixes
 ---------------------
+* GITHUB#15967: Fix HNSW InfoStream progress to show elapsed time since merge start instead of
+  duplicate incremental/total times. Add per-chunk completion logging with sub-millisecond
+  precision to aid merge concurrency debugging. (Prithvi S)
+
 * GITHUB#14049: Randomize KNN codec params in RandomCodec. Fixes scalar quantization div-by-zero
   when all values are identical. (Mike Sokolov)
 

lucene/core/src/java/org/apache/lucene/util/hnsw/HnswConcurrentMergeBuilder.java

@@ -22,8 +22,10 @@
 import java.io.IOException;
 import java.util.ArrayList;
 import java.util.List;
+import java.util.Locale;
 import java.util.concurrent.Callable;
 import java.util.concurrent.atomic.AtomicInteger;
+import java.util.concurrent.atomic.AtomicLong;
 import java.util.concurrent.locks.Lock;
 import org.apache.lucene.internal.hppc.IntHashSet;
 import org.apache.lucene.search.TaskExecutor;
@@ -76,11 +78,17 @@ public OnHeapHnswGraph build(int maxOrd) throws IOException {
     if (frozen) {
       throw new IllegalStateException("graph has already been built");
     }
+    long mergeStartTimeNS = System.nanoTime();
     if (infoStream.isEnabled(HNSW_COMPONENT)) {
       infoStream.message(
           HNSW_COMPONENT,
           "build graph from " + maxOrd + " vectors, with " + workers.length + " workers");
     }
+    AtomicLong cumulativeWorkTimeNS = new AtomicLong();
+    for (ConcurrentMergeWorker worker : workers) {
+      worker.setMergeStartTimeNS(mergeStartTimeNS);
+      worker.setCumulativeWorkTimeNS(cumulativeWorkTimeNS);
+    }
     List<Callable<Void>> futures = new ArrayList<>();
     for (int i = 0; i < workers.length; i++) {
       int finalI = i;
@@ -91,6 +99,20 @@ public OnHeapHnswGraph build(int maxOrd) throws IOException {
           });
     }
     taskExecutor.invokeAll(futures);
+    if (infoStream.isEnabled(HNSW_COMPONENT)) {
+      double wallClockMs = (System.nanoTime() - mergeStartTimeNS) / 1_000_000.0;
+      double totalWorkerMs = cumulativeWorkTimeNS.get() / 1_000_000.0;
+      double effectiveConcurrency = wallClockMs > 0 ? totalWorkerMs / wallClockMs : 0;
+      infoStream.message(
+          HNSW_COMPONENT,
+          String.format(
+              Locale.ROOT,
+              "merge completed: %d vectors, %.2f ms wall clock, %.2f ms cumulative worker time, %.2fx effective concurrency",
+              maxOrd,
+              wallClockMs,
+              totalWorkerMs,
+              effectiveConcurrency));
+    }
     return getCompletedGraph();
   }
 

lucene/core/src/java/org/apache/lucene/util/hnsw/HnswGraphBuilder.java

@@ -26,7 +26,7 @@
 import java.util.Locale;
 import java.util.Objects;
 import java.util.SplittableRandom;
-import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
 import java.util.concurrent.locks.Lock;
 import org.apache.lucene.internal.hppc.IntHashSet;
 import org.apache.lucene.search.KnnCollector;
@@ -85,6 +85,29 @@ public class HnswGraphBuilder implements HnswBuilder {
   protected InfoStream infoStream = InfoStream.getDefault();
   protected boolean frozen;
 
+  /**
+   * Merge-level start time in nanoseconds. When set, the periodic progress prints (every 10K
+   * vectors) show elapsed time since the overall merge began rather than since the current chunk
+   * began. A value of -1 means not set (non-concurrent path).
+   */
+  private long mergeStartTimeNS = -1;
+
+  /**
+   * Shared accumulator for total worker time across all concurrent merge workers. Each chunk's
+   * elapsed time is added here so that effective concurrency can be computed at merge end.
+   */
+  private AtomicLong cumulativeWorkTimeNS;
+
+  /** Set the merge-level start time so progress prints show time since merge began. */
+  void setMergeStartTimeNS(long mergeStartTimeNS) {
+    this.mergeStartTimeNS = mergeStartTimeNS;
+  }
+
+  /** Set the shared accumulator for tracking cumulative worker time across concurrent chunks. */
+  void setCumulativeWorkTimeNS(AtomicLong cumulativeWorkTimeNS) {
+    this.cumulativeWorkTimeNS = cumulativeWorkTimeNS;
+  }
+
   public static HnswGraphBuilder create(
       RandomVectorScorerSupplier scorerSupplier, int M, int beamWidth, long seed)
       throws IOException {
@@ -204,16 +227,30 @@ protected void addVectors(int minOrd, int maxOrd) throws IOException {
     if (frozen) {
       throw new IllegalStateException("This HnswGraphBuilder is frozen and cannot be updated");
     }
-    long start = System.nanoTime(), t = start;
-    if (infoStream.isEnabled(HNSW_COMPONENT)) {
-      infoStream.message(HNSW_COMPONENT, "addVectors [" + minOrd + " " + maxOrd + ")");
-    }
+    long start = System.nanoTime();
+    long progressStart = mergeStartTimeNS != -1 ? mergeStartTimeNS : start;
     for (int node = minOrd; node < maxOrd; node++) {
       addGraphNode(node);
       if ((node % 10000 == 0) && infoStream.isEnabled(HNSW_COMPONENT)) {
-        t = printGraphBuildStatus(node, start, t);
+        printGraphBuildStatus(node, progressStart);
       }
     }
+    long chunkElapsedNS = System.nanoTime() - start;
+    if (cumulativeWorkTimeNS != null) {
+      cumulativeWorkTimeNS.addAndGet(chunkElapsedNS);
+    }
+    if (infoStream.isEnabled(HNSW_COMPONENT)) {
+      double elapsedMs = chunkElapsedNS / 1_000_000.0;
+      infoStream.message(
+          HNSW_COMPONENT,
+          String.format(
+              Locale.ROOT,
+              "addVectors [%d %d): %d vectors in %.2f ms",
+              minOrd,
+              maxOrd,
+              maxOrd - minOrd,
+              elapsedMs));
+    }
   }
 
   private void addVectors(int maxOrd) throws IOException {
@@ -339,17 +376,10 @@ public void addGraphNode(int node, IntHashSet eps0) throws IOException {
     addGraphNodeInternal(node, scorer, eps0);
   }
 
-  private long printGraphBuildStatus(int node, long start, long t) {
-    long now = System.nanoTime();
+  private void printGraphBuildStatus(int node, long start) {
+    double elapsedMs = (System.nanoTime() - start) / 1_000_000.0;
     infoStream.message(
-        HNSW_COMPONENT,
-        String.format(
-            Locale.ROOT,
-            "built %d in %d/%d ms",
-            node,
-            TimeUnit.NANOSECONDS.toMillis(now - t),
-            TimeUnit.NANOSECONDS.toMillis(now - start)));
-    return now;
+        HNSW_COMPONENT, String.format(Locale.ROOT, "built %d in %.2f ms", node, elapsedMs));
   }
 
   void addDiverseNeighbors(