Adds debug logs for KNNQuery and KNNWeight

src/main/java/org/opensearch/knn/index/query/KNNQuery.java

@@ -10,6 +10,7 @@
 import lombok.EqualsAndHashCode;
 import lombok.Getter;
 import lombok.Setter;
+import lombok.extern.log4j.Log4j2;
 import org.apache.lucene.search.BooleanClause;
 import org.apache.lucene.search.BooleanQuery;
 import org.apache.lucene.search.FieldExistsQuery;
@@ -19,6 +20,7 @@
 import org.apache.lucene.search.ScoreMode;
 import org.apache.lucene.search.Weight;
 import org.apache.lucene.search.join.BitSetProducer;
+import org.opensearch.common.StopWatch;
 import org.opensearch.knn.index.KNNSettings;
 import org.opensearch.knn.index.VectorDataType;
 import org.opensearch.knn.index.query.rescore.RescoreContext;
@@ -32,6 +34,7 @@
  * Custom KNN query. Query is used for KNNEngine's that create their own custom segment files. These files need to be
  * loaded and queried in a custom manner throughout the query path.
  */
+@Log4j2
 @Getter
 @Builder
 @AllArgsConstructor
@@ -168,7 +171,17 @@ public Weight createWeight(IndexSearcher searcher, ScoreMode scoreMode, float bo
         if (!KNNSettings.isKNNPluginEnabled()) {
             throw new IllegalStateException("KNN plugin is disabled. To enable update knn.plugin.enabled to true");
         }
+        StopWatch stopWatch = null;
+        if (log.isDebugEnabled()) {
+            stopWatch = new StopWatch().start();
+        }
+
         final Weight filterWeight = getFilterWeight(searcher);
+        if (log.isDebugEnabled() && stopWatch != null) {
+            stopWatch.stop();
+            log.debug("Creating filter weight for field [{}] took [{}] nanos", field, stopWatch.totalTime().nanos());
+        }
+
         if (filterWeight != null) {
             return new KNNWeight(this, boost, filterWeight);
         }

src/main/java/org/opensearch/knn/index/query/KNNWeight.java

@@ -20,6 +20,8 @@
 import org.apache.lucene.util.BitSetIterator;
 import org.apache.lucene.util.Bits;
 import org.apache.lucene.util.FixedBitSet;
+import org.opensearch.common.Nullable;
+import org.opensearch.common.StopWatch;
 import org.opensearch.common.lucene.Lucene;
 import org.opensearch.knn.common.FieldInfoExtractor;
 import org.opensearch.knn.common.KNNConstants;
@@ -129,7 +131,10 @@ public Scorer scorer(LeafReaderContext context) throws IOException {
      * @return A Map of docId to scores for top k results
      */
     public PerLeafResult searchLeaf(LeafReaderContext context, int k) throws IOException {
+        StopWatch stopWatch = startStopWatch();
         final BitSet filterBitSet = getFilteredDocsBitSet(context);
+        stopStopWatchAndLog(stopWatch, "Creating filter bitset for field [{}] took [{}] nanos");
+
         final int maxDoc = context.reader().maxDoc();
         int cardinality = filterBitSet.cardinality();
         // We don't need to go to JNI layer if no documents are found which satisfy the filters
@@ -153,7 +158,10 @@ public PerLeafResult searchLeaf(LeafReaderContext context, int k) throws IOExcep
          * so that it will not do a bitset look up in bottom search layer.
          */
         final BitSet annFilter = (filterWeight != null && cardinality == maxDoc) ? null : filterBitSet;
+        StopWatch annStopWatch = startStopWatch();
+        ;
         final Map<Integer, Float> docIdsToScoreMap = doANNSearch(context, annFilter, cardinality, k);
+        stopStopWatchAndLog(annStopWatch, "ANN search for field [{}] took [{}] nanos");
 
         // See whether we have to perform exact search based on approx search results
         // This is required if there are no native engine files or if approximate search returned
@@ -166,6 +174,13 @@ public PerLeafResult searchLeaf(LeafReaderContext context, int k) throws IOExcep
         return new PerLeafResult(filterWeight == null ? null : filterBitSet, docIdsToScoreMap);
     }
 
+    private void stopStopWatchAndLog(@Nullable StopWatch stopWatch, String message) {
+        if (log.isDebugEnabled() && stopWatch != null) {
+            stopWatch.stop();
+            log.debug(message, knnQuery.getField(), stopWatch.totalTime().nanos());
+        }
+    }
+
     private BitSet getFilteredDocsBitSet(final LeafReaderContext ctx) throws IOException {
         if (this.filterWeight == null) {
             return new FixedBitSet(0);
@@ -402,7 +417,10 @@ public Map<Integer, Float> exactSearch(
         final LeafReaderContext leafReaderContext,
         final ExactSearcher.ExactSearcherContext exactSearcherContext
     ) throws IOException {
-        return exactSearcher.searchLeaf(leafReaderContext, exactSearcherContext);
+        StopWatch stopWatch = startStopWatch();
+        Map<Integer, Float> exactSearchResults = exactSearcher.searchLeaf(leafReaderContext, exactSearcherContext);
+        stopStopWatchAndLog(stopWatch, "Exact search for field [{}] took [{}] nanos");
+        return exactSearchResults;
     }
 
     @Override
@@ -523,4 +541,11 @@ private boolean isMissingNativeEngineFiles(LeafReaderContext context) {
         );
         return engineFiles.isEmpty();
     }
+
+    private StopWatch startStopWatch() {
+        if (log.isDebugEnabled()) {
+            return new StopWatch().start();
+        }
+        return null;
+    }
 }