[PDS-344883] Async Initialisation and Profiling

atlasdb-commons/src/main/java/com/palantir/async/initializer/AsyncInitializer.java

@@ -60,17 +60,28 @@ public final void initialize(boolean initializeAsync) {
 
     private void tryInitializationLoop() {
         if (state.isCancelled()) {
+            log.info(
+                    "Shutting down executor associated with asynchronous initialisation, as it was cancelled",
+                    SafeArg.of("className", getInitializingClassName()),
+                    SafeArg.of("numberOfAttempts", numberOfInitializationAttempts),
+                    SafeArg.of("durationBeforeCancellation", getMillisecondsSinceInitialization()));
             singleThreadedExecutor.shutdown();
             return;
         }
 
         try {
+            log.info(
+                    "Attempting to initialize {} on the attempt {}. The amount of time elapsed since we began was {}"
+                            + " milliseconds.",
+                    SafeArg.of("className", getInitializingClassName()),
+                    SafeArg.of("numberOfAttempts", numberOfInitializationAttempts),
+                    SafeArg.of("initializationDuration", getMillisecondsSinceInitialization()));
             tryInitializeInternal();
             log.info(
                     "Initialized {} on the attempt {} in {} milliseconds",
                     SafeArg.of("className", getInitializingClassName()),
                     SafeArg.of("numberOfAttempts", numberOfInitializationAttempts),
-                    SafeArg.of("initializationDuration", System.currentTimeMillis() - initializationStartTime));
+                    SafeArg.of("initializationDuration", getMillisecondsSinceInitialization()));
         } catch (Throwable throwable) {
             log.info(
                     "Failed to initialize {} on the attempt {}",
@@ -84,19 +95,23 @@ private void tryInitializationLoop() {
                         "Failed to cleanup when initialization of {} failed on attempt {} with {} milliseconds",
                         SafeArg.of("className", getInitializingClassName()),
                         SafeArg.of("numberOfAttempts", numberOfInitializationAttempts),
-                        SafeArg.of("initializationDuration", System.currentTimeMillis() - initializationStartTime),
+                        SafeArg.of("initializationDuration", getMillisecondsSinceInitialization()),
                         cleanupThrowable);
             }
             scheduleInitialization(sleepInterval());
         }
     }
 
+    private long getMillisecondsSinceInitialization() {
+        return System.currentTimeMillis() - initializationStartTime;
+    }
+
     // Not final for tests.
     void scheduleInitialization(Duration delay) {
         singleThreadedExecutor.schedule(this::tryInitializationLoop, delay.toMillis(), TimeUnit.MILLISECONDS);
     }
 
-    // Not final for tests
+    // Not final for tests.
     ScheduledExecutorService createExecutorService() {
         return PTExecutors.newSingleThreadScheduledExecutor(
                 new NamedThreadFactory("AsyncInitializer-" + getInitializingClassName(), true));

changelog/@unreleased/pr-6485.v2.yml

@@ -0,0 +1,6 @@
+type: improvement
+improvement:
+  description: Asynchronous initialisation now logs when the initialisation an individual
+    object starts, as well as when the executor is shutdown.
+  links:
+  - https://github.com/palantir/atlasdb/pull/6485