From dd26f70303399ac10a961c33ad92e58d81208560 Mon Sep 17 00:00:00 2001 From: Sandesh Kumar Date: Fri, 2 Jun 2023 13:15:54 -0700 Subject: [PATCH] Replace cached time with system clock in MasterService debug logs Signed-off-by: Sandesh Kumar --- CHANGELOG.md | 1 + .../opensearch/cluster/service/MasterService.java | 12 ++++++------ 2 files changed, 7 insertions(+), 6 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index e3ad2d4e7c7db..b063ef571d3b8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -94,6 +94,7 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), ### Changed - Replace jboss-annotations-api_1.2_spec with jakarta.annotation-api ([#7836](https://github.com/opensearch-project/OpenSearch/pull/7836)) - Add min, max, average and thread info to resource stats in tasks API ([#7673](https://github.com/opensearch-project/OpenSearch/pull/7673)) +- MasterService Debug logs for computation time to use system clock time instead of cached time ### Deprecated 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 9712fdbfbe8ec..29bbba1660d52 100644 --- a/server/src/main/java/org/opensearch/cluster/service/MasterService.java +++ b/server/src/main/java/org/opensearch/cluster/service/MasterService.java @@ -291,14 +291,14 @@ private void runTasks(TaskInputs taskInputs) { return; } - final long computationStartTime = threadPool.relativeTimeInMillis(); + final long computationStartTime = System.nanoTime(); final TaskOutputs taskOutputs = calculateTaskOutputs(taskInputs, previousClusterState); taskOutputs.notifyFailedTasks(); final TimeValue computationTime = getTimeSince(computationStartTime); logExecutionTime(computationTime, "compute cluster state update", summary); if (taskOutputs.clusterStateUnchanged()) { - final long notificationStartTime = threadPool.relativeTimeInMillis(); + final long notificationStartTime = System.nanoTime(); taskOutputs.notifySuccessfulTasksOnUnchangedClusterState(); final TimeValue executionTime = getTimeSince(notificationStartTime); logExecutionTime(executionTime, "notify listeners on unchanged cluster state", summary); @@ -309,7 +309,7 @@ private void runTasks(TaskInputs taskInputs) { } else { logger.debug("cluster state updated, version [{}], source [{}]", newClusterState.version(), summary); } - final long publicationStartTime = threadPool.relativeTimeInMillis(); + final long publicationStartTime = System.nanoTime(); try { ClusterChangedEvent clusterChangedEvent = new ClusterChangedEvent(summary, newClusterState, previousClusterState); // new cluster state, notify all listeners @@ -335,8 +335,8 @@ private void runTasks(TaskInputs taskInputs) { } } - private TimeValue getTimeSince(long startTimeMillis) { - return TimeValue.timeValueMillis(Math.max(0, threadPool.relativeTimeInMillis() - startTimeMillis)); + private TimeValue getTimeSince(long startTimeNanos) { + return TimeValue.timeValueMillis(TimeValue.nsecToMSec(System.nanoTime() - startTimeNanos)); } protected void publish(ClusterChangedEvent clusterChangedEvent, TaskOutputs taskOutputs, long startTimeMillis) { @@ -358,7 +358,7 @@ protected boolean blockingAllowed() { } void onPublicationSuccess(ClusterChangedEvent clusterChangedEvent, TaskOutputs taskOutputs) { - final long notificationStartTime = threadPool.relativeTimeInMillis(); + final long notificationStartTime = System.nanoTime(); taskOutputs.processedDifferentClusterState(clusterChangedEvent.previousState(), clusterChangedEvent.state()); try {