Add event bus and fix slow bean initialization logs

Author: pmendelski

.github/workflows/build.yml

@@ -14,7 +14,7 @@ jobs:
 
       - name: Skip duplicates and docs
         id: skip
-        uses: fkirc/skip-duplicate-actions@v4
+        uses: fkirc/skip-duplicate-actions@v5
         with:
           paths_ignore: '["**/README.md", "LICENSE", ".gitignore", ".editorconfig", ".idea/**"]'
 

build.gradle

@@ -12,10 +12,11 @@ group = 'com.coditory.quark'
 description = 'Coditory Quark Configuration Library'
 
 dependencies {
-    api 'org.slf4j:slf4j-api:2.0.0'
+    api 'org.slf4j:slf4j-api:2.0.3'
     api 'org.jetbrains:annotations:23.0.0'
-    testImplementation 'com.coditory.quark:quark-config:0.1.5'
-    testImplementation 'ch.qos.logback:logback-classic:1.4.0'
+    implementation 'com.coditory.quark:quark-eventbus:0.0.1'
+    testImplementation 'com.coditory.quark:quark-config:0.1.11'
+    testImplementation 'ch.qos.logback:logback-classic:1.4.4'
     testImplementation 'org.spockframework:spock-core:2.3-groovy-4.0'
     testImplementation 'org.skyscreamer:jsonassert:1.5.1'
 }

src/integration/groovy/annotated/SlowBeanCreationSpec.groovy

@@ -0,0 +1,33 @@
+package annotated
+
+import ch.qos.logback.classic.Logger
+import com.coditory.quark.context.Context
+import com.coditory.quark.context.base.CapturingAppender
+import org.slf4j.LoggerFactory
+import spock.lang.Specification
+
+class SlowBeanCreationSpec extends Specification {
+    CapturingAppender appender = new CapturingAppender()
+
+    void setup() {
+        Logger rootLogger = (Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME)
+        rootLogger.addAppender(appender)
+    }
+
+    void cleanup() {
+        Logger rootLogger = (Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME)
+        rootLogger.detachAppender(appender)
+    }
+
+    def "should log slow bean initialization"() {
+        given:
+            Context context = Context.scanPackage(annotated.samples.slow_beans.Bar)
+        when:
+            annotated.samples.slow_beans.Baz baz = context.get(annotated.samples.slow_beans.Baz)
+
+        then:
+            List<String> logs = appender.getLogsByMessagePrefix("Slow bean creation")
+            logs.size() == 1
+            logs.first().startsWith("[WARN] Slow bean creation. Bean: Bar")
+    }
+}

src/integration/groovy/annotated/samples/slow_beans/Bar.groovy

@@ -0,0 +1,4 @@
+package annotated.samples.slow_beans
+
+class Bar {
+}

src/integration/groovy/annotated/samples/slow_beans/Baz.groovy

@@ -0,0 +1,9 @@
+package annotated.samples.slow_beans
+
+class Baz {
+    final Bar bar
+
+    Baz(Bar bar) {
+        this.bar = bar
+    }
+}

src/integration/groovy/annotated/samples/slow_beans/ConfigInit.groovy

@@ -0,0 +1,24 @@
+package annotated.samples.slow_beans
+
+import com.coditory.quark.context.annotations.Bean
+import com.coditory.quark.context.annotations.Configuration
+
+@Configuration
+class ConfigInit {
+    @Bean
+    annotated.samples.slow_beans.Bar bar() {
+        Thread.sleep(1_000)
+        return new annotated.samples.slow_beans.Bar()
+    }
+
+    @Bean
+    annotated.samples.slow_beans.Baz baz(annotated.samples.slow_beans.Bar bar) {
+        return new annotated.samples.slow_beans.Baz(bar)
+    }
+
+    @Bean
+    annotated.samples.slow_beans.Foo foo(annotated.samples.slow_beans.Baz baz) {
+        Thread.sleep(1_000)
+        return new annotated.samples.slow_beans.Foo(baz)
+    }
+}

src/integration/groovy/annotated/samples/slow_beans/Foo.groovy

@@ -0,0 +1,15 @@
+package annotated.samples.slow_beans
+
+import static java.util.Objects.requireNonNull
+
+class Foo {
+    final Baz baz
+
+    Foo(Baz baz) {
+        this.baz = requireNonNull(baz)
+    }
+
+    Foo(Bar bar) {
+        throw new IllegalStateException("This constructor should not be used")
+    }
+}

src/main/java/com/coditory/quark/context/BeanFinalizer.java

@@ -38,9 +38,6 @@ private static void closeBean(Object bean, BeanDescriptor<?> descriptor, Method
             throw new BeanFinalizationException("Could not close bean: " + descriptor.toShortString() + " using method: " + simplifyMethodName(method), e);
         }
         log.debug("Closed bean {} using method {} in {}", descriptor.toShortString(), simplifyMethodName(method), timer.measureAndFormat());
