Skip to content

Commit

Permalink
Add the ability to print the startup time of each build step - v2
Browse files Browse the repository at this point in the history
  • Loading branch information
@geoand
geoand committed Jul 3, 2020
1 parent cf4abc5 commit b64f4f1
Show file tree
Hide file tree
Showing 5 changed files with 120 additions and 54 deletions.
56 changes: 3 additions & 53 deletions core/deployment/src/main/java/io/quarkus/deployment/recording/BytecodeRecorderImpl.java
View file
Expand Up @@ -4,7 +4,6 @@
import static io.quarkus.gizmo.MethodDescriptor.ofMethod;

import java.io.Closeable;
import java.io.PrintStream;
import java.lang.reflect.Array;
import java.lang.reflect.Constructor;
import java.lang.reflect.Field;
Expand Down Expand Up @@ -85,9 +84,6 @@
*/
public class BytecodeRecorderImpl implements RecorderContext {

// TODO: perhaps move this somewhere else, like Timing? Also, what about the name?
public static final String PRINT_STARTUP_TIMES_PROPERTY = "quarkus.debug.print-startup-times";

private static final Class<?> SINGLETON_LIST_CLASS = Collections.singletonList(1).getClass();
private static final Class<?> SINGLETON_SET_CLASS = Collections.singleton(1).getClass();
private static final Class<?> SINGLETON_MAP_CLASS = Collections.singletonMap(1, 1).getClass();
Expand All @@ -99,9 +95,6 @@ public class BytecodeRecorderImpl implements RecorderContext {

private static final MethodDescriptor COLLECTION_ADD = ofMethod(Collection.class, "add", boolean.class, Object.class);
private static final MethodDescriptor MAP_PUT = ofMethod(Map.class, "put", Object.class, Object.class, Object.class);
private static final MethodDescriptor MILLIS_TIME = ofMethod(System.class, "currentTimeMillis", long.class);
private static final MethodDescriptor STRING_BUILDER_APPEND = ofMethod(StringBuilder.class, "append", StringBuilder.class,
String.class);

private final boolean staticInit;
private final ClassLoader classLoader;
Expand Down Expand Up @@ -361,10 +354,9 @@ public void writeBytecode(ClassOutput classOutput) {
.superClass(Object.class).interfaces(StartupTask.class).build();
MethodCreator mainMethod = file.getMethodCreator("deploy", void.class, StartupContext.class);

ResultHandle startTime = null;
if (executionTimePrintEnabled()) {
startTime = mainMethod.invokeStaticMethod(MILLIS_TIME);
}
// 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<>();
Expand Down Expand Up @@ -494,53 +486,11 @@ public void write(MethodContext context, MethodCreator method, ResultHandle arra

}
context.close();

generationPrintExecutionTime(mainMethod, startTime);

mainMethod.returnValue(null);
file.close();

}

// don't bother writing the bytecode that prints the execution time if the proper system property is not set
// TODO: do we want this?
private boolean executionTimePrintEnabled() {
return Boolean.parseBoolean(System.getProperty(PRINT_STARTUP_TIMES_PROPERTY, "false"));
}

private void generationPrintExecutionTime(MethodCreator mainMethod, ResultHandle startTime) {
if ((buildStepName == null) || (methodName == null) || !executionTimePrintEnabled()) {
return;
}

// check if the property was enabled at runtime as well
// TODO: do we want this? Currently one needs to set the property both when building and running the application
ResultHandle timingEnabledProp = mainMethod.invokeStaticMethod(
ofMethod(System.class, "getProperty", String.class, String.class, String.class),
mainMethod.load(PRINT_STARTUP_TIMES_PROPERTY), mainMethod.load("true"));
ResultHandle timingEnabledPropBool = mainMethod.invokeStaticMethod(
ofMethod(Boolean.class, "parseBoolean", boolean.class, String.class), timingEnabledProp);
BytecodeCreator timingEnabled = mainMethod.ifTrue(timingEnabledPropBool).trueBranch();

ResultHandle stopTime = timingEnabled.invokeStaticMethod(MILLIS_TIME);
ResultHandle builder = timingEnabled.newInstance(ofConstructor(StringBuilder.class, String.class),
timingEnabled.load("Build step "));
timingEnabled.invokeVirtualMethod(STRING_BUILDER_APPEND, builder, timingEnabled.load(buildStepName));
timingEnabled.invokeVirtualMethod(STRING_BUILDER_APPEND, builder, timingEnabled.load("."));
timingEnabled.invokeVirtualMethod(STRING_BUILDER_APPEND, builder, timingEnabled.load(methodName));
timingEnabled.invokeVirtualMethod(STRING_BUILDER_APPEND, builder, timingEnabled.load("completed in: "));
timingEnabled.invokeVirtualMethod(STRING_BUILDER_APPEND, builder,
timingEnabled.invokeStaticMethod(ofMethod(String.class, "valueOf", String.class, long.class),
timingEnabled.invokeStaticMethod(
ofMethod(Math.class, "subtractExact", long.class, long.class, long.class),
stopTime,
startTime)));
timingEnabled.invokeVirtualMethod(STRING_BUILDER_APPEND, builder, timingEnabled.load("ms"));
ResultHandle out = timingEnabled.readStaticField(FieldDescriptor.of(System.class, "out", PrintStream.class));
timingEnabled.invokeVirtualMethod(ofMethod(PrintStream.class, "println", void.class, String.class), out,
timingEnabled.invokeVirtualMethod(ofMethod(StringBuilder.class, "toString", String.class), builder));
}

/**
* Returns a representation of a serialized parameter.
*/
Expand Down
4 changes: 4 additions & 0 deletions core/deployment/src/main/java/io/quarkus/deployment/steps/BootstrapConfigSetupBuildStep.java
View file
@@ -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;
Expand Down Expand Up @@ -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);
}
Expand Down
100 changes: 99 additions & 1 deletion core/deployment/src/main/java/io/quarkus/deployment/steps/MainClassBuildStep.java
View file
Expand Up @@ -4,6 +4,7 @@
import static io.quarkus.gizmo.MethodDescriptor.ofMethod;

