mikemccand opened a new issue, #15967:
URL: https://github.com/apache/lucene/issues/15967

   ### Description
   
   I'm digging into nightly benchy and concurrent HNSW merging, trying to 
extend segment traces to record details of HNSW concurrency.
   
   InfoStream has these useful lines:
   
   ```
   HNSW 0 [2026-04-15T14:58:00.633261871Z; hnsw-merge-1-thread-91]: built 
950000 in 11447/11447 ms
   ```
   
   But the `in X/X ms` is always the same `X`.  Here's [the 
source](https://github.com/apache/lucene/blob/fa0e704d2a0f941f2bbca17184472ae0e2b3743e/lucene/core/src/java/org/apache/lucene/util/hnsw/HnswGraphBuilder.java#L342-L353):
   
   ```
     private long printGraphBuildStatus(int node, long start, long t) {
       long now = System.nanoTime();
       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;
     }
   ```
   
   And it's [called from `addVectors` in the same 
class](https://github.com/apache/lucene/blob/fa0e704d2a0f941f2bbca17184472ae0e2b3743e/lucene/core/src/java/org/apache/lucene/util/hnsw/HnswGraphBuilder.java#L214):
   
   ```
     /** add vectors in range [minOrd, maxOrd) */
     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 + ")");
       }
       for (int node = minOrd; node < maxOrd; node++) {
         addGraphNode(node);
         if ((node % 10000 == 0) && infoStream.isEnabled(HNSW_COMPONENT)) {
           t = printGraphBuildStatus(node, start, t);
         }
       }
     }
   ```
   
   Since the chunk size is always 2048 (I think?), a worker working on a chunk 
could print 0 or 1 times ... which means the incoming `t` is always the same as 
`start`.
   
   I suspect this was factored out from a place where `start` was the true 
start time (to create the whole graph), and this InfoStream message is trying 
to show "time since we started" and "time since the last progress print" or so. 
 It's useful to fix this so segment traces can help debug HNSW merge 
concurrency...
   
   ### Version and environment details
   
   _No response_


-- 
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]


---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]

Reply via email to