Add step execution metrics and summary information

pom.xml

@@ -11,7 +11,7 @@
     <parent>
         <artifactId>smallrye-parent</artifactId>
         <groupId>io.smallrye</groupId>
-        <version>42</version>
+        <version>43-SNAPSHOT</version>
     </parent>
 
     <name>Quarkus Qlue</name>
@@ -25,6 +25,7 @@
 
     <properties>
         <version.io.smallrye.common>2.2.0</version.io.smallrye.common>
+        <test.loglevel>INFO</test.loglevel>
     </properties>
 
     <build>
@@ -37,6 +38,17 @@
                 <filtering>true</filtering>
             </resource>
         </resources>
+        <plugins>
+            <plugin>
+                <artifactId>maven-surefire-plugin</artifactId>
+                <configuration>
+                    <systemPropertyVariables>
+                        <java.util.logging.manager>org.jboss.logmanager.LogManager</java.util.logging.manager>
+                        <test.loglevel>${test.loglevel}</test.loglevel>
+                    </systemPropertyVariables>
+                </configuration>
+            </plugin>
+        </plugins>
     </build>
 
     <dependencyManagement>

src/main/java/io/quarkus/qlue/AnonymousStepId.java

@@ -0,0 +1,44 @@
+package io.quarkus.qlue;
+
+import java.util.concurrent.atomic.AtomicLong;
+
+/**
+ * A step identifier for anonymous steps.
+ * Such steps have a unique sequence number associated with them.
+ */
+public final class AnonymousStepId extends StepId {
+    private final long id;
+
+    private static final AtomicLong idSeq = new AtomicLong(1);
+
+    AnonymousStepId(final StepId parent, final long id) {
+        super(parent, Long.hashCode(id));
+        this.id = id;
+    }
+
+    /**
+     * Construct a new instance.
+     */
+    public AnonymousStepId() {
+        this(null, idSeq.getAndIncrement());
+    }
+
+    /**
+     * {@return the unique value of this identifier}
+     */
+    public long id() {
+        return id;
+    }
+
+    public boolean equals(final StepId other) {
+        return other instanceof AnonymousStepId id && equals(id);
+    }
+
+    public boolean equals(final AnonymousStepId other) {
+        return this == other || super.equals(other) && id == other.id;
+    }
+
+    public StringBuilder toString(final StringBuilder sb) {
+        return sb.append("anonymous<").append(Long.toHexString(id)).append('>');
+    }
+}

src/main/java/io/quarkus/qlue/ChainBuilder.java

@@ -2,7 +2,7 @@
 
 import static io.quarkus.qlue._private.Messages.log;
 import static java.lang.invoke.MethodHandles.Lookup;
-import static java.lang.invoke.MethodHandles.publicLookup;
+import static java.lang.invoke.MethodHandles.lookup;
 
 import java.lang.invoke.MethodHandle;
 import java.lang.reflect.Constructor;
@@ -13,19 +13,18 @@
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.Collections;
-import java.util.HashMap;
 import java.util.HashSet;
 import java.util.IdentityHashMap;
 import java.util.List;
-import java.util.Map;
 import java.util.Set;
 import java.util.function.BiConsumer;
 import java.util.function.Consumer;
 import java.util.function.Function;
+import java.util.stream.Stream;
 
 import io.quarkus.qlue.item.ClassItem;
+import io.quarkus.qlue.item.InstanceItem;
 import io.quarkus.qlue.item.Item;
