Add custom logs to track /create-index flow

sumitasr · Jul 23, 2024 · 295a70d · 295a70d
1 parent e32c30c
commit 295a70d
Show file tree

Hide file tree

Showing 5 changed files with 24 additions and 2 deletions.
diff --git a/.../src/main/java/org/opensearch/action/admin/indices/create/TransportCreateIndexAction.java b/.../src/main/java/org/opensearch/action/admin/indices/create/TransportCreateIndexAction.java
@@ -32,6 +32,8 @@
 
 package org.opensearch.action.admin.indices.create;
 
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
 import org.opensearch.action.support.ActionFilters;
 import org.opensearch.action.support.clustermanager.TransportClusterManagerNodeAction;
 import org.opensearch.cluster.ClusterState;
@@ -41,8 +43,10 @@
 import org.opensearch.cluster.metadata.MetadataCreateIndexService;
 import org.opensearch.cluster.service.ClusterService;
 import org.opensearch.common.inject.Inject;
+import org.opensearch.common.unit.TimeValue;
 import org.opensearch.core.action.ActionListener;
 import org.opensearch.core.common.io.stream.StreamInput;
+import org.opensearch.rest.RestController;
 import org.opensearch.threadpool.ThreadPool;
 import org.opensearch.transport.TransportService;
 
@@ -54,7 +58,7 @@
  * @opensearch.internal
  */
 public class TransportCreateIndexAction extends TransportClusterManagerNodeAction<CreateIndexRequest, CreateIndexResponse> {
-
+    private static final Logger logger = LogManager.getLogger(TransportCreateIndexAction.class);
     private final MetadataCreateIndexService createIndexService;
 
     @Inject
@@ -106,6 +110,7 @@ protected void clusterManagerOperation(
         final ClusterState state,
         final ActionListener<CreateIndexResponse> listener
     ) {
+        long latencyStartTimeInNs = System.nanoTime();
         String cause = request.cause();
         if (cause.length() == 0) {
             cause = "api";
@@ -130,6 +135,8 @@ protected void clusterManagerOperation(
                 response -> new CreateIndexResponse(response.isAcknowledged(), response.isShardsAcknowledged(), indexName)
             )
         );
+        logger.info("[Custom Log] TransportCreateIndexAction, clusterManagerOperation latency: {} ms",
+            TimeValue.nsecToMSec(System.nanoTime() - latencyStartTimeInNs));
     }
 
 }