-        if (timer.isOverThreshold()) {
-            log.warn("Detected long bean close operation. Bean: {}, Method: {}, Time: {}", descriptor.toShortString(), simplifyMethodName(method), timer.measureAndFormat());
-        }
     }
 
     private static void closeBean(Closeable bean, BeanDescriptor<?> descriptor) {
@@ -51,8 +48,5 @@ private static void closeBean(Closeable bean, BeanDescriptor<?> descriptor) {
             throw new BeanFinalizationException("Could not close bean: " + descriptor.toShortString(), e);
         }
         log.debug("Closed bean {} in {}", descriptor.toShortString(), timer.measureAndFormat());
-        if (timer.isOverThreshold()) {
-            log.warn("Detected long bean close operation. Bean: {}, Time: {}", descriptor.toShortString(), timer.measureAndFormat());
-        }
     }
 }

src/main/java/com/coditory/quark/context/BeanHolder.java

@@ -1,5 +1,6 @@
 package com.coditory.quark.context;
 
+import com.coditory.quark.eventbus.EventEmitter;
 import org.jetbrains.annotations.Nullable;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
@@ -25,6 +26,7 @@ static <T> BeanHolder<T> holder(BeanDescriptor<T> descriptor, BeanCreator<T> cre
     private final BeanDescriptor<T> descriptor;
     private final Set<Class<?>> classHierarchy;
     private final boolean eager;
+    private EventEmitter eventEmitter;
     private T bean;
     private boolean initialized = false;
     private boolean closed = false;
@@ -36,6 +38,13 @@ private BeanHolder(BeanDescriptor<T> descriptor, BeanCreator<T> creator, boolean
         this.eager = eager;
     }
 
+    void setEventEmitter(EventEmitter eventEmitter) {
+        if (this.eventEmitter != null) {
+            throw new IllegalStateException("EventEmitter was already set");
+        }
+        this.eventEmitter = requireNonNull(eventEmitter);
+    }
+
     public boolean isEager() {
         return eager;
     }
@@ -79,18 +88,21 @@ T getCached() {
     }
 
     boolean isActive(ConditionContext context) {
-        Timer timer = Timer.start();
+        expectEventEmitter();
+        eventEmitter.emit(new ContextEvent.BeanPreIsActiveCheckEvent(descriptor));
         boolean result = creator.isActive(context);
-        if (timer.isOverThreshold()) {
-            log.warn("Detected long bean condition check. Bean: {}, Time: {}", descriptor.toShortString(), timer.measureAndFormat());
-        }
+        eventEmitter.emit(new ContextEvent.BeanPostIsActiveCheckEvent(descriptor));
         return result;
     }
 
     @Nullable
     public T get(ResolutionContext context) {
         if (bean == null) {
+            expectEventEmitter();
+            ResolutionPath path = context.getResolutionPath();
+            eventEmitter.emit(new ContextEvent.BeanPreCreateEvent(descriptor, path));
             createBean(context);
+            eventEmitter.emit(new ContextEvent.BeanPostCreateEvent(descriptor, path));
         }
         return bean;
     }
@@ -102,9 +114,6 @@ private void createBean(ResolutionContext context) {
             throw new ContextException("Expected non-null bean: " + descriptor);
         }
         log.debug("Created bean {} in {}", descriptor.toShortString(), timer.measureAndFormat());
-        if (timer.isOverThreshold()) {
-            log.warn("Detected long bean creation. Bean: {}, Time: {}", descriptor.toShortString(), timer.measureAndFormat());
-        }
         if (!initialized) {
             initializeBean(bean, descriptor, context);
             initialized = true;
@@ -113,8 +122,18 @@ private void createBean(ResolutionContext context) {
 
     void close(ResolutionContext context) {
         if (!closed) {
+            expectEventEmitter();
+            ResolutionPath path = context.getResolutionPath();
+            eventEmitter.emit(new ContextEvent.BeanPreCloseEvent(descriptor, path));
             closeBean(bean, descriptor, context);
             closed = true;
+            eventEmitter.emit(new ContextEvent.BeanPostCloseEvent(descriptor, path));
+        }
+    }
+
+    private void expectEventEmitter() {
+        if (eventEmitter == null) {
+            throw new IllegalStateException("Expected BeanHolder to have eventEmitter");
         }
     }
 }

src/main/java/com/coditory/quark/context/BeanInitializer.java

@@ -37,9 +37,6 @@ private static void initializeBean(Object bean, BeanDescriptor<?> descriptor, Me
             throw new BeanInitializationException("Could not initialize bean: " + descriptor.toShortString() + " using method: " + simplifyMethodName(method), e);
         }
         log.debug("Initialized bean {} using method {} in {}", descriptor.toShortString(), simplifyMethodName(method), timer.measureAndFormat());
-        if (timer.isOverThreshold()) {
-            log.warn("Detected long bean initialization. Bean: {}, Method: {}, Time: {}", descriptor.toShortString(), simplifyMethodName(method), timer.measureAndFormat());
-        }
     }
 
     private static void initializeBean(Initializable bean, BeanDescriptor<?> descriptor) {
@@ -50,8 +47,5 @@ private static void initializeBean(Initializable bean, BeanDescriptor<?> descrip
             throw new BeanInitializationException("Could not initialize bean: " + descriptor.toShortString(), e);
         }
         log.debug("Initialized bean {} in {}", descriptor.toShortString(), timer.measureAndFormat());
-        if (timer.isOverThreshold()) {
-            log.warn("Detected long bean initialization. Bean: {}, Time: {}", descriptor.toShortString(), timer.measureAndFormat());
-        }
     }
 }