Adds debug logs for KNNQuery and KNNWeight #2466

shatejas · 2025-01-29T19:24:26Z

Description

Adds debug logs with timing information for various knn query components

Testing

Cluster setting changed in local

curl --request PUT \
  --url http://localhost:9200/_cluster/settings \
  --header 'Content-Type: application/json' \
  --data '{
  "persistent" : {
		"logger.org.opensearch.knn.index.query" : "DEBUG"
  }
}'

Output

q.KNNQueryFactory] [integTest-0] Creating custom k-NN query for index:target_index_faiss, field:location, k:3, filterQuery:+IndexOrDocValuesQuery(indexQuery=rating:[8 TO 10], dvQuery=rating:[8 TO 10]), efSearch:null
[2025-01-29T11:20:21,929][DEBUG][o.o.k.i.q.KNNQuery       ] [integTest-0] Creating filter weight for field [location] took [603583] nanos
[2025-01-29T11:20:21,930][DEBUG][o.o.k.i.q.KNNWeight      ] [integTest-0] Creating filter bitset for field [location] took [462500] nanos
[2025-01-29T11:20:21,930][DEBUG][o.o.k.i.q.KNNWeight      ] [integTest-0] Info for doing exact search filterIdsLength : 10, Threshold value: -1
[2025-01-29T11:20:21,930][DEBUG][o.o.k.i.q.KNNWeight      ] [integTest-0] Exact search for field [location] took [232083] nanos

Check List

New functionality includes testing.
Commits are signed per the DCO using --signoff.

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.
For more information on following Developer Certificate of Origin and signing off your commits, please check here.

Signed-off-by: Tejas Shah <[email protected]>

kotwanikunal · 2025-01-29T19:32:55Z

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

@@ -168,7 +171,10 @@ 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 = new StopWatch().start();


Should we wrap this behind log.isDebugEnabled()?
It's not a big overhead but given that it's being used only for debug logging.

I thought about if but wanted to avoid if conditions. Let me add it

Signed-off-by: Tejas Shah <[email protected]>

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

VijayanB · 2025-01-29T20:53:23Z

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

