improve bean instantiations check

Author: tobias-lippert

.github/workflows/bean-instantiations-startup.yml

@@ -30,10 +30,10 @@ jobs:
 
       - name: Start Spring Boot app
         run: |
-          PROFILES=dev,localci,lti,aeolus,theia,iris,localvc,artemis,scheduling,buildagent,core,ldap,no-liquibase
+          PROFILES=dev,localci,lti,aeolus,theia,iris,localvc,artemis,scheduling,buildagent,core,ldap
           JAR=$(ls build/libs/Artemis*.jar | head -n1)
           nohup java -jar $JAR \
-            --spring.profiles.active=dev,localci,lti,aeolus,theia,iris,localvc,artemis,scheduling,buildagent,core,ldap,no-liquibase \
+            --spring.profiles.active=$PROFILES \
             --artemis.user-management.passkey.enabled=true \
             --artemis.user-management.use-external=false \
             --artemis.iris.url=http://iris.fake \
@@ -49,58 +49,179 @@ jobs:
 
       - name: Wait for the application to start
         run: |
+          # Configuration variables
           RUNNING_MESSAGE="'Artemis is running!'"
-          echo "Waiting up to 60s for $RUNNING_MESSAGE to appear in app.log..."
+          STARTUP_TIMEOUT_ATTEMPTS=30
+          STARTUP_RETRY_INTERVAL=2
+          STARTUP_TOTAL_TIMEOUT=$((STARTUP_TIMEOUT_ATTEMPTS * STARTUP_RETRY_INTERVAL))
+          LOG_FILE="app.log"
+
+          echo "Waiting up to ${STARTUP_TOTAL_TIMEOUT}s for $RUNNING_MESSAGE to appear in $LOG_FILE..."
 
           isAppRunning=false
-          for i in {1..30}; do
-            if grep -q $RUNNING_MESSAGE app.log; then
+          for i in $(seq 1 $STARTUP_TIMEOUT_ATTEMPTS); do
+            if grep -q $RUNNING_MESSAGE $LOG_FILE; then
               isAppRunning=true
-              echo "✅ Found $RUNNING_MESSAGE in app.log after $i attempts"
+              echo "✅ Found $RUNNING_MESSAGE in $LOG_FILE after $i attempts"
               break
             fi
-            echo "  attempt $i/30: not found yet"
-            sleep 2
+            echo "  attempt $i/$STARTUP_TIMEOUT_ATTEMPTS: not found yet"
+            sleep $STARTUP_RETRY_INTERVAL
           done
 
           if [ "$isAppRunning" = false ]; then
