From 387e73a7cf258cf3741eb034519781161540632f Mon Sep 17 00:00:00 2001 From: Sumit Bansal Date: Tue, 23 Jul 2024 21:02:18 +0530 Subject: [PATCH] add more logs in create-index flow --- .../create/TransportCreateIndexAction.java | 7 +++--- .../metadata/MetadataCreateIndexService.java | 6 +++-- .../routing/allocation/AllocationService.java | 7 ++++-- .../service/ClusterApplierService.java | 22 +++++++++++++++++-- .../cluster/service/MasterService.java | 9 ++++++-- .../org/opensearch/rest/RestController.java | 12 ++++++---- 6 files changed, 48 insertions(+), 15 deletions(-) diff --git a/server/src/main/java/org/opensearch/action/admin/indices/create/TransportCreateIndexAction.java b/server/src/main/java/org/opensearch/action/admin/indices/create/TransportCreateIndexAction.java index d86551779f5d4..1b786b47a74a6 100644 --- a/server/src/main/java/org/opensearch/action/admin/indices/create/TransportCreateIndexAction.java +++ b/server/src/main/java/org/opensearch/action/admin/indices/create/TransportCreateIndexAction.java @@ -46,7 +46,6 @@ 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; @@ -135,8 +134,10 @@ protected void clusterManagerOperation( response -> new CreateIndexResponse(response.isAcknowledged(), response.isShardsAcknowledged(), indexName) ) ); - logger.info("[Custom Log] TransportCreateIndexAction, clusterManagerOperation latency: {} ms", - TimeValue.nsecToMSec(System.nanoTime() - latencyStartTimeInNs)); + 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 index 61eb298cc892f..13f88f51264d2 100644 --- a/server/src/main/java/org/opensearch/cluster/metadata/MetadataCreateIndexService.java +++ b/server/src/main/java/org/opensearch/cluster/metadata/MetadataCreateIndexService.java @@ -345,8 +345,10 @@ public void createIndex( request.index() ); } - logger.info("[Custom Log] MetadataCreateIndexService, createIndex latency: {} ms", - TimeValue.nsecToMSec(System.nanoTime() - latencyStartTimeInNs)); + 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 index a932d38d12273..987170f11ab94 100644 --- a/server/src/main/java/org/opensearch/cluster/routing/allocation/AllocationService.java +++ b/server/src/main/java/org/opensearch/cluster/routing/allocation/AllocationService.java @@ -567,6 +567,7 @@ private void reroute(RoutingAllocation allocation) { allocateExistingUnassignedShards(allocation); // try to allocate existing shard copies first shardsAllocator.allocate(allocation); + logger.info("[Custom Log] AllocationService, reroute latency: {} ms", TimeValue.nsecToMSec(System.nanoTime() - rerouteStartTimeNS)); clusterManagerMetrics.recordLatency( clusterManagerMetrics.rerouteHistogram, (double) Math.max(0, TimeValue.nsecToMSec(System.nanoTime() - rerouteStartTimeNS)) @@ -614,8 +615,10 @@ 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)); + 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/ClusterApplierService.java b/server/src/main/java/org/opensearch/cluster/service/ClusterApplierService.java index 6234427445754..21b2ebd680e6b 100644 --- a/server/src/main/java/org/opensearch/cluster/service/ClusterApplierService.java +++ b/server/src/main/java/org/opensearch/cluster/service/ClusterApplierService.java @@ -562,9 +562,14 @@ private void applyChanges(UpdateTask task, ClusterState previousClusterState, Cl } logger.trace("connecting to nodes of cluster state with version {}", newClusterState.version()); + long connectToNodesStartTimeNS = System.nanoTime(); try (TimingHandle ignored = stopWatch.timing("connecting to new nodes")) { connectToNodesAndWait(newClusterState); } + logger.info( + "[Custom Log] ClusterApplierService, connectToNodesAndWait latency: {} ms", + TimeValue.nsecToMSec(System.nanoTime() - connectToNodesStartTimeNS) + ); // nothing to do until we actually recover from the gateway or any other block indicates we need to disable persistency if (clusterChangedEvent.state().blocks().disableStatePersistence() == false && clusterChangedEvent.metadataChanged()) { @@ -574,11 +579,20 @@ private void applyChanges(UpdateTask task, ClusterState previousClusterState, Cl clusterSettings.applySettings(incomingSettings); } } - + long appliersStartTimeNS = System.nanoTime(); logger.debug("apply cluster state with version {}", newClusterState.version()); callClusterStateAppliers(clusterChangedEvent, stopWatch); + logger.info( + "[Custom Log] ClusterApplierService, callClusterStateAppliers latency: {} ms", + TimeValue.nsecToMSec(System.nanoTime() - appliersStartTimeNS) + ); + long disconnectStartTimeNS = System.nanoTime(); nodeConnectionsService.disconnectFromNodesExcept(newClusterState.nodes()); + logger.info( + "[Custom Log] ClusterApplierService, disconnectFromNodesExcept latency: {} ms", + TimeValue.nsecToMSec(System.nanoTime() - disconnectStartTimeNS) + ); assert newClusterState.coordinationMetadata() .getLastAcceptedConfiguration() @@ -591,8 +605,12 @@ private void applyChanges(UpdateTask task, ClusterState previousClusterState, Cl logger.debug("set locally applied cluster state to version {}", newClusterState.version()); state.set(newClusterState); - + long listenersStartTimeNS = System.nanoTime(); callClusterStateListeners(clusterChangedEvent, stopWatch); + logger.info( + "[Custom Log] callClusterStateListeners latency: {} ms", + TimeValue.nsecToMSec(System.nanoTime() - listenersStartTimeNS) + ); } protected void connectToNodesAndWait(ClusterState newClusterState) { diff --git a/server/src/main/java/org/opensearch/cluster/service/MasterService.java b/server/src/main/java/org/opensearch/cluster/service/MasterService.java index c2d2a60fb683c..82d9047ab5f0b 100644 --- a/server/src/main/java/org/opensearch/cluster/service/MasterService.java +++ b/server/src/main/java/org/opensearch/cluster/service/MasterService.java @@ -227,8 +227,7 @@ protected void run(Object batchingKey, List tasks, Functi ClusterStateTaskExecutor taskExecutor = (ClusterStateTaskExecutor) batchingKey; List updateTasks = (List) tasks; runTasks(new TaskInputs(taskExecutor, updateTasks, taskSummaryGenerator)); - logger.info("[Custom Log] MasterService, run latency: {} ms", - TimeValue.nsecToMSec(System.nanoTime() - latencyStartTimeInNs)); + logger.info("[Custom Log] MasterService, run latency: {} ms", TimeValue.nsecToMSec(System.nanoTime() - latencyStartTimeInNs)); } class UpdateTask extends BatchedTask { @@ -329,6 +328,11 @@ private void runTasks(TaskInputs taskInputs) { final TimeValue computationTime = getTimeSince(computationStartTime); logExecutionTime(computationTime, "compute cluster state update", shortSummary); + logger.info( + "[Custom Log] Cluster state compute - latency: {} ms, operation : {}", + computationTime.getMillis(), + taskInputs.executor.getClass().getSimpleName() + ); clusterManagerMetrics.recordLatency( clusterManagerMetrics.clusterStateComputeHistogram, (double) computationTime.getMillis(), @@ -394,6 +398,7 @@ protected boolean blockingAllowed() { stateStats.stateUpdateTook(durationMillis); stateStats.stateUpdated(); clusterManagerMetrics.recordLatency(clusterManagerMetrics.clusterStatePublishHistogram, (double) durationMillis); + logger.info("[Custom Log] Cluster state publish - latency: {} ms", durationMillis); } catch (Exception e) { stateStats.stateUpdateFailed(); onPublicationFailed(clusterChangedEvent, taskOutputs, startTimeNanos, e); diff --git a/server/src/main/java/org/opensearch/rest/RestController.java b/server/src/main/java/org/opensearch/rest/RestController.java index 1b26c18b9620d..21323330b330e 100644 --- a/server/src/main/java/org/opensearch/rest/RestController.java +++ b/server/src/main/java/org/opensearch/rest/RestController.java @@ -294,8 +294,10 @@ public void dispatchRequest(RestRequest request, RestChannel channel, ThreadCont try { long latencyStartTimeInNs = System.nanoTime(); tryAllHandlers(request, channel, threadContext); - logger.info("[Custom Log] RestController, dispatchRequest latency: {} ms", - TimeValue.nsecToMSec(System.nanoTime() - latencyStartTimeInNs)); + logger.info( + "[Custom Log] RestController, dispatchRequest latency: {} ms", + TimeValue.nsecToMSec(System.nanoTime() - latencyStartTimeInNs) + ); } catch (Exception e) { try { channel.sendResponse(new BytesRestResponse(channel, e)); @@ -384,8 +386,10 @@ private void dispatchRequest(RestRequest request, RestChannel channel, RestHandl } long latencyStartTimeInNs = System.nanoTime(); handler.handleRequest(request, responseChannel, client); - logger.info("[Custom Log] RestController, handleRequest latency: {} ms", - TimeValue.nsecToMSec(System.nanoTime() - latencyStartTimeInNs)); + logger.debug( + "[Custom Log] RestController, handleRequest latency: {} ms", + TimeValue.nsecToMSec(System.nanoTime() - latencyStartTimeInNs) + ); } catch (Exception e) { responseChannel.sendResponse(new BytesRestResponse(responseChannel, e)); }