@@ -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) {


nit: add final to method parameters?

VijayanB · 2025-01-29T20:53:41Z

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

@@ -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();
+        ;


nit: remove this line

VijayanB · 2025-01-29T20:56:17Z

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

+    private void stopStopWatchAndLog(@Nullable StopWatch stopWatch, String message) {
+        if (log.isDebugEnabled() && stopWatch != null) {
+            stopWatch.stop();
+            log.debug(message, knnQuery.getField(), stopWatch.totalTime().nanos());


is it advisable to assume that message will have two arguments and in that order?

Should be fine considering its private

IMO it is error prone. Considering it is private, can you add doc saying that param message expects two args with field name and nano secs in that order

I need the sequence of stopping the watch and then logging it I can change the name of the function or just pass a prefix and standardize the message

Signed-off-by: Tejas Shah <[email protected]>

navneet1v · 2025-01-29T22:37:42Z

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

        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());


do we need any segment info like total docs which was present? name of the shard etc for better debugging. Because we have a lot of segments then this log statement won't be that helpful

Added shard and segment info. cat APIs should help trace down total docs and deleted docs

Signed-off-by: Tejas Shah <[email protected]>

shatejas · 2025-01-30T00:34:17Z

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

-        return exactSearcher.searchLeaf(leafReaderContext, exactSearcherContext);
+        StopWatch stopWatch = startStopWatch();
+        Map<Integer, Float> exactSearchResults = exactSearcher.searchLeaf(leafReaderContext, exactSearcherContext);
+        final SegmentReader reader = Lucene.segmentReader(leafReaderContext.reader());


Added here to not have to make changes in NativeEngineQuery

Signed-off-by: Tejas Shah <[email protected]>

* Adds debug logs for KNNQuery and KNNWeight Signed-off-by: Tejas Shah <[email protected]> * Adds check to see if log is enabled to start and stop StopWatch Signed-off-by: Tejas Shah <[email protected]> * Addressing comments on the PR Signed-off-by: Tejas Shah <[email protected]> * Adds shard and segment info in the logs Signed-off-by: Tejas Shah <[email protected]> * Removes unnecessary segment name param from exact search Signed-off-by: Tejas Shah <[email protected]> * Fixes the build Signed-off-by: Tejas Shah <[email protected]> --------- Signed-off-by: Tejas Shah <[email protected]> (cherry picked from commit f322e27)

* Adds debug logs for KNNQuery and KNNWeight Signed-off-by: Tejas Shah <[email protected]> * Adds check to see if log is enabled to start and stop StopWatch Signed-off-by: Tejas Shah <[email protected]> * Addressing comments on the PR Signed-off-by: Tejas Shah <[email protected]> * Adds shard and segment info in the logs Signed-off-by: Tejas Shah <[email protected]> * Removes unnecessary segment name param from exact search Signed-off-by: Tejas Shah <[email protected]> * Fixes the build Signed-off-by: Tejas Shah <[email protected]> --------- Signed-off-by: Tejas Shah <[email protected]> (cherry picked from commit f322e27) Co-authored-by: Tejas Shah <[email protected]>

Adds debug logs for KNNQuery and KNNWeight

c526a13

Signed-off-by: Tejas Shah <[email protected]>

shatejas requested review from heemin32, navneet1v, VijayanB, vamshin, jmazanec15, naveentatikonda, junqiu-lei, martin-gaievski, ryanbogan, luyuncheng and 0ctopus13prime as code owners January 29, 2025 19:24

shatejas added skip-changelog backport main labels Jan 29, 2025

kotwanikunal reviewed Jan 29, 2025

View reviewed changes

Adds check to see if log is enabled to start and stop StopWatch

2883e80

Signed-off-by: Tejas Shah <[email protected]>

shatejas requested a review from kotwanikunal January 29, 2025 20:14

kotwanikunal approved these changes Jan 29, 2025

View reviewed changes

VijayanB reviewed Jan 29, 2025

View reviewed changes

src/main/java/org/opensearch/knn/index/query/KNNWeight.java Show resolved Hide resolved

VijayanB reviewed Jan 29, 2025

View reviewed changes

src/main/java/org/opensearch/knn/index/query/KNNWeight.java Show resolved Hide resolved

VijayanB reviewed Jan 29, 2025

View reviewed changes

Addressing comments on the PR

38756c3

Signed-off-by: Tejas Shah <[email protected]>

shatejas requested review from VijayanB and kotwanikunal January 29, 2025 22:06

navneet1v reviewed Jan 29, 2025

View reviewed changes

VijayanB previously approved these changes Jan 29, 2025

View reviewed changes

Adds shard and segment info in the logs

d855696

Signed-off-by: Tejas Shah <[email protected]>

shatejas dismissed VijayanB’s stale review via d855696 January 30, 2025 00:27

shatejas requested review from navneet1v and VijayanB January 30, 2025 00:28

Removes unnecessary segment name param from exact search

7b0d3f6

Signed-off-by: Tejas Shah <[email protected]>

shatejas commented Jan 30, 2025

View reviewed changes

Fixes the build

10821cd

Signed-off-by: Tejas Shah <[email protected]>

shatejas added the backport 2.19 label Jan 30, 2025

jmazanec15 approved these changes Jan 30, 2025

View reviewed changes

navneet1v approved these changes Jan 30, 2025

View reviewed changes

shatejas merged commit f322e27 into opensearch-project:2.x Jan 30, 2025
102 checks passed

opensearch-trigger-bot bot mentioned this pull request Jan 30, 2025

[Backport main] Adds debug logs for KNNQuery and KNNWeight #2470

Open

opensearch-trigger-bot bot mentioned this pull request Jan 30, 2025

[Backport 2.19] Adds debug logs for KNNQuery and KNNWeight #2471

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Adds debug logs for KNNQuery and KNNWeight #2466

Adds debug logs for KNNQuery and KNNWeight #2466

shatejas commented Jan 29, 2025 •

edited

Loading

kotwanikunal Jan 29, 2025

shatejas Jan 29, 2025

VijayanB Jan 29, 2025

shatejas Jan 29, 2025

VijayanB Jan 29, 2025

shatejas Jan 29, 2025

VijayanB Jan 29, 2025

shatejas Jan 29, 2025

VijayanB Jan 29, 2025

shatejas Jan 29, 2025

navneet1v Jan 29, 2025

shatejas Jan 30, 2025

shatejas Jan 30, 2025

Adds debug logs for KNNQuery and KNNWeight #2466

Adds debug logs for KNNQuery and KNNWeight #2466

Conversation

shatejas commented Jan 29, 2025 • edited Loading

Description

Testing

Check List

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

shatejas commented Jan 29, 2025 •

edited

Loading