-            echo "❌ Timeout: $RUNNING_MESSAGE not found in app.log"
-            cat app.log
+            echo "❌ Timeout: $RUNNING_MESSAGE not found in $LOG_FILE"
+            cat $LOG_FILE
+            exit 1
+          fi
+
+      - name: Extract and validate startup bean instantiation metrics
+        run: |
+          # Configuration variables
+          STARTUP_LOG_PATTERN="Bean instantiation graph exported to startupBeans\.dot \(([0-9]+) edges, longest dependency chain: \[([^\]]*)\]\)"
+          MIN_INSTANTIATED_BEANS=20
+          MAX_INSTANTIATED_BEANS=94
+          MAX_STARTUP_DEPENDENCY_CHAIN_LENGTH=9
+          LOG_FILE="app.log"
+
+          # Extract search text from pattern (everything before opening parenthesis)
+          STARTUP_SEARCH=$(echo "$STARTUP_LOG_PATTERN" | sed 's/ \\(.*$//')
+
+          LINE=$(grep -E "$STARTUP_SEARCH" $LOG_FILE) \
+            || { echo "❌ No startup metrics line found"; cat $LOG_FILE; exit 1; }
+
+          if [[ "$LINE" =~ $STARTUP_LOG_PATTERN ]]; then
+            INSTANTIATED_BEANS=${BASH_REMATCH[1]}
+            LONGEST_CHAIN_CONTENT=${BASH_REMATCH[2]}
+            # Count chain length by counting commas and adding 1 (if not empty)
+            if [ -n "$LONGEST_CHAIN_CONTENT" ]; then
+              ACTUAL_MAX_CHAIN_LENGTH=$(echo "$LONGEST_CHAIN_CONTENT" | tr ',' '\n' | wc -l)
+            else
+              ACTUAL_MAX_CHAIN_LENGTH=0
+            fi
+          else
+            echo "❌ Failed to parse startup metrics from: $LINE"
+            exit 1
+          fi
+
+          echo "• Number of instantiated beans = $INSTANTIATED_BEANS"
+          echo "• Longest dependency chain length = $ACTUAL_MAX_CHAIN_LENGTH"
+          echo "• Longest chain: [$LONGEST_CHAIN_CONTENT]"
+
+          echo "Validating against thresholds: MIN_INSTANTIATED_BEANS=$MIN_INSTANTIATED_BEANS (expected ≥ $MIN_INSTANTIATED_BEANS), MAX_INSTANTIATED_BEANS=$MAX_INSTANTIATED_BEANS (expected ≤ $MAX_INSTANTIATED_BEANS), MAX_STARTUP_DEPENDENCY_CHAIN_LENGTH=$MAX_STARTUP_DEPENDENCY_CHAIN_LENGTH (expected ≤ $MAX_STARTUP_DEPENDENCY_CHAIN_LENGTH)"
+
+          if (( INSTANTIATED_BEANS < MIN_INSTANTIATED_BEANS )); then
+            echo "❌ $INSTANTIATED_BEANS < $MIN_INSTANTIATED_BEANS beans. Something seems to be wrong, as usually more beans are instantiated."
+            exit 1
+          fi
+
+          if (( INSTANTIATED_BEANS > MAX_INSTANTIATED_BEANS )); then
+            echo "❌ $INSTANTIATED_BEANS > $MAX_INSTANTIATED_BEANS threshold"
+            exit 1
+          fi
+
+          if (( ACTUAL_MAX_CHAIN_LENGTH > MAX_STARTUP_DEPENDENCY_CHAIN_LENGTH )); then
+            echo "❌ Longest dependency chain length $ACTUAL_MAX_CHAIN_LENGTH > $MAX_STARTUP_DEPENDENCY_CHAIN_LENGTH threshold"
+            exit 1
+          fi
+
+          echo "✅ Final values → Beans: $INSTANTIATED_BEANS; Longest dependency chain length: $ACTUAL_MAX_CHAIN_LENGTH"
+          echo "🎉 Startup bean instantiation metrics within expected ranges"
+
+      - name: Check for startup dependency chains exceeding threshold
+        run: |
+          # Configuration variables
+          STARTUP_DEEP_CHAIN_PATTERN="Startup long bean instantiation chain"
+          MAX_STARTUP_DEPENDENCY_CHAIN_LENGTH=9
+          LOG_FILE="app.log"
+
+          echo "Checking for startup dependency chains exceeding threshold..."
+
+          if (( ACTUAL_MAX_CHAIN_LENGTH > MAX_STARTUP_DEPENDENCY_CHAIN_LENGTH )); then
+            echo "❌ Startup dependency chain length $ACTUAL_MAX_CHAIN_LENGTH > $MAX_STARTUP_DEPENDENCY_CHAIN_LENGTH threshold"
+            echo "Chains exceeding threshold:"
+            grep -E "$STARTUP_DEEP_CHAIN_PATTERN" $LOG_FILE || echo "  (No detailed chains found in log)"
+            echo "🔧 These chains violate the threshold MAX_STARTUP_DEPENDENCY_CHAIN_LENGTH. Please refactor them to break these chains."
             exit 1
+          else
+            echo "✅ No startup dependency chains exceed the threshold of $MAX_STARTUP_DEPENDENCY_CHAIN_LENGTH"
           fi
 
-      - name: Extract and validate bean instantiation metrics
+      - name: Extract and validate deferred eager bean chain length
         run: |
