Request level coordinator slow logs

Signed-off-by: David Zane <[email protected]>
dzane17 · Oct 5, 2023 · d85fc85 · d85fc85
1 parent 02ad689
commit d85fc85
Show file tree

Hide file tree

Showing 6 changed files with 501 additions and 1 deletion.
diff --git a/server/src/main/java/org/opensearch/action/search/AbstractSearchAsyncAction.java b/server/src/main/java/org/opensearch/action/search/AbstractSearchAsyncAction.java
@@ -192,6 +192,7 @@ public void releaseContext() {
      * Builds how long it took to execute the search.
      */
     long buildTookInMillis() {
+        searchRequestOperationsListener.ifPresent(searchRequestOperations -> searchRequestOperations.onRequestEnd(this));
         return timeProvider.buildTookInMillis();
     }
 
@@ -441,6 +442,10 @@ private void onPhaseStart(SearchPhase phase) {
         this.searchRequestOperationsListener.ifPresent(searchRequestOperations -> { searchRequestOperations.onPhaseStart(this); });
     }
 
+    private void onRequestEnd() {
+        this.searchRequestOperationsListener.ifPresent(searchRequestOperations -> { searchRequestOperations.onRequestEnd(this); });
+    }
+
     private void executePhase(SearchPhase phase) {
         try {
             onPhaseStart(phase);
@@ -678,6 +683,7 @@ boolean buildPointInTimeFromSearchResults() {
 
     @Override
     public void sendSearchResponse(InternalSearchResponse internalSearchResponse, AtomicArray<SearchPhaseResult> queryResults) {
+        long startTime = System.nanoTime();
         ShardSearchFailure[] failures = buildShardFailures();
         Boolean allowPartialResults = request.allowPartialSearchResults();
         assert allowPartialResults != null : "SearchRequest missing setting for allowPartialSearchResults";
@@ -696,9 +702,14 @@ public void sendSearchResponse(InternalSearchResponse internalSearchResponse, At
                     searchContextId = null;
                 }
             }
+            System.out.println("before listener.onResponse:" + Long.toString((System.nanoTime() - startTime) / 1000));
             listener.onResponse(buildSearchResponse(internalSearchResponse, failures, scrollId, searchContextId));
+            System.out.println("after listener.onResponse:" + Long.toString((System.nanoTime() - startTime) / 1000));
         }
         onPhaseEnd();
+        System.out.println("after onPhaseEnd:" + Long.toString((System.nanoTime() - startTime) / 1000));
+        onRequestEnd();
+        System.out.println("after onRequestEnd:" + Long.toString((System.nanoTime() - startTime) / 1000));
         setCurrentPhase(null);
     }
 

diff --git a/server/src/main/java/org/opensearch/action/search/SearchRequestOperationsListener.java b/server/src/main/java/org/opensearch/action/search/SearchRequestOperationsListener.java
@@ -26,6 +26,10 @@ public interface SearchRequestOperationsListener {
 
     void onPhaseFailure(SearchPhaseContext context);
 
+    default void onRequestStart(long startTimeNanos) {};
+
+    default void onRequestEnd(SearchPhaseContext context) {};
+
     /**
      * Holder of Composite Listeners
      *
@@ -73,5 +77,27 @@ public void onPhaseFailure(SearchPhaseContext context) {
                 }
             }
         }
+
+        @Override
+        public void onRequestStart(long startTimeNanos) {
+            for (SearchRequestOperationsListener listener : listeners) {
+                try {
+                    listener.onRequestStart(startTimeNanos);
+                } catch (Exception e) {
+                    logger.warn(() -> new ParameterizedMessage("onRequestStart listener [{}] failed", listener), e);
+                }
+            }
+        }
+
+        @Override
+        public void onRequestEnd(SearchPhaseContext context) {
+            for (SearchRequestOperationsListener listener : listeners) {
+                try {
+                    listener.onRequestEnd(context);
+                } catch (Exception e) {
+                    logger.warn(() -> new ParameterizedMessage("onRequestEnd listener [{}] failed", listener), e);
+                }
+            }
+        }
     }
 }