import java.io.File;
import java.io.PrintStream;
import java.lang.reflect.Modifier;
import java.util.ArrayList;
import java.util.Arrays;
Expand Down Expand Up @@ -93,10 +94,23 @@ 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(Application.APP_CLASS_NAME, "printStepTime",
void.class);
private static final FieldDescriptor STEP_TIMING_ENABLED_FIELD = FieldDescriptor.of(Application.APP_CLASS_NAME,
"stepTimingEnabled",
boolean.class);
private static final FieldDescriptor STEP_TIMING_START_FIELD = FieldDescriptor.of(Application.APP_CLASS_NAME,
"stepTimingStart",
long.class);
private static final MethodDescriptor MILLIS_TIME = ofMethod(System.class, "currentTimeMillis", long.class);
private static final MethodDescriptor STRING_BUILDER_APPEND = ofMethod(StringBuilder.class, "append", StringBuilder.class,
String.class);

@BuildStep
void build(List<StaticBytecodeRecorderBuildItem> staticInitTasks,
List<ObjectSubstitutionBuildItem> substitutions,
Expand Down Expand Up @@ -127,6 +141,12 @@ void build(List<StaticBytecodeRecorderBuildItem> staticInitTasks,
FieldCreator scField = file.getFieldCreator(STARTUP_CONTEXT_FIELD);
scField.setModifiers(Modifier.PUBLIC | Modifier.STATIC);

// create step timing related fields
file.getFieldCreator(STEP_TIMING_ENABLED_FIELD).setModifiers(Modifier.STATIC | Modifier.PRIVATE);
file.getFieldCreator(STEP_TIMING_START_FIELD).setModifiers(Modifier.STATIC | Modifier.PRIVATE);

generationPrintStepTimeMethod(file);

MethodCreator mv = file.getMethodCreator("<clinit>", void.class);
mv.setModifiers(Modifier.PUBLIC | Modifier.STATIC);

Expand All @@ -141,6 +161,8 @@ void build(List<StaticBytecodeRecorderBuildItem> staticInitTasks,
mv.invokeStaticMethod(MethodDescriptor.ofMethod(ProfileManager.class, "setLaunchMode", void.class, LaunchMode.class),
lm);

setStepTimingField(mv);

mv.invokeStaticMethod(MethodDescriptor.ofMethod(Timing.class, "staticInitStarted", void.class));

// ensure that the config class is initialized
Expand All @@ -155,6 +177,7 @@ void build(List<StaticBytecodeRecorderBuildItem> staticInitTasks,
ResultHandle startupContext = mv.newInstance(ofConstructor(StartupContext.class));
mv.writeStaticField(scField.getFieldDescriptor(), startupContext);
TryBlock tryBlock = mv.tryBlock();
tryBlock.writeStaticField(STEP_TIMING_START_FIELD, tryBlock.invokeStaticMethod(MILLIS_TIME));
for (StaticBytecodeRecorderBuildItem holder : staticInitTasks) {
writeRecordedBytecode(holder.getBytecodeRecorder(), null, substitutions, loaders, gizmoOutput, startupContext,
tryBlock);
Expand Down Expand Up @@ -243,8 +266,10 @@ void build(List<StaticBytecodeRecorderBuildItem> staticInitTasks,
MethodDescriptor.ofMethod(StartupContext.class, "setCommandLineArguments", void.class, String[].class),
startupContext, mv.getMethodParam(0));

tryBlock = mv.tryBlock();
setStepTimingField(mv);

tryBlock = mv.tryBlock();
tryBlock.writeStaticField(STEP_TIMING_START_FIELD, tryBlock.invokeStaticMethod(MILLIS_TIME));
for (MainBytecodeRecorderBuildItem holder : mainMethod) {
writeRecordedBytecode(holder.getBytecodeRecorder(), holder.getGeneratedStartupContextClassName(), substitutions,
loaders, gizmoOutput, startupContext, tryBlock);
Expand Down Expand Up @@ -308,6 +333,78 @@ void build(List<StaticBytecodeRecorderBuildItem> staticInitTasks,
file.close();
}

/**
* Step timing is enabled only if 'quarkus.debug.print-startup-times' is set.
* This method should be called both in static init and runtime init in order to
* make sure that the system properly works properly in native mode
*/
private void setStepTimingField(MethodCreator mv) {
ResultHandle timingEnabledProp = mv.invokeStaticMethod(
ofMethod(System.class, "getProperty", String.class, String.class, String.class),
mv.load(MainClassBuildStep.PRINT_STARTUP_TIMES_PROPERTY), mv.load("false"));
mv.writeStaticField(STEP_TIMING_ENABLED_FIELD, mv.invokeStaticMethod(
ofMethod(Boolean.class, "parseBoolean", boolean.class, String.class), timingEnabledProp));
}

/**
* Generated bytecode like the following:
*
* <pre>
*
* private static void printStepTime() {
* if (stepTimingEnabled) {
* long var2 = System.currentTimeMillis();
* String var0 = STARTUP_CONTEXT.getCurrentBuildStepName();
* StringBuilder var1 = new StringBuilder("Build step ");
* var1.append(var0);
* var1.append(" completed in: ");
* long var4 = stepTimingStart;
* String var6 = String.valueOf(Math.subtractExact(var2, var4));
* var1.append(var6);
* var1.append("ms");
* PrintStream var7 = System.out;
* String var8 = var1.toString();
* var7.println(var8);
* stepTimingStart = System.currentTimeMillis();
* }
* }
*
* This is used to print the time it took for a build step to execute. The first invocation of this method
* assumes that the static {@code stepTimingStart} field has been set.
*
* After printing the time, it also resets {@code stepTimingStart} because steps are executed one after the other.
*
* </pre>
*/
private void generationPrintStepTimeMethod(ClassCreator file) {
MethodCreator mc = file.getMethodCreator(PRINT_STEP_TIME_METHOD).setModifiers(Modifier.STATIC | Modifier.PRIVATE);
ResultHandle resultHandle = mc.readStaticField(STEP_TIMING_ENABLED_FIELD);
BytecodeCreator timingEnabled = mc.ifTrue(resultHandle).trueBranch();

ResultHandle stopTime = timingEnabled.invokeStaticMethod(MILLIS_TIME);
ResultHandle buildStepName = timingEnabled.invokeVirtualMethod(
ofMethod(StartupContext.class, "getCurrentBuildStepName", String.class),
timingEnabled.readStaticField(STARTUP_CONTEXT_FIELD));
ResultHandle builder = timingEnabled.newInstance(ofConstructor(StringBuilder.class, String.class),
timingEnabled.load("Build step "));
timingEnabled.invokeVirtualMethod(STRING_BUILDER_APPEND, builder, buildStepName);
timingEnabled.invokeVirtualMethod(STRING_BUILDER_APPEND, builder, timingEnabled.load(" completed in: "));
timingEnabled.invokeVirtualMethod(STRING_BUILDER_APPEND, builder,
timingEnabled.invokeStaticMethod(ofMethod(String.class, "valueOf", String.class, long.class),
timingEnabled.invokeStaticMethod(
ofMethod(Math.class, "subtractExact", long.class, long.class, long.class),
stopTime,
timingEnabled.readStaticField(STEP_TIMING_START_FIELD))));
timingEnabled.invokeVirtualMethod(STRING_BUILDER_APPEND, builder, timingEnabled.load("ms"));
ResultHandle out = timingEnabled.readStaticField(FieldDescriptor.of(System.class, "out", PrintStream.class));
timingEnabled.invokeVirtualMethod(ofMethod(PrintStream.class, "println", void.class, String.class), out,
timingEnabled.invokeVirtualMethod(ofMethod(StringBuilder.class, "toString", String.class), builder));

// record the start time which will be used to compute the startup time of the next build step
timingEnabled.writeStaticField(STEP_TIMING_START_FIELD, timingEnabled.invokeStaticMethod(MILLIS_TIME));
mc.returnValue(null);
}

@BuildStep
public MainClassBuildItem mainClassBuildStep(BuildProducer<GeneratedClassBuildItem> generatedClass,
ApplicationArchivesBuildItem applicationArchivesBuildItem,
Expand Down Expand Up @@ -431,6 +528,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);
}

/**
Expand Down
3 changes: 3 additions & 0 deletions core/deployment/src/main/java/io/quarkus/deployment/steps/RuntimeConfigSetupBuildStep.java
View file
Expand Up @@ -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()) {
Expand Down
11 changes: 11 additions & 0 deletions core/runtime/src/main/java/io/quarkus/runtime/StartupContext.java
View file
Expand Up @@ -34,6 +34,7 @@ public void addLastShutdownTask(Runnable runnable) {
}
};
private String[] commandLineArgs;
private String currentBuildStepName;

public StartupContext() {
values.put(ShutdownContext.class.getName(), shutdownContext);
Expand Down Expand Up @@ -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;
}
}

0 comments on commit b64f4f1

Please sign in to comment.