mikemccand commented on code in PR #15978:
URL: https://github.com/apache/lucene/pull/15978#discussion_r3139320476
##########
lucene/core/src/java/org/apache/lucene/util/hnsw/HnswGraphBuilder.java:
##########
@@ -205,15 +205,27 @@ protected void addVectors(int minOrd, int maxOrd) throws
IOException {
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 + ")");
- }
+ int numVectors = maxOrd - minOrd;
for (int node = minOrd; node < maxOrd; node++) {
addGraphNode(node);
- if ((node % 10000 == 0) && infoStream.isEnabled(HNSW_COMPONENT)) {
+ // Skip in-loop progress for ranges <= 10000 where it would fire at most
once
+ // with identical incremental/total times (#15967).
+ if (numVectors > 10000 && (node % 10000 == 0) &&
infoStream.isEnabled(HNSW_COMPONENT)) {
t = printGraphBuildStatus(node, start, t);
}
}
+ if (infoStream.isEnabled(HNSW_COMPONENT)) {
+ long elapsed = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start);
+ infoStream.message(
Review Comment:
This is awesome! I wonder if, separately from this new `InfoStream` log
line, we could also aggregate these times and then (when HNSW merge is
completely done, upstairs) add another summary `InfoStream` log line stating
the effective concurrency? Could maybe just be an `AtomicLong` that each chunk
increments its elapsed time into, then upstairs at HNSW merge end just divide
that value by elapsed wall clock time to get & `InfoStream.message` the implied
concurrency?
##########
lucene/core/src/java/org/apache/lucene/util/hnsw/HnswGraphBuilder.java:
##########
@@ -205,15 +205,27 @@ protected void addVectors(int minOrd, int maxOrd) throws
IOException {
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 + ")");
- }
+ int numVectors = maxOrd - minOrd;
for (int node = minOrd; node < maxOrd; node++) {
addGraphNode(node);
- if ((node % 10000 == 0) && infoStream.isEnabled(HNSW_COMPONENT)) {
+ // Skip in-loop progress for ranges <= 10000 where it would fire at most
once
+ // with identical incremental/total times (#15967).
+ if (numVectors > 10000 && (node % 10000 == 0) &&
infoStream.isEnabled(HNSW_COMPONENT)) {
Review Comment:
I think maybe the original print (when this was single threaded, maybe?)
is/was trying to print elapsed time since the merge kicked off, and then also
relative time since the previous print?
Also, it'd be nice to keep the consistent printing every 10K vectors
(whichever worker thread happens to get the lucky golden tickets). Imagine an
adversarial-to-`InfoStream` world where a large merge kicks off, there are many
threads so all chunks get pulled and worked on by a thread, but there are not
enough cores, so the threads progress slowly, and we never see any logging
until all chunks are done?
Maybe we could stop trying to log the delta-time (time since last log)?
Just time since merge began, and, keep printing on the lucky golden ticket
(`node % 10000 == 0`)? Then we will see regular prints, it's always since HNSW
merge start, it kinda behaves similar w/ many chunks vs one chunk?
##########
lucene/core/src/java/org/apache/lucene/util/hnsw/HnswGraphBuilder.java:
##########
@@ -205,15 +205,27 @@ protected void addVectors(int minOrd, int maxOrd) throws
IOException {
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 + ")");
- }
+ int numVectors = maxOrd - minOrd;
for (int node = minOrd; node < maxOrd; node++) {
addGraphNode(node);
- if ((node % 10000 == 0) && infoStream.isEnabled(HNSW_COMPONENT)) {
+ // Skip in-loop progress for ranges <= 10000 where it would fire at most
once
+ // with identical incremental/total times (#15967).
+ if (numVectors > 10000 && (node % 10000 == 0) &&
infoStream.isEnabled(HNSW_COMPONENT)) {
t = printGraphBuildStatus(node, start, t);
}
}
+ if (infoStream.isEnabled(HNSW_COMPONENT)) {
+ long elapsed = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start);
+ infoStream.message(
+ HNSW_COMPONENT,
+ String.format(
+ Locale.ROOT,
+ "addVectors [%d %d): %d vectors in %d ms",
Review Comment:
Maybe I am overly optimistic, but maybe we could `%.2f` these `ms` instead
of `%d`? (And also the one in `printGraphBuildStatus`)? How fast are 2048 ANN
searches + HNSW insert on these modern CPUs with massive SIMD silicon and
native optimized dot products and such ...
--
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]
