Skip to content

Commit

Permalink
Merge pull request quarkusio#25786 from mkouba/build-metrics
Browse files Browse the repository at this point in the history
Quarkus Builder - introduce build metrics
  • Loading branch information
mkouba authored Jun 21, 2022
2 parents d33d063 + 72ca803 commit 5aac1c4
Show file tree
Hide file tree
Showing 12 changed files with 679 additions and 14 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -266,15 +266,15 @@ 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("};");
writer.newLine();
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("; ");
}
}
Expand All @@ -299,11 +299,11 @@ public BuildChain build() throws ChainBuildException {
private static void writeStep(final BufferedWriter writer, final HashSet<StepInfo> 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<StepInfo> 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(" -> ");
Expand Down
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.getId(), 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.metrics.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
9 changes: 9 additions & 0 deletions core/builder/src/main/java/io/quarkus/builder/BuildStep.java
Original file line number Diff line number Diff line change
Expand Up @@ -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.
*/
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.metrics.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
Original file line number Diff line number Diff line change
@@ -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<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 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<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("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;
}

}

}
Loading

0 comments on commit 5aac1c4

Please sign in to comment.