From 72ca8039a2e93fecca9f0f29ba15e30510da33c6 Mon Sep 17 00:00:00 2001 From: Martin Kouba Date: Wed, 25 May 2022 08:41:06 +0200 Subject: [PATCH] Quarkus Builder - introduce build metrics - dump the metrics to a JSON file in the build output: A. always in the dev mode B. when a system property is set: -Dquarkus.debug.dump-build-metrics=true - add the list of the build steps to the Dev UI - also add BuildStep#getId() and fix DOT graphviz generator (previously ambiguous build step names were used) --- .../io/quarkus/builder/BuildChainBuilder.java | 8 +- .../java/io/quarkus/builder/BuildContext.java | 14 +- .../java/io/quarkus/builder/BuildResult.java | 12 +- .../java/io/quarkus/builder/BuildStep.java | 9 + .../java/io/quarkus/builder/Execution.java | 17 +- .../quarkus/builder/metrics/BuildMetrics.java | 116 ++++++ .../java/io/quarkus/builder/metrics/Json.java | 364 ++++++++++++++++++ .../quarkus/deployment/ExtensionLoader.java | 20 + .../quarkus/deployment/QuarkusAugmentor.java | 16 +- .../BuildMetricsDevConsoleProcessor.java | 58 +++ .../main/resources/dev-templates/index.html | 15 + .../build-steps.html | 44 +++ 12 files changed, 679 insertions(+), 14 deletions(-) create mode 100644 core/builder/src/main/java/io/quarkus/builder/metrics/BuildMetrics.java create mode 100644 core/builder/src/main/java/io/quarkus/builder/metrics/Json.java create mode 100644 extensions/vertx-http/deployment/src/main/java/io/quarkus/vertx/http/deployment/devmode/BuildMetricsDevConsoleProcessor.java create mode 100644 extensions/vertx-http/deployment/src/main/resources/dev-templates/io.quarkus.quarkus-vertx-http/build-steps.html diff --git a/core/builder/src/main/java/io/quarkus/builder/BuildChainBuilder.java b/core/builder/src/main/java/io/quarkus/builder/BuildChainBuilder.java index 85f0bed07308c..820e66dc3e81a 100644 --- a/core/builder/src/main/java/io/quarkus/builder/BuildChainBuilder.java +++ b/core/builder/src/main/java/io/quarkus/builder/BuildChainBuilder.java @@ -266,7 +266,7 @@ public BuildChain build() throws ChainBuildException { writer.newLine(); writer.write(" { rank = same; "); for (StepInfo startStep : startSteps) { - writer.write(quoteString(startStep.getBuildStep().toString())); + writer.write(quoteString(startStep.getBuildStep().getId())); writer.write("; "); } writer.write("};"); @@ -274,7 +274,7 @@ public BuildChain build() throws ChainBuildException { writer.write(" { rank = same; "); for (StepInfo endStep : endSteps) { if (!startSteps.contains(endStep)) { - writer.write(quoteString(endStep.getBuildStep().toString())); + writer.write(quoteString(endStep.getBuildStep().getId())); writer.write("; "); } } @@ -299,11 +299,11 @@ public BuildChain build() throws ChainBuildException { private static void writeStep(final BufferedWriter writer, final HashSet printed, final StepInfo step) throws IOException { if (printed.add(step)) { - final String currentStepName = quoteString(step.getBuildStep().toString()); + final String currentStepName = quoteString(step.getBuildStep().getId()); final Set dependents = step.getDependents(); if (!dependents.isEmpty()) { for (StepInfo dependent : dependents) { - final String dependentName = quoteString(dependent.getBuildStep().toString()); + final String dependentName = quoteString(dependent.getBuildStep().getId()); writer.write(" "); writer.write(dependentName); writer.write(" -> "); diff --git a/core/builder/src/main/java/io/quarkus/builder/BuildContext.java b/core/builder/src/main/java/io/quarkus/builder/BuildContext.java index 21ac7d2028354..ffaf9aed77937 100644 --- a/core/builder/src/main/java/io/quarkus/builder/BuildContext.java +++ b/core/builder/src/main/java/io/quarkus/builder/BuildContext.java @@ -2,12 +2,14 @@ import static io.quarkus.builder.Execution.*; +import java.time.LocalTime; import java.util.ArrayList; import java.util.Collections; import java.util.Comparator; import java.util.List; import java.util.Set; import java.util.concurrent.Executor; +import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicInteger; import org.wildfly.common.Assert; @@ -266,12 +268,14 @@ void run() { final Execution execution = this.execution; final StepInfo stepInfo = this.stepInfo; final BuildStep buildStep = stepInfo.getBuildStep(); - final long start = System.currentTimeMillis(); + final long start = System.nanoTime(); + final LocalTime started = LocalTime.now(); + final Thread currentThread = Thread.currentThread(); log.tracef("Starting step \"%s\"", buildStep); try { if (!execution.isErrorReported()) { running = true; - ClassLoader old = Thread.currentThread().getContextClassLoader(); + ClassLoader old = currentThread.getContextClassLoader(); try { Thread.currentThread().setContextClassLoader(classLoader); buildStep.execute(this); @@ -281,11 +285,13 @@ void run() { execution.setErrorReported(); } finally { running = false; - Thread.currentThread().setContextClassLoader(old); + currentThread.setContextClassLoader(old); } } } finally { - log.tracef("Finished step \"%s\" in %s ms", buildStep, System.currentTimeMillis() - start); + long duration = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start); + execution.getMetrics().buildStepFinished(buildStep.getId(), currentThread.getName(), started, duration); + log.tracef("Finished step \"%s\" in %s ms", buildStep, duration); execution.removeBuildContext(stepInfo, this); } final Set dependents = stepInfo.getDependents(); diff --git a/core/builder/src/main/java/io/quarkus/builder/BuildResult.java b/core/builder/src/main/java/io/quarkus/builder/BuildResult.java index d97f43a20e845..99930e723002a 100644 --- a/core/builder/src/main/java/io/quarkus/builder/BuildResult.java +++ b/core/builder/src/main/java/io/quarkus/builder/BuildResult.java @@ -11,6 +11,7 @@ import io.quarkus.builder.item.BuildItem; import io.quarkus.builder.item.MultiBuildItem; import io.quarkus.builder.item.SimpleBuildItem; +import io.quarkus.builder.metrics.BuildMetrics; /** * The final result of a successful deployment operation. @@ -22,14 +23,16 @@ public final class BuildResult { private final ConcurrentHashMap> multiItems; private final List diagnostics; private final long nanos; + private final BuildMetrics metrics; BuildResult(final ConcurrentHashMap simpleItems, final ConcurrentHashMap> multiItems, final Set finalIds, - final List diagnostics, final long nanos) { + final List diagnostics, final long nanos, BuildMetrics metrics) { this.simpleItems = simpleItems; this.multiItems = multiItems; this.diagnostics = diagnostics; this.nanos = nanos; + this.metrics = metrics; } /** @@ -102,6 +105,13 @@ public long getDuration(TimeUnit timeUnit) { return timeUnit.convert(nanos, TimeUnit.NANOSECONDS); } + /** + * @return the build metrics + */ + public BuildMetrics getMetrics() { + return metrics; + } + /** * Close all the resultant resources, logging any failures. */ diff --git a/core/builder/src/main/java/io/quarkus/builder/BuildStep.java b/core/builder/src/main/java/io/quarkus/builder/BuildStep.java index b13ec641a4701..49ddb09dc857c 100644 --- a/core/builder/src/main/java/io/quarkus/builder/BuildStep.java +++ b/core/builder/src/main/java/io/quarkus/builder/BuildStep.java @@ -15,6 +15,15 @@ public interface BuildStep { */ void execute(BuildContext context); + /** + * The identifier should be unique for a build chain. + * + * @return the identifier + */ + default String getId() { + return toString(); + } + /** * The empty build step, which immediately succeeds. */ diff --git a/core/builder/src/main/java/io/quarkus/builder/Execution.java b/core/builder/src/main/java/io/quarkus/builder/Execution.java index e89393b444963..b46e91de5dd2d 100644 --- a/core/builder/src/main/java/io/quarkus/builder/Execution.java +++ b/core/builder/src/main/java/io/quarkus/builder/Execution.java @@ -1,7 +1,8 @@ package io.quarkus.builder; import static java.lang.Math.max; -import static java.util.concurrent.locks.LockSupport.*; +import static java.util.concurrent.locks.LockSupport.park; +import static java.util.concurrent.locks.LockSupport.unpark; import java.util.ArrayList; import java.util.Collections; @@ -19,6 +20,7 @@ import io.quarkus.builder.diag.Diagnostic; import io.quarkus.builder.item.BuildItem; +import io.quarkus.builder.metrics.BuildMetrics; /** */ @@ -39,6 +41,8 @@ final class Execution { private volatile Thread runningThread; private volatile boolean done; + private final BuildMetrics metrics; + static { try { Class.forName("org.jboss.threads.EnhancedQueueExecutor$1", false, Execution.class.getClassLoader()); @@ -62,6 +66,8 @@ final class Execution { lastStepCount.set(builder.getChain().getEndStepCount()); if (lastStepCount.get() == 0) done = true; + + metrics = new BuildMetrics(buildTargetName); } List getDiagnostics() { @@ -78,7 +84,9 @@ void removeBuildContext(StepInfo stepInfo, BuildContext buildContext) { BuildResult run() throws BuildException { final long start = System.nanoTime(); + metrics.buildStarted(); runningThread = Thread.currentThread(); + // run the build final List startSteps = chain.getStartSteps(); for (StepInfo startStep : startSteps) { @@ -124,8 +132,9 @@ BuildResult run() throws BuildException { } if (lastStepCount.get() > 0) throw new BuildException("Extra steps left over", Collections.emptyList()); + return new BuildResult(singles, multis, finalIds, Collections.unmodifiableList(diagnostics), - max(0, System.nanoTime() - start)); + max(0, System.nanoTime() - start), metrics); } EnhancedQueueExecutor getExecutor() { @@ -156,6 +165,10 @@ BuildChain getBuildChain() { return chain; } + BuildMetrics getMetrics() { + return metrics; + } + void depFinished() { final int count = lastStepCount.decrementAndGet(); log.tracef("End step completed; %d remaining", count); diff --git a/core/builder/src/main/java/io/quarkus/builder/metrics/BuildMetrics.java b/core/builder/src/main/java/io/quarkus/builder/metrics/BuildMetrics.java new file mode 100644 index 0000000000000..1e4625b452854 --- /dev/null +++ b/core/builder/src/main/java/io/quarkus/builder/metrics/BuildMetrics.java @@ -0,0 +1,116 @@ +package io.quarkus.builder.metrics; + +import java.io.BufferedWriter; +import java.io.FileWriter; +import java.io.IOException; +import java.nio.charset.StandardCharsets; +import java.nio.file.Path; +import java.time.LocalDateTime; +import java.time.LocalTime; +import java.time.format.DateTimeFormatter; +import java.time.temporal.ChronoUnit; +import java.util.ArrayList; +import java.util.Collection; +import java.util.Comparator; +import java.util.List; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.ConcurrentMap; +import java.util.concurrent.atomic.AtomicInteger; + +import org.jboss.logging.Logger; + +import io.quarkus.builder.metrics.Json.JsonArrayBuilder; +import io.quarkus.builder.metrics.Json.JsonObjectBuilder; + +public class BuildMetrics { + + static final Logger LOG = Logger.getLogger(BuildMetrics.class.getName()); + + private volatile LocalDateTime started; + private final String buildTargetName; + private final ConcurrentMap records = new ConcurrentHashMap<>(); + private final AtomicInteger duplicates = new AtomicInteger(); + + public BuildMetrics(String buildTargetName) { + this.buildTargetName = buildTargetName; + } + + public Collection getRecords() { + return records.values(); + } + + public void buildStarted() { + this.started = LocalDateTime.now().truncatedTo(ChronoUnit.MILLIS); + } + + public void buildStepFinished(String stepId, String thread, LocalTime started, long duration) { + BuildStepRecord prev = records.putIfAbsent(stepId, new BuildStepRecord(stepId, thread, started, duration)); + if (prev != null) { + String newName = stepId + "_d#" + duplicates.incrementAndGet(); + LOG.debugf("A build step with the same identifier already exists - added a generated suffix: %s", newName); + buildStepFinished(newName, thread, started, duration); + } + } + + public void dumpTo(Path file) throws IOException { + DateTimeFormatter formatter = DateTimeFormatter.ofPattern("HH:mm:ss.SSS"); + + List sorted = new ArrayList<>(records.values()); + sorted.sort(new Comparator() { + @Override + public int compare(BuildStepRecord o1, BuildStepRecord o2) { + return Long.compare(o2.duration, o1.duration); + } + }); + + JsonObjectBuilder json = Json.object(); + json.put("buildTarget", buildTargetName); + json.put("started", started.format(DateTimeFormatter.ISO_LOCAL_DATE_TIME)); + + JsonArrayBuilder steps = Json.array(); + json.put("steps", steps); + for (BuildStepRecord rec : sorted) { + JsonObjectBuilder recJson = Json.object(); + recJson.put("stepId", rec.stepId); + recJson.put("thread", rec.thread); + recJson.put("started", rec.started.format(formatter)); + recJson.put("duration", rec.duration); + steps.add(recJson); + } + try (BufferedWriter writer = new BufferedWriter(new FileWriter(file.toFile(), StandardCharsets.UTF_8))) { + json.appendTo(writer); + } + } + + public static class BuildStepRecord { + + /** + * The identifier of the build step. + */ + public final String stepId; + + /** + * The name of the thread this build step was executed on. + */ + public final String thread; + + /** + * The time the execution started. + */ + public final LocalTime started; + + /** + * The duration in ms. + */ + public final long duration; + + BuildStepRecord(String stepId, String thread, LocalTime started, long duration) { + this.stepId = stepId; + this.thread = thread; + this.started = started; + this.duration = duration; + } + + } + +} diff --git a/core/builder/src/main/java/io/quarkus/builder/metrics/Json.java b/core/builder/src/main/java/io/quarkus/builder/metrics/Json.java new file mode 100644 index 0000000000000..30f4c75cd613d --- /dev/null +++ b/core/builder/src/main/java/io/quarkus/builder/metrics/Json.java @@ -0,0 +1,364 @@ +package io.quarkus.builder.metrics; + +import java.io.IOException; +import java.util.ArrayList; +import java.util.Collection; +import java.util.HashMap; +import java.util.Iterator; +import java.util.List; +import java.util.ListIterator; +import java.util.Map; +import java.util.Map.Entry; +import java.util.Objects; + +/** + * A simple JSON string generator. + */ +final class Json { + + private static final String OBJECT_START = "{"; + private static final String OBJECT_END = "}"; + private static final String ARRAY_START = "["; + private static final String ARRAY_END = "]"; + private static final String NAME_VAL_SEPARATOR = ":"; + private static final String ENTRY_SEPARATOR = ","; + + private static final int CONTROL_CHAR_START = 0; + private static final int CONTROL_CHAR_END = 0x1f; + private static final char CHAR_QUOTATION_MARK = '"'; + + private static final Map REPLACEMENTS; + + static { + REPLACEMENTS = new HashMap<>(); + // control characters + for (int i = CONTROL_CHAR_START; i <= CONTROL_CHAR_END; i++) { + REPLACEMENTS.put((char) i, String.format("\\u%04x", i)); + } + // quotation mark + REPLACEMENTS.put('"', "\\\""); + // reverse solidus + REPLACEMENTS.put('\\', "\\\\"); + } + + private Json() { + } + + /** + * @return the new JSON array builder, empty builders are not ignored + */ + static JsonArrayBuilder array() { + return new JsonArrayBuilder(false); + } + + /** + * + * @param ignoreEmptyBuilders + * @return the new JSON array builder + * @see JsonBuilder#ignoreEmptyBuilders + */ + static JsonArrayBuilder array(boolean ignoreEmptyBuilders) { + return new JsonArrayBuilder(ignoreEmptyBuilders); + } + + /** + * + * @return the new JSON object builder, empty builders are not ignored + */ + static JsonObjectBuilder object() { + return new JsonObjectBuilder(false); + } + + /** + * + * @param ignoreEmptyBuilders + * @return the new JSON object builder + * @see JsonBuilder#ignoreEmptyBuilders + */ + static JsonObjectBuilder object(boolean ignoreEmptyBuilders) { + return new JsonObjectBuilder(ignoreEmptyBuilders); + } + + abstract static class JsonBuilder { + + protected boolean ignoreEmptyBuilders = false; + + /** + * + * @param ignoreEmptyBuilders If set to true all empty builders added to this builder will be ignored during + * {@link #build()} + */ + JsonBuilder(boolean ignoreEmptyBuilders) { + this.ignoreEmptyBuilders = ignoreEmptyBuilders; + } + + /** + * + * @return true if there are no elements/properties, false otherwise + */ + abstract boolean isEmpty(); + + /** + * + * @return a string representation + * @throws IOException + */ + abstract String build() throws IOException; + + abstract void appendTo(Appendable appendable) throws IOException; + + /** + * + * @param value + * @return true if the value is null or an empty builder and {@link #ignoreEmptyBuilders} is set to + * true, false + * otherwise + */ + protected boolean isIgnored(Object value) { + return value == null || (ignoreEmptyBuilders && value instanceof JsonBuilder && ((JsonBuilder) value).isEmpty()); + } + + protected boolean isValuesEmpty(Collection values) { + if (values.isEmpty()) { + return true; + } + for (Object object : values) { + if (object instanceof JsonBuilder) { + if (!((JsonBuilder) object).isEmpty()) { + return false; + } + } else { + return false; + } + } + return true; + + } + + protected abstract T self(); + + } + + /** + * JSON array builder. + */ + static class JsonArrayBuilder extends JsonBuilder { + + private final List values; + + private JsonArrayBuilder(boolean ignoreEmptyBuilders) { + super(ignoreEmptyBuilders); + this.values = new ArrayList(); + } + + JsonArrayBuilder add(JsonArrayBuilder value) { + addInternal(value); + return this; + } + + JsonArrayBuilder add(JsonObjectBuilder value) { + addInternal(value); + return this; + } + + JsonArrayBuilder add(String value) { + addInternal(value); + return this; + } + + JsonArrayBuilder add(boolean value) { + addInternal(value); + return this; + } + + JsonArrayBuilder add(int value) { + addInternal(value); + return this; + } + + JsonArrayBuilder add(long value) { + addInternal(value); + return this; + } + + JsonArrayBuilder addAll(List value) { + if (value != null && !value.isEmpty()) { + values.addAll(value); + } + return this; + } + + void addInternal(Object value) { + if (value != null) { + values.add(value); + } + } + + boolean isEmpty() { + return isValuesEmpty(values); + } + + String build() throws IOException { + StringBuilder builder = new StringBuilder(); + appendTo(builder); + return builder.toString(); + } + + @Override + void appendTo(Appendable appendable) throws IOException { + appendable.append(ARRAY_START); + int idx = 0; + for (ListIterator iterator = values.listIterator(); iterator.hasNext();) { + Object value = iterator.next(); + if (isIgnored(value)) { + continue; + } + if (++idx > 1) { + appendable.append(ENTRY_SEPARATOR); + } + appendValue(appendable, value); + } + appendable.append(ARRAY_END); + } + + @Override + protected JsonArrayBuilder self() { + return this; + } + + } + + /** + * JSON object builder. + */ + static class JsonObjectBuilder extends JsonBuilder { + + private final Map properties; + + private JsonObjectBuilder(boolean ignoreEmptyBuilders) { + super(ignoreEmptyBuilders); + this.properties = new HashMap(); + } + + JsonObjectBuilder put(String name, String value) { + putInternal(name, value); + return this; + } + + JsonObjectBuilder put(String name, JsonObjectBuilder value) { + putInternal(name, value); + return this; + } + + JsonObjectBuilder put(String name, JsonArrayBuilder value) { + putInternal(name, value); + return this; + } + + JsonObjectBuilder put(String name, boolean value) { + putInternal(name, value); + return this; + } + + JsonObjectBuilder put(String name, int value) { + putInternal(name, value); + return this; + } + + JsonObjectBuilder put(String name, long value) { + putInternal(name, value); + return this; + } + + boolean has(String name) { + return properties.containsKey(name); + } + + void putInternal(String name, Object value) { + Objects.requireNonNull(name); + if (value != null) { + properties.put(name, value); + } + } + + public boolean isEmpty() { + if (properties.isEmpty()) { + return true; + } + return isValuesEmpty(properties.values()); + } + + String build() throws IOException { + StringBuilder builder = new StringBuilder(); + appendTo(builder); + return builder.toString(); + } + + @Override + void appendTo(Appendable appendable) throws IOException { + appendable.append(OBJECT_START); + int idx = 0; + for (Iterator> iterator = properties.entrySet().iterator(); iterator.hasNext();) { + Entry entry = iterator.next(); + if (isIgnored(entry.getValue())) { + continue; + } + if (++idx > 1) { + appendable.append(ENTRY_SEPARATOR); + } + appendStringValue(appendable, entry.getKey()); + appendable.append(NAME_VAL_SEPARATOR); + appendValue(appendable, entry.getValue()); + } + appendable.append(OBJECT_END); + } + + @Override + protected JsonObjectBuilder self() { + return this; + } + + } + + static void appendValue(Appendable appendable, Object value) throws IOException { + if (value instanceof JsonObjectBuilder) { + appendable.append(((JsonObjectBuilder) value).build()); + } else if (value instanceof JsonArrayBuilder) { + appendable.append(((JsonArrayBuilder) value).build()); + } else if (value instanceof String) { + appendStringValue(appendable, value.toString()); + } else if (value instanceof Boolean || value instanceof Integer || value instanceof Long) { + appendable.append(value.toString()); + } else { + throw new IllegalStateException("Unsupported value type: " + value); + } + } + + static void appendStringValue(Appendable appendable, String value) throws IOException { + appendable.append(CHAR_QUOTATION_MARK); + appendable.append(escape(value)); + appendable.append(CHAR_QUOTATION_MARK); + } + + /** + * Escape quotation mark, reverse solidus and control characters (U+0000 through U+001F). + * + * @param value + * @return escaped value + * @see http://www.ietf.org/rfc/rfc4627.txt + */ + static String escape(String value) { + StringBuilder builder = new StringBuilder(); + for (int i = 0; i < value.length(); i++) { + char c = value.charAt(i); + String replacement = REPLACEMENTS.get(c); + if (replacement != null) { + builder.append(replacement); + } else { + builder.append(c); + } + } + return builder.toString(); + } + +} diff --git a/core/deployment/src/main/java/io/quarkus/deployment/ExtensionLoader.java b/core/deployment/src/main/java/io/quarkus/deployment/ExtensionLoader.java index a48946735e4ea..109fbf04823a3 100644 --- a/core/deployment/src/main/java/io/quarkus/deployment/ExtensionLoader.java +++ b/core/deployment/src/main/java/io/quarkus/deployment/ExtensionLoader.java @@ -24,6 +24,7 @@ import java.lang.reflect.ParameterizedType; import java.lang.reflect.Type; import java.util.ArrayList; +import java.util.Arrays; import java.util.Collections; import java.util.EnumSet; import java.util.HashMap; @@ -39,6 +40,7 @@ import java.util.function.Consumer; import java.util.function.Function; import java.util.function.Supplier; +import java.util.stream.Collectors; import javax.inject.Inject; @@ -97,6 +99,7 @@ import io.quarkus.runtime.annotations.Recorder; import io.quarkus.runtime.configuration.ConfigUtils; import io.quarkus.runtime.configuration.QuarkusConfigFactory; +import io.quarkus.runtime.util.HashUtil; import io.smallrye.config.ConfigMappings.ConfigClassWithPrefix; import io.smallrye.config.KeyMap; import io.smallrye.config.KeyMapBackedConfigSource; @@ -526,6 +529,8 @@ private static Consumer loadStepsFromClass(Class clazz, // now iterate the methods final List methods = getMethods(clazz); + final Map> nameToMethods = methods.stream().collect(Collectors.groupingBy(m -> m.getName())); + for (Method method : methods) { final BuildStep buildStep = method.getAnnotation(BuildStep.class); if (buildStep == null) { @@ -879,6 +884,16 @@ private static Consumer loadStepsFromClass(Class clazz, .andThen(buildStepBuilder -> buildStepBuilder.buildIf(finalAddStep)); final BiConsumer finalStepInstanceSetup = stepInstanceSetup; final String name = clazz.getName() + "#" + method.getName(); + final String stepId; + List methodsWithName = nameToMethods.get(method.getName()); + if (methodsWithName.size() > 1) { + // Append the sha1 of the parameter types to resolve the ambiguity + stepId = name + "_" + HashUtil.sha1(Arrays.toString(method.getParameterTypes())); + loadLog.debugf("Build steps with ambiguous name detected: %s, using discriminator suffix for step id: %s", name, + stepId); + } else { + stepId = name; + } chainConfig = chainConfig .andThen(bcb -> { @@ -965,6 +980,11 @@ public void execute(final BuildContext bc) { } } + @Override + public String getId() { + return stepId; + } + public String toString() { return name; } diff --git a/core/deployment/src/main/java/io/quarkus/deployment/QuarkusAugmentor.java b/core/deployment/src/main/java/io/quarkus/deployment/QuarkusAugmentor.java index 9cbaa6e1f4945..297edb0caa9a6 100644 --- a/core/deployment/src/main/java/io/quarkus/deployment/QuarkusAugmentor.java +++ b/core/deployment/src/main/java/io/quarkus/deployment/QuarkusAugmentor.java @@ -10,6 +10,7 @@ import java.util.Optional; import java.util.Properties; import java.util.Set; +import java.util.concurrent.TimeUnit; import java.util.function.Consumer; import org.eclipse.microprofile.config.spi.ConfigProviderResolver; @@ -86,7 +87,7 @@ public BuildResult run() throws Exception { if (!JavaVersionUtil.isJava11OrHigher()) { throw new IllegalStateException("Quarkus applications require Java 11 or higher to build"); } - long time = System.currentTimeMillis(); + long start = System.nanoTime(); log.debug("Beginning Quarkus augmentation"); ClassLoader originalClassLoader = Thread.currentThread().getContextClassLoader(); QuarkusBuildCloseablesBuildItem buildCloseables = new QuarkusBuildCloseablesBuildItem(); @@ -137,7 +138,7 @@ public BuildResult run() throws Exception { rootBuilder.setExcludedFromIndexing(excludedFromIndexing); BuildChain chain = chainBuilder.build(); - BuildExecutionBuilder execBuilder = chain.createExecutionBuilder("main") + BuildExecutionBuilder execBuilder = chain.createExecutionBuilder(baseName) .produce(buildCloseables) .produce(liveReloadBuildItem) .produce(rootBuilder.build(buildCloseables)) @@ -155,12 +156,21 @@ public BuildResult run() throws Exception { execBuilder.produce(new AdditionalApplicationArchiveBuildItem(i)); } BuildResult buildResult = execBuilder.execute(); - String message = "Quarkus augmentation completed in " + (System.currentTimeMillis() - time) + "ms"; + String message = "Quarkus augmentation completed in " + TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start) + + "ms"; if (launchMode == LaunchMode.NORMAL) { log.info(message); + if (Boolean.parseBoolean(System.getProperty("quarkus.debug.dump-build-metrics"))) { + buildResult.getMetrics().dumpTo(targetDir.resolve("build-metrics.json")); + } } else { //test and dev mode already report the total startup time, no need to add noise to the logs log.debug(message); + + // Always dump the metrics in the dev mode + if (launchMode == LaunchMode.DEVELOPMENT) { + buildResult.getMetrics().dumpTo(targetDir.resolve("build-metrics.json")); + } } return buildResult; } finally { diff --git a/extensions/vertx-http/deployment/src/main/java/io/quarkus/vertx/http/deployment/devmode/BuildMetricsDevConsoleProcessor.java b/extensions/vertx-http/deployment/src/main/java/io/quarkus/vertx/http/deployment/devmode/BuildMetricsDevConsoleProcessor.java new file mode 100644 index 0000000000000..b6679b2c16a8e --- /dev/null +++ b/extensions/vertx-http/deployment/src/main/java/io/quarkus/vertx/http/deployment/devmode/BuildMetricsDevConsoleProcessor.java @@ -0,0 +1,58 @@ +package io.quarkus.vertx.http.deployment.devmode; + +import java.io.IOException; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.HashMap; +import java.util.HashSet; +import java.util.Map; +import java.util.Set; +import java.util.function.Supplier; + +import org.jboss.logging.Logger; + +import io.quarkus.arc.impl.LazyValue; +import io.quarkus.deployment.IsDevelopment; +import io.quarkus.deployment.annotations.BuildStep; +import io.quarkus.deployment.pkg.builditem.BuildSystemTargetBuildItem; +import io.quarkus.devconsole.spi.DevConsoleTemplateInfoBuildItem; +import io.vertx.core.json.JsonObject; + +public class BuildMetricsDevConsoleProcessor { + + private static final Logger LOG = Logger.getLogger(BuildMetricsDevConsoleProcessor.class.getName()); + + @BuildStep(onlyIf = IsDevelopment.class) + DevConsoleTemplateInfoBuildItem collectMetrics(BuildSystemTargetBuildItem buildSystemTarget) { + + // We need to read the data lazily because the build is not finished yet at the time this build item is produced + return new DevConsoleTemplateInfoBuildItem("buildMetrics", + new LazyValue>(new Supplier>() { + + @Override + public Map get() { + Map metrics = new HashMap<>(); + + Path metricsJsonFile = buildSystemTarget.getOutputDirectory().resolve("build-metrics.json"); + if (Files.isReadable(metricsJsonFile)) { + try { + JsonObject data = new JsonObject(Files.readString(metricsJsonFile)); + metrics.put("steps", data.getValue("steps")); + + Set threads = new HashSet<>(); + for (Object step : data.getJsonArray("steps")) { + threads.add(((JsonObject) step).getString("thread")); + } + metrics.put("threads", threads); + + } catch (IOException e) { + LOG.error(e); + } + } + return metrics; + } + })); + + } + +} diff --git a/extensions/vertx-http/deployment/src/main/resources/dev-templates/index.html b/extensions/vertx-http/deployment/src/main/resources/dev-templates/index.html index 4debd03720629..6fe4bd44f99a8 100644 --- a/extensions/vertx-http/deployment/src/main/resources/dev-templates/index.html +++ b/extensions/vertx-http/deployment/src/main/resources/dev-templates/index.html @@ -3,6 +3,21 @@ {#body}
+
+
+
+ Build +
+
+

+ + + Build Steps + +

+
+
+
diff --git a/extensions/vertx-http/deployment/src/main/resources/dev-templates/io.quarkus.quarkus-vertx-http/build-steps.html b/extensions/vertx-http/deployment/src/main/resources/dev-templates/io.quarkus.quarkus-vertx-http/build-steps.html new file mode 100644 index 0000000000000..d705d699d9661 --- /dev/null +++ b/extensions/vertx-http/deployment/src/main/resources/dev-templates/io.quarkus.quarkus-vertx-http/build-steps.html @@ -0,0 +1,44 @@ +{#include main fluid=true} +{#title}Build Steps{/title} +{#body} + +{#let metrics=info:buildMetrics.get} + +

+Executed {metrics.steps.size} build steps on {metrics.threads.size} threads. +

+ + + + + + + + + + + + + {#for step in metrics.steps} + + + + + + + {/for} + +
#Build StepStartedDurationThread
{step_count} + {step.stepId} + + {step.started} + + {step.duration} ms + + {step.thread} +
+ +{/let} + +{/body} +{/include} \ No newline at end of file