-import io.quarkus.qlue.item.StepClassItem;
 import io.smallrye.common.constraint.Assert;
 
 /**
@@ -149,13 +148,13 @@ public ChainBuilder setInjectionMapper(final InjectionMapper injectionMapper) {
      * Add all of the steps defined in the given object's class. The given object instance is used as-is.
      * Each recognized step method is added as a step which invokes the method, producing any results that are produced
      * by the method.
-     * Step methods must be {@code public}.
+     * Step methods must be {@code public} or accessible from this module.
      *
      * @param obj the step object to add (must not be {@code null})
      * @return this builder
      */
     public ChainBuilder addStepObject(Object obj) {
-        return addStepObject(obj, publicLookup());
+        return addStepObject(obj, lookup());
     }
 
     /**
@@ -186,6 +185,7 @@ public ChainBuilder addStepObject(Object obj, Lookup lookup) {
                 }
                 SwitchableConsumer<StepContext> cons = new SwitchableConsumer<>(method.toString());
                 StepBuilder stepBuilder = addRawStep(cons);
+                stepBuilder.id(new MethodStepId(new InstanceStepId(obj), method));
                 Consumer<StepContext> methodHandler = injectionMapper.handleStepMethod(stepBuilder, method, lookup);
                 int cnt = method.getParameterCount();
                 List<Function<StepContext, Object>> methodParamVals = new ArrayList<>(cnt);
@@ -223,7 +223,7 @@ public void accept(final StepContext stepContext) {
     /**
      * Add all of the steps defined in the given class. The construction of the class itself is
      * added as a step which consumes the injected dependencies of the class and produces the
-     * corresponding {@link StepClassItem}. Each recognized step method is added as a step
+     * corresponding {@link InstanceItem}. Each recognized step method is added as a step
      * which consumes the {@code StepClassItem} and the injected dependencies of the method, and subsequently invokes
      * the method, producing any results that are produced by the method.
      *
@@ -232,13 +232,13 @@ public void accept(final StepContext stepContext) {
      * @return this builder
      */
     public <T> ChainBuilder addStepClass(Class<T> clazz) {
-        return addStepClass(clazz, publicLookup());
+        return addStepClass(clazz, lookup());
     }
 
     /**
      * Add all of the steps defined in the given class. The construction of the class itself is
      * added as a step which consumes the injected dependencies of the class and produces the
-     * corresponding {@link StepClassItem}. Each recognized step method is added as a step
+     * corresponding {@link InstanceItem}. Each recognized step method is added as a step
      * which consumes the {@code StepClassItem} and the injected dependencies of the method, and subsequently invokes
      * the method, producing any results that are produced by the method.
      *
@@ -252,7 +252,7 @@ public <T> ChainBuilder addStepClass(Class<T> clazz, Lookup lookup) {
         SwitchableConsumer<StepContext> cons = new SwitchableConsumer<>(clazz.toString());
         // this is the step builder for the class producer
         StepBuilder classStepBuilder = addRawStep(cons);
-        classStepBuilder.produces(StepClassItem.class, clazz);
+        classStepBuilder.produces(InstanceItem.class, clazz);
         // get the overall class handler
         Consumer<StepContext> classHandler = injectionMapper.handleClass(classStepBuilder, clazz, lookup);
         MethodHandle mh = null;
@@ -269,6 +269,7 @@ public <T> ChainBuilder addStepClass(Class<T> clazz, Lookup lookup) {
             if (mh != null) {
                 throw log.multipleConstructors(clazz);
             }
+            classStepBuilder.id(new MethodStepId(constructor));
             mh = tmp;
         }
         // no eligible constructor found
@@ -283,16 +284,31 @@ public <T> ChainBuilder addStepClass(Class<T> clazz, Lookup lookup) {
             ctorParamVals.add(injectionMapper.handleParameter(classStepBuilder, ctor, i, lookup));
         }
         // check out each field
-        Map<Field, Function<StepContext, Object>> fieldVals = new HashMap<>();
-        for (Field field : clazz.getDeclaredFields()) {
-            int mods = field.getModifiers();
-            if (Modifier.isFinal(mods) || Modifier.isStatic(mods)) {
-                // skip it
-                continue;
-            }
-            field.setAccessible(true);
-            fieldVals.put(field, injectionMapper.handleField(classStepBuilder, field, lookup));
-        }
+        Field[] declaredFields = clazz.getDeclaredFields();
+        List<BiConsumer<Object, StepContext>> fieldInjections = Stream.of(declaredFields)
+                .filter(field -> {
+                    int mods = field.getModifiers();
+                    return !Modifier.isFinal(mods) && !Modifier.isStatic(mods);
+                })
+                .map(field -> {
+                    MethodHandle setter;
+                    try {
+                        setter = lookup.unreflectSetter(field);
+                    } catch (IllegalAccessException e) {
+                        throw log.notAccessible(field, lookup.lookupClass(), e);
+                    }
+                    Function<StepContext, Object> fn = injectionMapper.handleField(classStepBuilder, field, lookup);
+                    return (BiConsumer<Object, StepContext>) (instance, ctxt) -> {
+                        try {
+                            setter.invoke(instance, fn.apply(ctxt));
+                        } catch (Throwable e) {
+                            log.failedToSetField(field, e);
+                            ctxt.addProblem(e);
+                            return;
+                        }
+                    };
+                })
+                .toList();
         Consumer<StepContext> classFinish = injectionMapper.handleClassFinish(classStepBuilder, clazz, lookup);
         // now create the real class build step
         final Constructor<?> finalCtor = ctor;
@@ -314,20 +330,12 @@ public void accept(final StepContext stepContext) {
                     return;
                 }
                 // inject fields
-                for (Map.Entry<Field, Function<StepContext, Object>> entry : fieldVals.entrySet()) {
-                    Field field = entry.getKey();
-                    Function<StepContext, Object> fn = entry.getValue();
-                    try {
-                        field.set(instance, fn.apply(stepContext));
-                    } catch (IllegalAccessException e) {
-                        log.failedToSetField(field, e);
-                        stepContext.addProblem(e);
-                        return;
-                    }
+                for (BiConsumer<Object, StepContext> injection : fieldInjections) {
+                    injection.accept(instance, stepContext);
                 }
                 classFinish.accept(stepContext);
                 // and we're set
-                stepContext.produce(clazz, new StepClassItem(instance));
+                stepContext.produce(clazz, new InstanceItem(instance));
             }
         });
         classStepBuilder.build();
@@ -341,7 +349,8 @@ public void accept(final StepContext stepContext) {
                 method.setAccessible(true);
                 cons = new SwitchableConsumer<>(method.toString());
                 StepBuilder stepBuilder = addRawStep(cons);
-                stepBuilder.consumes(StepClassItem.class, clazz);
+                stepBuilder.id(new MethodStepId(method));
+                stepBuilder.consumes(InstanceItem.class, clazz);
                 Consumer<StepContext> methodHandler = injectionMapper.handleStepMethod(stepBuilder, method, lookup);
                 cnt = method.getParameterCount();
                 List<Function<StepContext, Object>> methodParamVals = new ArrayList<>(cnt);
@@ -351,8 +360,8 @@ public void accept(final StepContext stepContext) {
                 BiConsumer<StepContext, Object> retHandler = injectionMapper.handleReturnValue(stepBuilder, method, lookup);
                 cons.setDelegate(new Consumer<StepContext>() {
                     public void accept(final StepContext stepContext) {
-                        StepClassItem item = stepContext.consume(StepClassItem.class, clazz);
-                        Object instance = item.getInstance();
+                        InstanceItem item = stepContext.consume(InstanceItem.class, clazz);
+                        Object instance = item.instance();
                         methodHandler.accept(stepContext);
                         final int cnt = methodParamVals.size();
                         final Object[] args = new Object[cnt];

src/main/java/io/quarkus/qlue/Consume.java

@@ -1,22 +1,10 @@
 package io.quarkus.qlue;
 
 /**
+ *
  */