diff --git a/server/src/main/java/org/opensearch/cluster/metadata/MetadataCreateIndexService.java b/server/src/main/java/org/opensearch/cluster/metadata/MetadataCreateIndexService.java
@@ -331,6 +331,7 @@ public void createIndex(
         final CreateIndexClusterStateUpdateRequest request,
         final ActionListener<CreateIndexClusterStateUpdateResponse> listener
     ) {
+        long latencyStartTimeInNs = System.nanoTime();
         onlyCreateIndex(request, ActionListener.wrap(response -> {
             if (response.isAcknowledged()) {
                 activeShardsObserver.waitForActiveShards(
@@ -344,6 +345,8 @@ public void createIndex(
                                 request.index()
                             );
                         }
+                        logger.info("[Custom Log] MetadataCreateIndexService, createIndex latency: {} ms",
+                            TimeValue.nsecToMSec(System.nanoTime() - latencyStartTimeInNs));
                         listener.onResponse(new CreateIndexClusterStateUpdateResponse(response.isAcknowledged(), shardsAcknowledged));
                     },
                     listener::onFailure

diff --git a/server/src/main/java/org/opensearch/cluster/routing/allocation/AllocationService.java b/server/src/main/java/org/opensearch/cluster/routing/allocation/AllocationService.java
@@ -575,6 +575,7 @@ private void reroute(RoutingAllocation allocation) {
     }
 
     private void allocateExistingUnassignedShards(RoutingAllocation allocation) {
+        long latencyStartTimeInNs = System.nanoTime();
         allocation.routingNodes().unassigned().sort(PriorityComparator.getAllocationComparator(allocation)); // sort for priority ordering
 
         for (final ExistingShardsAllocator existingShardsAllocator : existingShardsAllocators.values()) {
@@ -613,6 +614,8 @@ private void allocateExistingUnassignedShards(RoutingAllocation allocation) {
                 getAllocatorForShard(shardRouting, allocation).allocateUnassigned(shardRouting, allocation, replicaIterator);
             }
         }
+        logger.info("[Custom Log] AllocationService, allocateExistingUnassignedShards latency: {} ms",
+            TimeValue.nsecToMSec(System.nanoTime() - latencyStartTimeInNs));
     }
 
     private void allocateAllUnassignedShards(RoutingAllocation allocation) {

diff --git a/server/src/main/java/org/opensearch/cluster/service/MasterService.java b/server/src/main/java/org/opensearch/cluster/service/MasterService.java
@@ -223,9 +223,12 @@ protected void onTimeout(List<? extends BatchedTask> tasks, TimeValue timeout) {
 
         @Override
         protected void run(Object batchingKey, List<? extends BatchedTask> tasks, Function<Boolean, String> taskSummaryGenerator) {
+            long latencyStartTimeInNs = System.nanoTime();
             ClusterStateTaskExecutor<Object> taskExecutor = (ClusterStateTaskExecutor<Object>) batchingKey;
             List<UpdateTask> updateTasks = (List<UpdateTask>) tasks;
             runTasks(new TaskInputs(taskExecutor, updateTasks, taskSummaryGenerator));
+            logger.info("[Custom Log] MasterService, run latency: {} ms",
+                TimeValue.nsecToMSec(System.nanoTime() - latencyStartTimeInNs));
         }
 
         class UpdateTask extends BatchedTask {

diff --git a/server/src/main/java/org/opensearch/rest/RestController.java b/server/src/main/java/org/opensearch/rest/RestController.java
@@ -41,6 +41,7 @@
 import org.opensearch.common.io.stream.BytesStreamOutput;
 import org.opensearch.common.logging.DeprecationLogger;
 import org.opensearch.common.path.PathTrie;
+import org.opensearch.common.unit.TimeValue;
 import org.opensearch.common.util.FeatureFlags;
 import org.opensearch.common.util.concurrent.ThreadContext;
 import org.opensearch.common.util.io.Streams;
@@ -291,7 +292,10 @@ public Optional<RestHandler> dispatchHandler(String uri, String rawPath, RestReq
     @Override
     public void dispatchRequest(RestRequest request, RestChannel channel, ThreadContext threadContext) {
         try {
+            long latencyStartTimeInNs = System.nanoTime();
             tryAllHandlers(request, channel, threadContext);
+            logger.info("[Custom Log] RestController, dispatchRequest latency: {} ms",
+                TimeValue.nsecToMSec(System.nanoTime() - latencyStartTimeInNs));
         } catch (Exception e) {
             try {
                 channel.sendResponse(new BytesRestResponse(channel, e));
@@ -378,8 +382,10 @@ private void dispatchRequest(RestRequest request, RestChannel channel, RestHandl
                 // This header is intended for internal use only.
                 client.threadPool().getThreadContext().putHeader(SYSTEM_INDEX_ACCESS_CONTROL_HEADER_KEY, Boolean.FALSE.toString());
             }
-
+            long latencyStartTimeInNs = System.nanoTime();
             handler.handleRequest(request, responseChannel, client);
+            logger.info("[Custom Log] RestController, handleRequest latency: {} ms",
+                TimeValue.nsecToMSec(System.nanoTime() - latencyStartTimeInNs));
         } catch (Exception e) {
             responseChannel.sendResponse(new BytesRestResponse(responseChannel, e));
         }