-          LINE=$(grep 'Bean instantiation graph exported' app.log) \
-            || { echo "❌ No metrics line"; cat app.log; exit 1; }
-          if [[ "$LINE" =~ \(([0-9]+)\ edges,\ max\ call\ stack\ size:\ ([0-9]+)\) ]]; then
-            EDGES=${BASH_REMATCH[1]}
-            MAXSTACK=${BASH_REMATCH[2]}
+          DEFERRED_BEAN_PATTERN="Maximum dependency chain length during deferred eager init: ([0-9]+)"
+          DEFERRED_TIMEOUT_ATTEMPTS=10
+          DEFERRED_RETRY_INTERVAL=3
+          DEFERRED_TOTAL_TIMEOUT=$((DEFERRED_TIMEOUT_ATTEMPTS * DEFERRED_RETRY_INTERVAL))
+          MIN_DEFERRED_CHAIN_LENGTH=1
+          MAX_DEFERRED_CHAIN_LENGTH=15
+          LOG_FILE="app.log"
+          LOG_TAIL_LINES=50
+
+          # Extract search text from pattern (everything before :)
+          DEFERRED_BEAN_SEARCH=$(echo "$DEFERRED_BEAN_PATTERN" | sed 's/:.*$//')
+
+          echo "Waiting for deferred eager bean initialization to complete..."
+
+          DEFERRED_LINE=""
+          for i in $(seq 1 $DEFERRED_TIMEOUT_ATTEMPTS); do
+            DEFERRED_LINE=$(grep -E "$DEFERRED_BEAN_SEARCH" $LOG_FILE 2>/dev/null || true)
+            if [ -n "$DEFERRED_LINE" ]; then
+              echo "✅ Found deferred eager bean initialization log after $i attempts"
+              break
+            fi
+            echo "  attempt $i/$DEFERRED_TIMEOUT_ATTEMPTS: deferred eager bean initialization not completed yet"
+            sleep $DEFERRED_RETRY_INTERVAL
+          done
+
+          if [ -z "$DEFERRED_LINE" ]; then
+            echo "❌ No deferred eager bean chain length line found after ${DEFERRED_TOTAL_TIMEOUT}s"
+            echo "Last $LOG_TAIL_LINES lines of $LOG_FILE:"
+            tail -$LOG_TAIL_LINES $LOG_FILE
+            exit 1
+          fi
+
+          if [[ "$DEFERRED_LINE" =~ $DEFERRED_BEAN_PATTERN ]]; then
+            DEFERRED_CHAIN_LENGTH=${BASH_REMATCH[1]}
           else
-            echo "❌ Failed to parse numbers"; exit 1
+            echo "❌ Failed to parse deferred eager bean chain length from: $DEFERRED_LINE"
+            exit 1
           fi
-          echo "• Number of edges = $EDGES"
-          echo "• Max call stack size = $MAXSTACK"
-          MIN_EDGES=20
-          MAX_EDGES=94
-          MAX_STACK_SIZE_THRESHOLD=9
-          echo "Validating against thresholds: MIN_EDGES=$MIN_EDGES, MAX_EDGES=$MAX_EDGES, MAX_STACK_SIZE_THRESHOLD=$MAX_STACK_SIZE_THRESHOLD"
-          if (( EDGES < MIN_EDGES )); then
-          echo "❌ < $MIN_EDGES edges. Something seems to be wrong, as usually more beans are instantiated."
-          exit 1
+
+          echo "• Maximum dependency chain length during deferred eager bean initialization = $DEFERRED_CHAIN_LENGTH"
+          echo "Validating against thresholds: MIN_DEFERRED_CHAIN_LENGTH=$MIN_DEFERRED_CHAIN_LENGTH (expected ≥ $MIN_DEFERRED_CHAIN_LENGTH), MAX_DEFERRED_CHAIN_LENGTH=$MAX_DEFERRED_CHAIN_LENGTH (expected ≤ $MAX_DEFERRED_CHAIN_LENGTH)"
+
+          if (( DEFERRED_CHAIN_LENGTH < MIN_DEFERRED_CHAIN_LENGTH )); then
+            echo "❌ Deferred chain length $DEFERRED_CHAIN_LENGTH < $MIN_DEFERRED_CHAIN_LENGTH. Something seems to be wrong, as usually some deferred beans are instantiated."
+            exit 1
           fi
 
-          if (( EDGES > MAX_EDGES )); then
-          echo "❌ > $MAX_EDGES edges"
-          exit 1
+          if (( DEFERRED_CHAIN_LENGTH > MAX_DEFERRED_CHAIN_LENGTH )); then
+            echo "❌ Deferred chain length $DEFERRED_CHAIN_LENGTH > $MAX_DEFERRED_CHAIN_LENGTH threshold"
+            exit 1
           fi
 
