Improve Snapshot Logging

server/src/main/java/org/elasticsearch/repositories/blobstore/BlobStoreRepository.java

@@ -94,6 +94,7 @@
 import org.elasticsearch.core.RefCounted;
 import org.elasticsearch.core.Releasable;
 import org.elasticsearch.core.SuppressForbidden;
+import org.elasticsearch.core.TimeValue;
 import org.elasticsearch.core.Tuple;
 import org.elasticsearch.index.IndexVersion;
 import org.elasticsearch.index.shard.ShardId;
@@ -4223,11 +4224,12 @@ private void checkAborted() {
                 final long uploadTimeInMillis = threadPool.rawRelativeTimeInMillis() - startMillis;
                 blobStoreSnapshotMetrics.incrementCountersForPartUpload(partBytes, uploadTimeInMillis);
                 logger.trace(
-                    "[{}] Writing [{}] of size [{}b] to [{}] took [{}ms]",
+                    "[{}] Writing [{}] of size [{}b] to [{}] took [{}/{}ms]",
                     metadata.name(),
                     partName,
                     partBytes,
                     shardContainer.path(),
+                    new TimeValue(uploadTimeInMillis),
                     uploadTimeInMillis
                 );
             }

server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java

@@ -15,6 +15,7 @@
 import org.elasticsearch.common.Strings;
 import org.elasticsearch.common.settings.ClusterSettings;
 import org.elasticsearch.common.settings.Setting;
+import org.elasticsearch.common.time.DateFormatter;
 import org.elasticsearch.common.util.concurrent.ConcurrentCollections;
 import org.elasticsearch.core.TimeValue;
 import org.elasticsearch.index.shard.ShardId;
@@ -44,6 +45,7 @@ public class SnapshotShutdownProgressTracker {
     );
 
     private static final Logger logger = LogManager.getLogger(SnapshotShutdownProgressTracker.class);
+    private static final DateFormatter DATE_TIME_FORMATTER = DateFormatter.forPattern("strict_date_optional_time");
 
     private final Supplier<String> getLocalNodeId;
     private final Consumer<Logger> logIndexShardSnapshotStatuses;
@@ -136,15 +138,17 @@ private void logProgressReport() {
         logger.info(
             """
                 Current active shard snapshot stats on data node [{}]. \
-                Node shutdown cluster state update received at [{} millis]. \
-                Finished signalling shard snapshots to pause at [{} millis]. \
+                Node shutdown cluster state update received at [{} UTC]. \
+                Finished signalling shard snapshots to pause at [{} UTC]. \
+                Time between the node shutdown cluster state update and signalling shard snapshots to pause is [{} millis]. \
                 Number shard snapshots running [{}]. \
                 Number shard snapshots waiting for master node reply to status update request [{}] \
                 Shard snapshot completion stats since shutdown began: Done [{}]; Failed [{}]; Aborted [{}]; Paused [{}]\
                 """,
             getLocalNodeId.get(),
-            shutdownStartMillis,
-            shutdownFinishedSignallingPausingMillis,
+            DATE_TIME_FORMATTER.formatMillis(shutdownStartMillis),
+            DATE_TIME_FORMATTER.formatMillis(shutdownFinishedSignallingPausingMillis),
+            shutdownFinishedSignallingPausingMillis - shutdownStartMillis,
             numberOfShardSnapshotsInProgressOnDataNode.get(),
             shardSnapshotRequests.size(),
             doneCount.get(),

server/src/test/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTrackerTests.java

@@ -16,6 +16,7 @@
 import org.elasticsearch.common.settings.ClusterSettings;
 import org.elasticsearch.common.settings.Setting;
 import org.elasticsearch.common.settings.Settings;
+import org.elasticsearch.common.time.DateFormatter;
 import org.elasticsearch.common.unit.ByteSizeValue;
 import org.elasticsearch.common.util.concurrent.DeterministicTaskQueue;
 import org.elasticsearch.core.TimeValue;
@@ -271,12 +272,15 @@ public void testTrackerPauseTimestamp() {
         );
 
         try (var mockLog = MockLog.capture(Coordinator.class, SnapshotShutdownProgressTracker.class)) {
+            long timeInMillis = testThreadPool.relativeTimeInMillis();
             mockLog.addExpectation(
                 new MockLog.SeenEventExpectation(
                     "pausing timestamp should be set",
                     SnapshotShutdownProgressTracker.class.getName(),
                     Level.INFO,
-                    "*Finished signalling shard snapshots to pause at [" + testThreadPool.relativeTimeInMillis() + " millis]*"
+                    "*Finished signalling shard snapshots to pause at ["
+                        + DateFormatter.forPattern("strict_date_optional_time").formatMillis(timeInMillis)
+                        + " UTC]*"
                 )
             );