From 116940b53aad2dd6cb4e348f4762c3fc221923d0 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
---
.../java/io/quarkus/builder/BuildContext.java | 14 +-
.../java/io/quarkus/builder/BuildResult.java | 12 +-
.../java/io/quarkus/builder/Execution.java | 17 +-
.../quarkus/builder/report/BuildMetrics.java | 116 ++++++
.../java/io/quarkus/builder/report/Json.java | 364 ++++++++++++++++++
.../quarkus/deployment/QuarkusAugmentor.java | 16 +-
.../BuildMetricsDevConsoleProcessor.java | 58 +++
.../main/resources/dev-templates/index.html | 21 +
.../build-metrics.html | 40 ++
9 files changed, 648 insertions(+), 10 deletions(-)
create mode 100644 core/builder/src/main/java/io/quarkus/builder/report/BuildMetrics.java
create mode 100644 core/builder/src/main/java/io/quarkus/builder/report/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-metrics.html
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 c1bee22846c8c6..b3cc7690be9c0e 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.toString(), 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 2219e2dbd6f023..1f6f04583c018a 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.report.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/Execution.java b/core/builder/src/main/java/io/quarkus/builder/Execution.java
index e89393b444963a..4d6f4b9708ba5b 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.report.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/report/BuildMetrics.java b/core/builder/src/main/java/io/quarkus/builder/report/BuildMetrics.java
new file mode 100644
index 00000000000000..659384ae4ed7a4
--- /dev/null
+++ b/core/builder/src/main/java/io/quarkus/builder/report/BuildMetrics.java
@@ -0,0 +1,116 @@
+package io.quarkus.builder.report;
+
+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.report.Json.JsonArrayBuilder;
+import io.quarkus.builder.report.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 name, String thread, LocalTime started, long duration) {
+ BuildStepRecord prev = records.putIfAbsent(name, new BuildStepRecord(name, thread, started, duration));
+ if (prev != null) {
+ String newName = name + "_d#" + duplicates.incrementAndGet();
+ LOG.debugf("A build step with the same name 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("name", rec.name);
+ 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 name of the build step.
+ */
+ public final String name;
+
+ /**
+ * 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 name, String thread, LocalTime started, long duration) {
+ this.name = name;
+ this.thread = thread;
+ this.started = started;
+ this.duration = duration;
+ }
+
+ }
+
+}
diff --git a/core/builder/src/main/java/io/quarkus/builder/report/Json.java b/core/builder/src/main/java/io/quarkus/builder/report/Json.java
new file mode 100644
index 00000000000000..1472bb0f2d597f
--- /dev/null
+++ b/core/builder/src/main/java/io/quarkus/builder/report/Json.java
@@ -0,0 +1,364 @@
+package io.quarkus.builder.report;
+
+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
+
+
+
+ Build Metrics
+
+
+
+
+
+
diff --git a/extensions/vertx-http/deployment/src/main/resources/dev-templates/io.quarkus.quarkus-vertx-http/build-metrics.html b/extensions/vertx-http/deployment/src/main/resources/dev-templates/io.quarkus.quarkus-vertx-http/build-metrics.html
new file mode 100644
index 00000000000000..1a3bde89ad3892
--- /dev/null
+++ b/extensions/vertx-http/deployment/src/main/resources/dev-templates/io.quarkus.quarkus-vertx-http/build-metrics.html
@@ -0,0 +1,40 @@
+{#include main fluid=true}
+{#title}Build Metrics - Build Steps{/title}
+{#body}
+
+{#let metrics=info:buildMetrics.get}
+
+
+Executed {metrics.steps.size} build steps on {metrics.threads.size} threads.
+
+
+
+
+
+ # |
+ Build Step |
+ Duration |
+ Thread |
+
+
+
+ {#for step in metrics.steps}
+
+ {step_count} |
+
+ {step.name}
+ |
+
+ {step.duration} ms
+ |
+
+ {step.thread}
+ |
+ {/for}
+
+
+
+{/let}
+
+{/body}
+{/include}
\ No newline at end of file