-          if (( MAXSTACK > MAX_STACK_SIZE_THRESHOLD )); then
-          echo "❌ stack > $MAX_STACK_SIZE_THRESHOLD"
-          exit 1
+          echo "✅ Deferred eager bean chain length: $DEFERRED_CHAIN_LENGTH"
+          echo "🎉 Deferred eager bean dependency chain length within expected ranges"
+
+      - name: Check for deferred dependency chains exceeding threshold
+        run: |
+          # Configuration variables
+          DEFERRED_DEEP_CHAIN_PATTERN="Deferred long bean instantiation chain"
+          MAX_DEFERRED_DEPENDENCY_CHAIN_LENGTH=15
+          LOG_FILE="app.log"
+
+          echo "Checking for deferred dependency chains exceeding threshold..."
+
+          if (( DEFERRED_CHAIN_LENGTH > MAX_DEFERRED_DEPENDENCY_CHAIN_LENGTH )); then
+            echo "❌ Deferred dependency chain length $DEFERRED_CHAIN_LENGTH > $MAX_DEFERRED_DEPENDENCY_CHAIN_LENGTH threshold"
+            echo "Chains exceeding threshold:"
+            grep -E "$DEFERRED_DEEP_CHAIN_PATTERN" $LOG_FILE || echo "  (No detailed chains found in log)"
+            echo "🔧 These chains violate the threshold MAX_DEFERRED_DEPENDENCY_CHAIN_LENGTH. Please refactor them to break these chains."
+            exit 1
+          else
+            echo "✅ No deferred dependency chains exceed the threshold of $MAX_DEFERRED_DEPENDENCY_CHAIN_LENGTH"
           fi
-          echo "✅ Final values → Edges: $EDGES; Max call stack size: $MAXSTACK"
-          echo "🎉 Number of instantiated beans on startup within expected ranges"
 
       - name: Stop application
         if: always()

src/main/java/de/tum/cit/aet/artemis/core/DeferredEagerBeanInitializationCompletedEvent.java

@@ -0,0 +1,4 @@
+package de.tum.cit.aet.artemis.core;
+
+public record DeferredEagerBeanInitializationCompletedEvent() {
+}

src/main/java/de/tum/cit/aet/artemis/core/config/BeanInstantiationTracer.java

@@ -5,10 +5,14 @@
 import java.io.IOException;
 import java.io.PrintWriter;
 import java.util.ArrayDeque;
+import java.util.ArrayList;
+import java.util.Collections;
 import java.util.Deque;
+import java.util.List;
 import java.util.Queue;
 import java.util.concurrent.ConcurrentLinkedQueue;
 import java.util.concurrent.atomic.AtomicInteger;
+import java.util.concurrent.atomic.AtomicReference;
 
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
@@ -18,6 +22,7 @@
 import org.springframework.context.event.EventListener;
 import org.springframework.stereotype.Component;
 
+import de.tum.cit.aet.artemis.core.DeferredEagerBeanInitializationCompletedEvent;
 import de.tum.cit.aet.artemis.core.PrintStartupBeansEvent;
 import de.tum.cit.aet.artemis.core.util.Pair;
 
@@ -36,6 +41,16 @@ public class BeanInstantiationTracer implements InstantiationAwareBeanPostProces
 
     private final AtomicInteger maxCallStackSize = new AtomicInteger(0);
 