-final class Consume {
-    private final StepBuilder stepBuilder;
-    private final ItemId itemId;
-    private final Constraint constraint;
-    private final ConsumeFlags flags;
-
-    Consume(final StepBuilder stepBuilder, final ItemId itemId, final Constraint constraint, final ConsumeFlags flags) {
-        this.stepBuilder = stepBuilder;
-        this.itemId = itemId;
-        this.constraint = constraint;
-        this.flags = flags;
-    }
-
-    ConsumeFlags getFlags() {
-        return flags;
+record Consume(StepBuilder stepBuilder, ItemId itemId, Constraint constraint, ConsumeFlags flags) {
+    Consume {
     }
 
     Consume combine(final Constraint constraint, final ConsumeFlags flags) {
@@ -29,7 +17,7 @@ Consume combine(final Constraint constraint, final ConsumeFlags flags) {
         return new Consume(stepBuilder, itemId, outputConstraint, outputFlags);
     }
 
-    Constraint getConstraint() {
-        return constraint;
+    StepId stepId() {
+        return stepBuilder.id();
     }
 }

src/main/java/io/quarkus/qlue/Execution.java

@@ -1,10 +1,11 @@
 package io.quarkus.qlue;
 
 import static io.quarkus.qlue._private.Messages.log;
-import static java.lang.Math.max;
 import static java.util.concurrent.locks.LockSupport.park;
 import static java.util.concurrent.locks.LockSupport.unpark;
 
+import java.time.Clock;
+import java.time.Instant;
 import java.util.ArrayList;
 import java.util.Collections;
 import java.util.List;
@@ -19,10 +20,12 @@
  */
 final class Execution {
 
+    private final Clock clock;
     private final Chain chain;
     private final ConcurrentHashMap<ItemId, Item> singles;
     private final ConcurrentHashMap<ItemId, List<Item>> multis;
     private final ConcurrentHashMap<StepInfo, StepContext> contextCache = new ConcurrentHashMap<>();
+    private final ConcurrentHashMap<StepId, StepSummary> summaries = new ConcurrentHashMap<>();
     private final Executor executor;
     private final List<Throwable> problems = Collections.synchronizedList(new ArrayList<>());
     private final AtomicBoolean errorReported = new AtomicBoolean();
@@ -31,11 +34,12 @@ final class Execution {
     private volatile boolean done;
 
     Execution(final ExecutionBuilder builder, final Executor executor) {
-        chain = builder.getChain();
-        this.singles = new ConcurrentHashMap<>(builder.getInitialSingle());
-        this.multis = new ConcurrentHashMap<>(builder.getInitialMulti());
+        chain = builder.chain();
+        clock = builder.clock();
+        this.singles = new ConcurrentHashMap<>(builder.initialSingle());
+        this.multis = new ConcurrentHashMap<>(builder.initialMulti());
         this.executor = executor;
-        lastStepCount.set(builder.getChain().getEndStepCount());
+        lastStepCount.set(builder.chain().getEndStepCount());
         if (lastStepCount.get() == 0)
             done = true;
     }
@@ -50,10 +54,16 @@ StepContext getStepContext(StepInfo stepInfo) {
 
     void removeStepContext(StepInfo stepInfo, StepContext stepContext) {
         contextCache.remove(stepInfo, stepContext);
+        summaries.put(stepInfo.id(), stepContext.summary());
+    }
+
+    Chain chain() {
+        return chain;
     }
 
     Result run() {
-        final long start = System.nanoTime();
+        Clock clock = this.clock;
+        final Instant start = clock.instant();
         runningThread = Thread.currentThread();
         // run the operation
         final List<StepInfo> startSteps = chain.getStartSteps();
@@ -78,16 +88,16 @@ Result run() {
             }
             runningThread = null;
         }
+        final Instant end = clock.instant();
         if (errorReported.get()) {
             synchronized (problems) {
-                return new Failure(new ArrayList<>(problems));
+                return new Failure(start, end, new ArrayList<>(problems), summaries);
             }
         }
         if (lastStepCount.get() > 0) {
             throw new IllegalStateException("Extra steps left over");
         }
-        return new Success(singles, multis,
-                max(0, System.nanoTime() - start));
+        return new Success(start, end, singles, multis, summaries);
     }
 
     Executor getExecutor() {
@@ -122,4 +132,8 @@ void depFinished() {
             unpark(runningThread);
         }
     }
+
+    Clock clock() {
+        return clock;
+    }
 }