feat(imp):[#214] add stop watches for analyzing performance

irs-common/src/main/java/org/eclipse/tractusx/irs/common/util/concurrent/ResultFinder.java

@@ -35,13 +35,17 @@
 import lombok.Getter;
 import lombok.ToString;
 import lombok.extern.slf4j.Slf4j;
+import org.slf4j.Logger;
 
 /**
  * Helper class to find the relevant result from a list of futures.
  */
 @Slf4j
 public class ResultFinder {
 
+    // TODO (mfischer): Remove when #214 is tested
+    public static final String LOGPREFIX_TO_BE_REMOVED_LATER = "#214@ ";
+
     /**
      * Returns a new {@link CompletableFuture} which completes
      * when at least one of the given futures completes successfully or all fail.
@@ -53,12 +57,14 @@ public class ResultFinder {
      */
     public <T> CompletableFuture<T> getFastestResult(final List<CompletableFuture<T>> futures) {
 
+        final String logPrefix = LOGPREFIX_TO_BE_REMOVED_LATER + "getFastestResult - ";
+
         if (futures == null || futures.isEmpty()) {
-            log.warn("#214@getFastestResult#0 Called getFastestResult with empty list of futures");
+            log.warn(logPrefix + "Called getFastestResult with empty list of futures");
             return CompletableFuture.completedFuture(null);
         }
 
-        log.info("#214@getFastestResult#1 Trying to get fastest result from list of futures");
+        log.info(logPrefix + "Trying to get fastest result from list of futures");
 
         final CompletableFuture<T> fastestResultPromise = new CompletableFuture<>();
 
@@ -69,19 +75,17 @@ public <T> CompletableFuture<T> getFastestResult(final List<CompletableFuture<T>
                                                             .handle(completingOnFirstSuccessful(fastestResultPromise)))
                                        .toList();
 
-        log.info("#214@getFastestResult#2");
-
         allOf(toArray(futuresList)).whenComplete((value, ex) -> {
 
-            log.info("#214@getFastestResult#3 List of futures completed");
+            log.info(logPrefix + "All of the futures completed");
 
             if (ex != null) {
-                log.error("g#214@etFastestResult#4 Exception occurred: " + ex.getMessage(), ex);
+                log.error(logPrefix + "Exception occurred: " + ex.getMessage(), ex);
                 fastestResultPromise.completeExceptionally(new CompletionExceptions(exceptions));
             } else if (fastestResultPromise.isDone()) {
-                log.info("#214@getFastestResult#5 Fastest result already found, ignoring the others");
+                log.info(logPrefix + "Fastest result already found, ignoring the others");
             } else {
-                log.info("#214@getFastestResult#6 Completing");
+                log.info(logPrefix + "Completing");
                 fastestResultPromise.complete(null);
             }
         });
@@ -96,29 +100,28 @@ private static <T> CompletableFuture<T>[] toArray(final List<CompletableFuture<T
     private static <T> BiFunction<T, Throwable, Boolean> completingOnFirstSuccessful(
             final CompletableFuture<T> resultPromise) {
 
+        final String logPrefix = LOGPREFIX_TO_BE_REMOVED_LATER + "completingOnFirstSuccessful - ";
+
         return (value, throwable) -> {
 
-            log.info("#214@completingOnFirstSuccessful#1 value: {}, throwable: {}", value, throwable);
+            log.info(logPrefix + "value: '{}', throwable: {}", value, throwable);
 
             final boolean notFinishedByOtherFuture = !resultPromise.isDone();
-            log.info("#214@completingOnFirstSuccessful#2 notFinishedByOtherFuture {} ", notFinishedByOtherFuture);
+            log.info(logPrefix + "notFinishedByOtherFuture {} ", notFinishedByOtherFuture);
 
             final boolean currentFutureSuccessful = throwable == null && value != null;
 
             if (notFinishedByOtherFuture && currentFutureSuccessful) {
 
                 // first future that completes successfully completes the overall future
-                log.info("#214@completingOnFirstSuccessful#3 First future that completed successfully");
+                log.info(logPrefix + "First future that completed successfully");
                 resultPromise.complete(value);
                 return true;
 
             } else {
                 if (throwable != null) {
-                    log.warn("#214@completingOnFirstSuccessful#4 Exception occurred: " + throwable.getMessage(),
-                            throwable);
+                    log.warn(logPrefix + "Exception occurred: " + throwable.getMessage(), throwable);
                     throw new CompletionException(throwable.getMessage(), throwable);
-                } else {
-                    log.info("#214@completingOnFirstSuccessful#5 log just for debugging");
                 }
                 return false;
             }
@@ -127,7 +130,8 @@ private static <T> BiFunction<T, Throwable, Boolean> completingOnFirstSuccessful
 
     private static <T> Function<Throwable, T> collectingExceptionsAndThrow(final List<Throwable> exceptions) {
         return t -> {
-            log.error("collectingExceptionsAndThrow -- Exception occurred: " + t.getMessage(), t);
+            log.error(LOGPREFIX_TO_BE_REMOVED_LATER + "collectingExceptionsAndThrow - " + "Exception occurred: "
+                    + t.getMessage(), t);
             exceptions.add(t);
             throw new CompletionException(t);
         };
@@ -143,9 +147,18 @@ public static class CompletionExceptions extends CompletionException {
         private final List<Throwable> causes;
 
         public CompletionExceptions(final List<Throwable> causes) {
-            super("All failing, use getCauses() for details");
+            super(LOGPREFIX_TO_BE_REMOVED_LATER + "All failing, use getCauses() for details");
             this.causes = causes;
         }
 
+        public void logWarn(final Logger log, final String prefix) {
+
+            log.warn("{}{}", prefix, this.getMessage(), this.getCause());
+
+            for (final Throwable cause : this.getCauses()) {
+                log.warn(prefix + cause.getMessage(), cause);
+            }
+        }
+
     }
 }

irs-common/src/main/java/org/eclipse/tractusx/irs/common/util/concurrent/StopwatchUtils.java

@@ -0,0 +1,52 @@
+/********************************************************************************
+ * Copyright (c) 2022,2024 Bayerische Motoren Werke Aktiengesellschaft (BMW AG)
+ * Copyright (c) 2021,2024 Contributors to the Eclipse Foundation
+ *
+ * See the NOTICE file(s) distributed with this work for additional
+ * information regarding copyright ownership.
+ *
+ * This program and the accompanying materials are made available under the
+ * terms of the Apache License, Version 2.0 which is available at
+ * https://www.apache.org/licenses/LICENSE-2.0.
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+ * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+ * License for the specific language governing permissions and limitations
+ * under the License.
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ ********************************************************************************/
+package org.eclipse.tractusx.irs.common.util.concurrent;
+
+import org.apache.commons.lang3.StringUtils;
+import org.slf4j.Logger;
+import org.springframework.util.StopWatch;
+
+/**
+ * Utilities for stop watches.
+ */
+public final class StopwatchUtils {
+
+    /**
+     * utility class, therefore private constructor
+     */
+    private StopwatchUtils() {
+        super();
+    }
+
+    public static void startWatch(final Logger log, final StopWatch stopWatch, final String msg) {
+        stopWatch.start(msg);
+        log.info(msg);
+    }
+
+    public static void stopWatch(final Logger log, final StopWatch stopWatch) {
+        stopWatch(log, stopWatch, "");
+    }
+
+    public static void stopWatch(final Logger log, final StopWatch stopWatch, final String messagePrefix) {
+        stopWatch.stop();
+        final String prefix = StringUtils.isNotBlank(messagePrefix) ? messagePrefix + " - " : "";
+        log.info("{}{} took {} ms", prefix, stopWatch.getLastTaskName(), stopWatch.getLastTaskTimeMillis());
+    }
+}