Skip to content

Commit

Permalink
Quarkus Builder - introduce build metrics
Browse files Browse the repository at this point in the history
- 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
  • Loading branch information
mkouba committed May 25, 2022
1 parent 748908f commit 116940b
Show file tree
Hide file tree
Showing 9 changed files with 648 additions and 10 deletions.
14 changes: 10 additions & 4 deletions core/builder/src/main/java/io/quarkus/builder/BuildContext.java
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
Expand All @@ -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<StepInfo> dependents = stepInfo.getDependents();
Expand Down
12 changes: 11 additions & 1 deletion core/builder/src/main/java/io/quarkus/builder/BuildResult.java
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand All @@ -22,14 +23,16 @@ public final class BuildResult {
private final ConcurrentHashMap<ItemId, List<BuildItem>> multiItems;
private final List<Diagnostic> diagnostics;
private final long nanos;
private final BuildMetrics metrics;

BuildResult(final ConcurrentHashMap<ItemId, BuildItem> simpleItems,
final ConcurrentHashMap<ItemId, List<BuildItem>> multiItems, final Set<ItemId> finalIds,
final List<Diagnostic> diagnostics, final long nanos) {
final List<Diagnostic> diagnostics, final long nanos, BuildMetrics metrics) {
this.simpleItems = simpleItems;
this.multiItems = multiItems;
this.diagnostics = diagnostics;
this.nanos = nanos;
this.metrics = metrics;
}

/**
Expand Down Expand Up @@ -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.
*/
Expand Down
17 changes: 15 additions & 2 deletions core/builder/src/main/java/io/quarkus/builder/Execution.java
Original file line number Diff line number Diff line change
@@ -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;
Expand All @@ -19,6 +20,7 @@

import io.quarkus.builder.diag.Diagnostic;
import io.quarkus.builder.item.BuildItem;
import io.quarkus.builder.report.BuildMetrics;

/**
*/
Expand All @@ -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());
Expand All @@ -62,6 +66,8 @@ final class Execution {
lastStepCount.set(builder.getChain().getEndStepCount());
if (lastStepCount.get() == 0)
done = true;

metrics = new BuildMetrics(buildTargetName);
}

List<Diagnostic> getDiagnostics() {
Expand All @@ -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<StepInfo> startSteps = chain.getStartSteps();
for (StepInfo startStep : startSteps) {
Expand Down Expand Up @@ -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() {
Expand Down Expand Up @@ -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);
Expand Down
116 changes: 116 additions & 0 deletions core/builder/src/main/java/io/quarkus/builder/report/BuildMetrics.java
Original file line number Diff line number Diff line change
@@ -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<String, BuildStepRecord> records = new ConcurrentHashMap<>();
private final AtomicInteger duplicates = new AtomicInteger();

public BuildMetrics(String buildTargetName) {
this.buildTargetName = buildTargetName;
}

public Collection<BuildStepRecord> 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<BuildStepRecord> sorted = new ArrayList<>(records.values());
sorted.sort(new Comparator<BuildStepRecord>() {
@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;
}

}

}
Loading

0 comments on commit 116940b

Please sign in to comment.