From 86b9fda5342d8f48b16e1a8e6a710d883caab033 Mon Sep 17 00:00:00 2001 From: Georgios Andrianakis Date: Fri, 26 Jun 2020 11:27:13 +0300 Subject: [PATCH] Add the ability to print the startup time of each build step --- .../recording/BytecodeRecorderImpl.java | 28 +++++++++++++---- .../steps/BootstrapConfigSetupBuildStep.java | 4 +++ .../deployment/steps/MainClassBuildStep.java | 17 ++++++++++- .../steps/RuntimeConfigSetupBuildStep.java | 3 ++ .../io/quarkus/runtime/StartupContext.java | 11 +++++++ .../io/quarkus/runtime/util/StepTiming.java | 30 +++++++++++++++++++ .../src/main/asciidoc/writing-extensions.adoc | 20 +++++++++++++ 7 files changed, 106 insertions(+), 7 deletions(-) create mode 100644 core/runtime/src/main/java/io/quarkus/runtime/util/StepTiming.java diff --git a/core/deployment/src/main/java/io/quarkus/deployment/recording/BytecodeRecorderImpl.java b/core/deployment/src/main/java/io/quarkus/deployment/recording/BytecodeRecorderImpl.java index 956cb7a3584da..771fd095f350c 100644 --- a/core/deployment/src/main/java/io/quarkus/deployment/recording/BytecodeRecorderImpl.java +++ b/core/deployment/src/main/java/io/quarkus/deployment/recording/BytecodeRecorderImpl.java @@ -110,6 +110,9 @@ public class BytecodeRecorderImpl implements RecorderContext { private final Map, NonDefaultConstructorHolder> nonDefaultConstructors = new HashMap<>(); private final String className; + private final String buildStepName; + private final String methodName; + private final List 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 classInstanceVariables = new HashMap<>(); diff --git a/core/deployment/src/main/java/io/quarkus/deployment/steps/BootstrapConfigSetupBuildStep.java b/core/deployment/src/main/java/io/quarkus/deployment/steps/BootstrapConfigSetupBuildStep.java index dcab9e0edecbb..8e4ef126d0a52 100644 --- a/core/deployment/src/main/java/io/quarkus/deployment/steps/BootstrapConfigSetupBuildStep.java +++ b/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 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); } diff --git a/core/deployment/src/main/java/io/quarkus/deployment/steps/MainClassBuildStep.java b/core/deployment/src/main/java/io/quarkus/deployment/steps/MainClassBuildStep.java index 3400b5b1b6fe8..fe2ef6657dc6e 100644 --- a/core/deployment/src/main/java/io/quarkus/deployment/steps/MainClassBuildStep.java +++ b/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 staticInitTasks, List substitutions, @@ -141,6 +150,8 @@ void build(List 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 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 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); } /** diff --git a/core/deployment/src/main/java/io/quarkus/deployment/steps/RuntimeConfigSetupBuildStep.java b/core/deployment/src/main/java/io/quarkus/deployment/steps/RuntimeConfigSetupBuildStep.java index 802e3e670b7f1..3f15d2c250217 100644 --- a/core/deployment/src/main/java/io/quarkus/deployment/steps/RuntimeConfigSetupBuildStep.java +++ b/core/deployment/src/main/java/io/quarkus/deployment/steps/RuntimeConfigSetupBuildStep.java @@ -57,6 +57,9 @@ void setupRuntimeConfig(List 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()) { diff --git a/core/runtime/src/main/java/io/quarkus/runtime/StartupContext.java b/core/runtime/src/main/java/io/quarkus/runtime/StartupContext.java index bae846efad0ae..2414557346ae4 100644 --- a/core/runtime/src/main/java/io/quarkus/runtime/StartupContext.java +++ b/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 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; + } } diff --git a/core/runtime/src/main/java/io/quarkus/runtime/util/StepTiming.java b/core/runtime/src/main/java/io/quarkus/runtime/util/StepTiming.java new file mode 100644 index 0000000000000..7b73ecb03c20a --- /dev/null +++ b/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(); + } +} diff --git a/docs/src/main/asciidoc/writing-extensions.adoc b/docs/src/main/asciidoc/writing-extensions.adoc index 5f00582591b8f..58b33e52d6b57 100755 --- a/docs/src/main/asciidoc/writing-extensions.adoc +++ b/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 ////