Merge pull request #10294 from geoand/build-step-startup-times

Add the ability to print the startup time of each build step

core/deployment/src/main/java/io/quarkus/deployment/recording/BytecodeRecorderImpl.java

@@ -110,6 +110,9 @@ public class BytecodeRecorderImpl implements RecorderContext {
     private final Map<Class<?>, NonDefaultConstructorHolder> nonDefaultConstructors = new HashMap<>();
     private final String className;
 
+    private final String buildStepName;
+    private final String methodName;
+
     private final List<ObjectLoader> loaders = new ArrayList<>();
 
     /**
@@ -124,15 +127,23 @@ public class BytecodeRecorderImpl implements RecorderContext {
     private int deferredParameterCount = 0;
     private boolean loadComplete;
 
-    public BytecodeRecorderImpl(ClassLoader classLoader, boolean staticInit, String className) {
+    public BytecodeRecorderImpl(boolean staticInit, String buildStepName, String methodName, String uniqueHash) {
+        this(Thread.currentThread().getContextClassLoader(), staticInit,
+                BASE_PACKAGE + buildStepName + "$" + methodName + uniqueHash, buildStepName, methodName);
+    }
+
+    // visible for testing
+    BytecodeRecorderImpl(ClassLoader classLoader, boolean staticInit, String className) {
+        this(classLoader, staticInit, className, null, null);
+    }
+
+    private BytecodeRecorderImpl(ClassLoader classLoader, boolean staticInit, String className, String buildStepName,
+            String methodName) {
         this.classLoader = classLoader;
         this.staticInit = staticInit;
         this.className = className;
-    }
-
-    public BytecodeRecorderImpl(boolean staticInit, String buildStepName, String methodName, String uniqueHash) {
-        this(Thread.currentThread().getContextClassLoader(), staticInit,
-                BASE_PACKAGE + buildStepName + "$" + methodName + uniqueHash);
+        this.buildStepName = buildStepName;
+        this.methodName = methodName;
     }
 
     public boolean isEmpty() {
@@ -342,6 +353,11 @@ public void writeBytecode(ClassOutput classOutput) {
                 .className(className)
                 .superClass(Object.class).interfaces(StartupTask.class).build();
         MethodCreator mainMethod = file.getMethodCreator("deploy", void.class, StartupContext.class);
+
+        // record the build step name
+        mainMethod.invokeVirtualMethod(ofMethod(StartupContext.class, "setCurrentBuildStepName", void.class, String.class),
+                mainMethod.getMethodParam(0), mainMethod.load(buildStepName + "." + methodName));
+
         //now create instances of all the classes we invoke on and store them in variables as well
         Map<Class, DeferredArrayStoreParameter> classInstanceVariables = new HashMap<>();
 

core/deployment/src/main/java/io/quarkus/deployment/steps/BootstrapConfigSetupBuildStep.java

@@ -1,6 +1,7 @@
 package io.quarkus.deployment.steps;
 
 import static io.quarkus.deployment.configuration.RunTimeConfigurationGenerator.C_CREATE_BOOTSTRAP_CONFIG;
+import static io.quarkus.gizmo.MethodDescriptor.ofMethod;
 
 import io.quarkus.deployment.GeneratedClassGizmoAdaptor;
 import io.quarkus.deployment.annotations.BuildProducer;
@@ -34,6 +35,9 @@ void setupBootstrapConfig(BuildProducer<GeneratedClassBuildItem> generatedClass,
                 .interfaces(StartupTask.class).build()) {
 
             try (MethodCreator deploy = clazz.getMethodCreator("deploy", void.class, StartupContext.class)) {
+                deploy.invokeVirtualMethod(ofMethod(StartupContext.class, "setCurrentBuildStepName", void.class, String.class),
+                        deploy.getMethodParam(0), deploy.load("BootstrapConfigSetupBuildStep.setupBootstrapConfig"));
+
                 deploy.invokeStaticMethod(C_CREATE_BOOTSTRAP_CONFIG);
                 deploy.returnValue(null);
             }

core/deployment/src/main/java/io/quarkus/deployment/steps/MainClassBuildStep.java

@@ -75,6 +75,7 @@
 import io.quarkus.runtime.annotations.QuarkusMain;
 import io.quarkus.runtime.appcds.AppCDSUtil;
 import io.quarkus.runtime.configuration.ProfileManager;
+import io.quarkus.runtime.util.StepTiming;
 
 public class MainClassBuildStep {
 
@@ -93,10 +94,18 @@ public class MainClassBuildStep {
             JAVAX_NET_SSL_TRUST_STORE_PASSWORD));
 
     public static final String GENERATE_APP_CDS_SYSTEM_PROPERTY = "quarkus.appcds.generate";
+    public static final String PRINT_STARTUP_TIMES_PROPERTY = "quarkus.debug.print-startup-times";
 
     private static final FieldDescriptor STARTUP_CONTEXT_FIELD = FieldDescriptor.of(Application.APP_CLASS_NAME, STARTUP_CONTEXT,
             StartupContext.class);
 
+    public static final MethodDescriptor PRINT_STEP_TIME_METHOD = ofMethod(StepTiming.class.getName(), "printStepTime",
+            void.class, StartupContext.class);
+    public static final MethodDescriptor CONFIGURE_STEP_TIME_ENABLED = ofMethod(StepTiming.class.getName(), "configureEnabled",
+            void.class);
+    public static final MethodDescriptor CONFIGURE_STEP_TIME_START = ofMethod(StepTiming.class.getName(), "configureStart",
+            void.class);
+
     @BuildStep
     void build(List<StaticBytecodeRecorderBuildItem> staticInitTasks,
             List<ObjectSubstitutionBuildItem> substitutions,
@@ -141,6 +150,8 @@ void build(List<StaticBytecodeRecorderBuildItem> staticInitTasks,
         mv.invokeStaticMethod(MethodDescriptor.ofMethod(ProfileManager.class, "setLaunchMode", void.class, LaunchMode.class),
                 lm);
 
+        mv.invokeStaticMethod(CONFIGURE_STEP_TIME_ENABLED);
+
         mv.invokeStaticMethod(MethodDescriptor.ofMethod(Timing.class, "staticInitStarted", void.class));
 
         // ensure that the config class is initialized
@@ -155,6 +166,7 @@ void build(List<StaticBytecodeRecorderBuildItem> staticInitTasks,
         ResultHandle startupContext = mv.newInstance(ofConstructor(StartupContext.class));
         mv.writeStaticField(scField.getFieldDescriptor(), startupContext);
         TryBlock tryBlock = mv.tryBlock();
+        tryBlock.invokeStaticMethod(CONFIGURE_STEP_TIME_START);
         for (StaticBytecodeRecorderBuildItem holder : staticInitTasks) {
             writeRecordedBytecode(holder.getBytecodeRecorder(), null, substitutions, loaders, gizmoOutput, startupContext,
                     tryBlock);
@@ -243,8 +255,10 @@ void build(List<StaticBytecodeRecorderBuildItem> staticInitTasks,
                 MethodDescriptor.ofMethod(StartupContext.class, "setCommandLineArguments", void.class, String[].class),
                 startupContext, mv.getMethodParam(0));
 
-        tryBlock = mv.tryBlock();
+        mv.invokeStaticMethod(CONFIGURE_STEP_TIME_ENABLED);
 
+        tryBlock = mv.tryBlock();
+        tryBlock.invokeStaticMethod(CONFIGURE_STEP_TIME_START);
         for (MainBytecodeRecorderBuildItem holder : mainMethod) {
             writeRecordedBytecode(holder.getBytecodeRecorder(), holder.getGeneratedStartupContextClassName(), substitutions,
                     loaders, gizmoOutput, startupContext, tryBlock);
@@ -431,6 +445,7 @@ private void writeRecordedBytecode(BytecodeRecorderImpl recorder, String fallbac
                 .newInstance(ofConstructor(recorder != null ? recorder.getClassName() : fallbackGeneratedStartupTaskClassName));
         bytecodeCreator.invokeInterfaceMethod(ofMethod(StartupTask.class, "deploy", void.class, StartupContext.class), dup,
                 startupContext);
+        bytecodeCreator.invokeStaticMethod(PRINT_STEP_TIME_METHOD, startupContext);
     }
 
     /**

core/deployment/src/main/java/io/quarkus/deployment/steps/RuntimeConfigSetupBuildStep.java

@@ -57,6 +57,9 @@ void setupRuntimeConfig(List<RunTimeConfigurationSourceValueBuildItem> runTimeCo
                 .interfaces(StartupTask.class).build()) {
 
             try (MethodCreator method = clazz.getMethodCreator("deploy", void.class, StartupContext.class)) {
+                method.invokeVirtualMethod(ofMethod(StartupContext.class, "setCurrentBuildStepName", void.class, String.class),
+                        method.getMethodParam(0), method.load("RuntimeConfigSetupBuildStep.setupRuntimeConfig"));
+
                 ResultHandle config = method.readStaticField(C_INSTANCE);
 
                 if (runTimeConfigurationSourceValues.isEmpty()) {

core/runtime/src/main/java/io/quarkus/runtime/StartupContext.java

@@ -34,6 +34,7 @@ public void addLastShutdownTask(Runnable runnable) {
         }
     };
     private String[] commandLineArgs;
+    private String currentBuildStepName;
 
     public StartupContext() {
         values.put(ShutdownContext.class.getName(), shutdownContext);
@@ -90,4 +91,14 @@ private void runAllInReverseOrder(List<Runnable> tasks) {
     public void setCommandLineArguments(String[] commandLineArguments) {
         this.commandLineArgs = commandLineArguments;
     }
+
+    @SuppressWarnings("unused")
+    public String getCurrentBuildStepName() {
+        return currentBuildStepName;
+    }
+
+    @SuppressWarnings("unused")
+    public void setCurrentBuildStepName(String currentBuildStepName) {
+        this.currentBuildStepName = currentBuildStepName;
+    }
 }

core/runtime/src/main/java/io/quarkus/runtime/util/StepTiming.java

@@ -0,0 +1,30 @@
+package io.quarkus.runtime.util;
+
+import io.quarkus.runtime.StartupContext;
+
+public class StepTiming {
+
+    public static final String PRINT_STARTUP_TIMES = "quarkus.debug.print-startup-times";
+
+    private static boolean stepTimingEnabled;
+    private static long stepTimingStart;
+
+    public static void configureEnabled() {
+        stepTimingEnabled = System.getProperty(PRINT_STARTUP_TIMES, "false").equalsIgnoreCase("true");
+    }
+
+    public static void configureStart() {
+        stepTimingStart = System.currentTimeMillis();
+    }
+
+    public static void printStepTime(StartupContext startupContext) {
+        if (!stepTimingEnabled) {
+            return;
+        }
+        long stepTimingStop = System.currentTimeMillis();
+        String currentBuildStepName = startupContext.getCurrentBuildStepName();
+        System.out
+                .println("Build step " + currentBuildStepName + " completed in: " + (stepTimingStop - stepTimingStart) + "ms");
+        stepTimingStart = System.currentTimeMillis();
+    }
+}

docs/src/main/asciidoc/writing-extensions.adoc

@@ -1302,6 +1302,26 @@ Calling `classProxy` with a given class name will create a `Class` that can be p
 methods, and at runtime will be substituted with the class whose name was passed in to `classProxy`. This is basically a
 convenience to avoid the need to explicitly load classes in the recorders.
 
+==== Printing step execution time
+
+At times, it can be useful to know how the exact time each startup task (which is the result of each bytecode recording) takes when the application is run.
+The simplest way to determine this information is to set the `quarkus.debug.print-startup-times` property to `true` when running the application.
+The output will look something like:
+
+[source%nowrap]
+----
+Build step LoggingResourceProcessor.setupLoggingRuntimeInit completed in: 42ms
+Build step ConfigGenerationBuildStep.checkForBuildTimeConfigChange completed in: 4ms
+Build step SyntheticBeansProcessor.initRuntime completed in: 0ms
+Build step ConfigBuildStep.validateConfigProperties completed in: 1ms
+Build step ResteasyStandaloneBuildStep.boot completed in: 95ms
+Build step VertxHttpProcessor.initializeRouter completed in: 1ms
+Build step VertxHttpProcessor.finalizeRouter completed in: 4ms
+Build step LifecycleEventsBuildStep.startupEvent completed in: 1ms
+Build step VertxHttpProcessor.openSocket completed in: 93ms
+Build step ShutdownListenerBuildStep.setupShutdown completed in: 1ms
+----
+
 ////
 TODO: config integration
 ////