From 7d51ae1982eecffc0fbc65cbdfe31b6b1e257163 Mon Sep 17 00:00:00 2001 From: Navneet Verma Date: Fri, 27 Sep 2024 20:01:27 -0700 Subject: [PATCH] Added logs to understand the time taken by different merge related items Signed-off-by: Navneet Verma --- .../NativeEngines990KnnVectorsWriter.java | 15 ++++++++++----- 1 file changed, 10 insertions(+), 5 deletions(-) diff --git a/src/main/java/org/opensearch/knn/index/codec/KNN990Codec/NativeEngines990KnnVectorsWriter.java b/src/main/java/org/opensearch/knn/index/codec/KNN990Codec/NativeEngines990KnnVectorsWriter.java index 23cd2a4de0..52bab34183 100644 --- a/src/main/java/org/opensearch/knn/index/codec/KNN990Codec/NativeEngines990KnnVectorsWriter.java +++ b/src/main/java/org/opensearch/knn/index/codec/KNN990Codec/NativeEngines990KnnVectorsWriter.java @@ -24,6 +24,7 @@ import org.apache.lucene.search.DocIdSetIterator; import org.apache.lucene.util.IOUtils; import org.apache.lucene.util.RamUsageEstimator; +import org.apache.lucene.util.hnsw.CloseableRandomVectorScorerSupplier; import org.opensearch.common.StopWatch; import org.opensearch.knn.index.VectorDataType; import org.opensearch.knn.index.codec.nativeindex.NativeIndexWriter; @@ -108,31 +109,35 @@ public void flush(int maxDoc, final Sorter.DocMap sortMap) throws IOException { @Override public void mergeOneField(final FieldInfo fieldInfo, final MergeState mergeState) throws IOException { // This will ensure that we are merging the FlatIndex during force merge. + StopWatch stopwatch = new StopWatch().start(); flatVectorsWriter.mergeOneField(fieldInfo, mergeState); - + log.info("Merge : Reading and writing merged FlatVector Took : {} ms", stopwatch.stop().totalTime().millis()); final VectorDataType vectorDataType = extractVectorDataType(fieldInfo); final Supplier> knnVectorValuesSupplier = () -> getKNNVectorValuesForMerge( vectorDataType, fieldInfo, mergeState ); + stopwatch = new StopWatch().start(); int totalLiveDocs = getLiveDocs(knnVectorValuesSupplier.get()); + log.info("Merge : Reading live docs Took : {} ms", stopwatch.stop().totalTime().millis()); if (totalLiveDocs == 0) { log.debug("[Merge] No live docs for field {}", fieldInfo.getName()); return; } final QuantizationState quantizationState = train(fieldInfo, knnVectorValuesSupplier, totalLiveDocs); - final NativeIndexWriter writer = NativeIndexWriter.getWriter(fieldInfo, segmentWriteState, quantizationState); - final KNNVectorValues knnVectorValues = knnVectorValuesSupplier.get(); + StopWatch stopWatch2 = new StopWatch().start(); + final KNNVectorValues knnVectorValues = knnVectorValuesSupplier.get(); + log.info("Merge : Creating merged VectorValues Took : {} ms", stopWatch2.stop().totalTime().millis()); StopWatch stopWatch = new StopWatch().start(); - + final NativeIndexWriter writer = NativeIndexWriter.getWriter(fieldInfo, segmentWriteState, quantizationState); writer.mergeIndex(knnVectorValues, totalLiveDocs); long time_in_millis = stopWatch.stop().totalTime().millis(); KNNGraphValue.MERGE_TOTAL_TIME_IN_MILLIS.incrementBy(time_in_millis); - log.debug("Merge took {} ms for vector field [{}]", time_in_millis, fieldInfo.getName()); + log.info("Merge took {} ms for vector field [{}]", time_in_millis, fieldInfo.getName()); } /**