+    private final AtomicReference<List<String>> longestChain = new AtomicReference<>(new ArrayList<>());
+
+    private static final int STARTUP_MAX_DEPENDENCY_CHAIN_THRESHOLD = 9;
+
+    private static final int DEFERRED_INIT_MAX_DEPENDENCY_CHAIN_THRESHOLD = 15;
+
+    private final Queue<List<String>> exceedingThresholdChains = new ConcurrentLinkedQueue<>();
+
+    private final Queue<List<String>> deferredInstantiationExceedingThresholdChains = new ConcurrentLinkedQueue<>();
+
     @Override
     public Object postProcessBeforeInstantiation(Class<?> cls, String name) {
         if (cls.getName().startsWith(BASE)) {
@@ -44,10 +59,21 @@ public Object postProcessBeforeInstantiation(Class<?> cls, String name) {
             if (parent != null) {
                 edges.add(new Pair<>(parent, name));
             }
-            log.debug("Instantiating: {} ← {}", name, parent != null ? parent : "root");
             stack.push(name);
+
             int depth = stack.size();
-            maxCallStackSize.updateAndGet(prev -> Math.max(prev, depth));
+
+            if (depth > STARTUP_MAX_DEPENDENCY_CHAIN_THRESHOLD) {
+                exceedingThresholdChains.add(new ArrayList<>(stack));
+            }
+            if (depth > DEFERRED_INIT_MAX_DEPENDENCY_CHAIN_THRESHOLD) {
+                deferredInstantiationExceedingThresholdChains.add(new ArrayList<>(stack));
+            }
+
+            int prevMax = maxCallStackSize.get();
+            if (depth > prevMax && maxCallStackSize.compareAndSet(prevMax, depth)) {
+                longestChain.set(new ArrayList<>(stack));
+            }
         }
         return null;
     }
@@ -63,10 +89,6 @@ public Object postProcessAfterInitialization(Object bean, String name) {
         return bean;
     }
 
-    /**
-     * Prints the bean instantiation graph for the startup to a DOT file.
-     * This file can be used to visualize the dependencies between beans using tools like Graphviz.
-     */
     @EventListener(PrintStartupBeansEvent.class)
     public void printDependencyGraph() {
         try (PrintWriter out = new PrintWriter("startupBeans.dot")) {
@@ -75,10 +97,37 @@ public void printDependencyGraph() {
                 out.printf("  \"%s\" -> \"%s\";%n", edge.first(), edge.second());
             }
             out.println("}");
-            log.debug("Bean instantiation graph exported to startupBeans.dot ({} edges, max call stack size: {})", edges.size(), maxCallStackSize.get());
+            log.debug("Bean instantiation graph exported to startupBeans.dot ({} edges, longest dependency chain: {})", edges.size(), longestChain.get());
         }
         catch (IOException e) {
             log.error("Failed to write startupBeans.dot", e);
         }
+
+        int i = 1;
+        for (List<String> chain : exceedingThresholdChains) {
+            List<String> reversed = new ArrayList<>(chain);
+            Collections.reverse(reversed);
+            log.debug("Startup long bean instantiation chain {} (length {}): {}", i++, reversed.size(), String.join(" → ", reversed));
+        }
+
+        // Log the single longest chain
+        List<String> longest = longestChain.get();
+        if (!longest.isEmpty()) {
+            List<String> forward = new ArrayList<>(longest);
+            Collections.reverse(forward);
+            log.debug("Longest instantiation chain: {}", String.join(" → ", forward));
+        }
+    }
+
+    @EventListener(DeferredEagerBeanInitializationCompletedEvent.class)
+    public void logDeferredInitChainsExceedingThreshold() {
+        int i = 1;
+        for (List<String> chain : deferredInstantiationExceedingThresholdChains) {
+            List<String> reversed = new ArrayList<>(chain);
+            Collections.reverse(reversed);
+            log.debug("Deferred long bean instantiation chain {} (length {}): {}", i++, reversed.size(), String.join(" → ", reversed));
+        }
+
+        log.debug("Maximum dependency chain length during deferred eager init: {}", maxCallStackSize.get());
     }
 }

src/main/java/de/tum/cit/aet/artemis/core/config/DeferredEagerBeanInitializer.java

@@ -14,6 +14,8 @@
 import org.springframework.context.annotation.Profile;
 import org.springframework.stereotype.Component;
 
+import de.tum.cit.aet.artemis.core.DeferredEagerBeanInitializationCompletedEvent;
+
 /**
  * This component initializes all lazy singleton beans after the application is ready.
  * This allows us to benefit from the lazy initialization of beans during startup, without comprising end user experience as beans are initialized before the first request is
@@ -62,7 +64,7 @@ public void initializeDeferredEagerBeans() {
                 log.warn("Deferred eager initialization of bean {} failed", name, ex);
             }
         });
-
+        context.publishEvent(new DeferredEagerBeanInitializationCompletedEvent());
         log.info("Deferred eager initialization of all beans completed");
     }
 }

src/main/java/de/tum/cit/aet/artemis/core/config/migration/MigrationRegistry.java

@@ -7,6 +7,7 @@
 import java.util.SortedMap;
 import java.util.TreeMap;
 
+import org.springframework.boot.autoconfigure.condition.ConditionalOnBooleanProperty;
 import org.springframework.boot.context.event.ApplicationReadyEvent;
 import org.springframework.context.annotation.Lazy;
 import org.springframework.context.annotation.Profile;
@@ -19,6 +20,7 @@
 @Component
 @Lazy
 @Profile(PROFILE_CORE_AND_SCHEDULING)
+@ConditionalOnBooleanProperty(prefix = "spring.liquibase", name = "enabled", matchIfMissing = true)
 public class MigrationRegistry {
 
     // Using SortedMap to allow sorting. I'm using a map because with a list entries could accidentally be switched.