flasn4nt
/
graal
mirror of https://github.com/oracle/graal.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

[JDK-8338189] Track phase times in graph dumps. 

PullRequest: graal/18558
This commit is contained in:
David Leopoldseder 2024-09-25 01:41:48 +00:00
parent 575698f2d8 95e1942d86
commit 63499df074
5 changed files with 344 additions and 16 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

108
compiler/src/jdk.graal.compiler.test/src/jdk/graal/compiler/debug/test/CompilationAlarmPhaseTimesTest.java Normal file
View File

@ -0,0 +1,108 @@
/*
* Copyright (c) 2024, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
* under the terms of the GNU General Public License version 2 only, as
* published by the Free Software Foundation. Oracle designates this
* particular file as subject to the "Classpath" exception as provided
* by Oracle in the LICENSE file that accompanied this code.
*
* This code is distributed in the hope that it will be useful, but WITHOUT
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
* version 2 for more details (a copy is included in the LICENSE file that
* accompanied this code).
*
* You should have received a copy of the GNU General Public License version
* 2 along with this work; if not, write to the Free Software Foundation,
* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
*
* Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
* or visit www.oracle.com if you need additional information or have any
* questions.
*/
package jdk.graal.compiler.debug.test;
import java.util.Optional;
import org.junit.Test;
import jdk.graal.compiler.core.common.util.CompilationAlarm;
import jdk.graal.compiler.core.test.GraalCompilerTest;
import jdk.graal.compiler.debug.GraalError;
import jdk.graal.compiler.nodes.GraphState;
import jdk.graal.compiler.nodes.StructuredGraph;
import jdk.graal.compiler.options.OptionValues;
import jdk.graal.compiler.phases.BasePhase;
import jdk.graal.compiler.phases.tiers.LowTierContext;
import jdk.graal.compiler.phases.tiers.Suites;
public class CompilationAlarmPhaseTimesTest extends GraalCompilerTest {
@Override
protected Suites createSuites(OptionValues opts) {
Suites s = super.createSuites(opts);
s = s.copy();
s.getLowTier().appendPhase(new BasePhase<>() {
@Override
public Optional<NotApplicable> notApplicableTo(GraphState graphState) {
return ALWAYS_APPLICABLE;
}
@Override
protected void run(StructuredGraph graph, LowTierContext context) {
try {
for (int i = 0; i < SLEEP_SECONDS * 1000; i++) {
// sleep often to check progress often
Thread.sleep(1);
CompilationAlarm.checkProgress(graph);
}
} catch (InterruptedException e) {
throw GraalError.shouldNotReachHere(e);
}
}
});
return s;
}
/**
* Seconds this test tries to sleep a compiler phase to trigger a timeout.
*/
public static final int SLEEP_SECONDS = 10;
@Test
public void testTimeOutRetryToString() {
// 1D will be multiplied by 2 since we are running with assertions
OptionValues opt = new OptionValues(getInitialOptions(), CompilationAlarm.Options.CompilationExpirationPeriod, 1D);
try {
test(opt, "foo", 10000);
} catch (Throwable t) {
assert t.getMessage().contains("Compilation exceeded 2.000 seconds");
StructuredGraph g = lastCompiledGraph;
assert g != null;
String message = t.getMessage();
final String phaseName = "CompilationAlarmPhaseTimesTest$1";
int index = message.indexOf(phaseName);
// skip the "->"
index += phaseName.length() + 2;
String duration = "";
char c;
while (Character.isDigit((c = message.charAt(index)))) {
duration += c;
index++;
}
assert Integer.parseInt(duration) >= 2000 : "Must at least wait for 2000ms";
}
}
public static int foo(int limit) {
int result = 0;
for (int i = 0; i < limit; i++) {
result += i;
}
return result;
}
}

2
compiler/src/jdk.graal.compiler/src/jdk/graal/compiler/core/CompilationWrapper.java
View File

@ -43,6 +43,7 @@ import java.util.Map;
import org.graalvm.collections.EconomicMap;
import jdk.graal.compiler.core.common.util.CompilationAlarm;
import jdk.graal.compiler.core.common.NumUtil;
import jdk.graal.compiler.debug.DebugCloseable;
import jdk.graal.compiler.debug.DebugContext;
@ -350,6 +351,7 @@ public abstract class CompilationWrapper<T> {
T res;
try {
CompilationAlarm.current().reset(retryOptions);
res = performCompilation(retryDebug);
} finally {
ps.println("<Metrics>");

210
compiler/src/jdk.graal.compiler/src/jdk/graal/compiler/core/common/util/CompilationAlarm.java
View File

@ -35,6 +35,7 @@ import jdk.graal.compiler.options.Option;
import jdk.graal.compiler.options.OptionKey;
import jdk.graal.compiler.options.OptionType;
import jdk.graal.compiler.options.OptionValues;
import jdk.graal.compiler.phases.BasePhase;
import jdk.graal.compiler.serviceprovider.GraalServices;
import jdk.vm.ci.services.Services;
@ -63,10 +64,43 @@ public final class CompilationAlarm implements AutoCloseable {
public static final boolean LOG_PROGRESS_DETECTION = !Services.IS_IN_NATIVE_IMAGE &&
Boolean.parseBoolean(GraalServices.getSavedProperty("debug." + CompilationAlarm.class.getName() + ".logProgressDetection"));
/**
* The previously installed alarm.
*/
private final CompilationAlarm previous;
@SuppressWarnings("this-escape")
private CompilationAlarm(double period) {
this.period = period;
this.expiration = period == 0.0D ? 0L : System.currentTimeMillis() + (long) (period * 1000);
this.previous = currentAlarm.get();
reset(period);
}
/**
* Resets the compilation alarm with a new period for expiration. See
* {@link #trackCompilationPeriod} for details about tracking compilation periods.
*/
public void reset(double newPeriod) {
if (this != NEVER_EXPIRES) {
this.period = newPeriod;
this.expiration = newPeriod == 0.0D ? 0L : System.currentTimeMillis() + (long) (newPeriod * 1000);
}
}
/**
* Use the option value defined compilation expiration period and reset this alarm. See
* {@link #reset(double)}.
*/
public void reset(OptionValues options) {
double optionPeriod = Options.CompilationExpirationPeriod.getValue(options);
if (optionPeriod > 0) {
if (Assertions.assertionsEnabled()) {
optionPeriod *= 2;
}
if (Assertions.detailedAssertionsEnabled(options)) {
optionPeriod *= 2;
}
reset(optionPeriod);
}
}
/**
@ -98,43 +132,188 @@ public final class CompilationAlarm implements AutoCloseable {
* @return {@code true} if this alarm has been active for more than {@linkplain #getPeriod()
* period} seconds, {@code false} otherwise
*/
private boolean hasExpired() {
return expiration != 0 && System.currentTimeMillis() > expiration;
public boolean hasExpired() {
/*
* We have multiple ways to mark a disabled alarm: it can be NEVER_EXPIRES which is shared
* among all threads and thus must not be altered, or it can be an Alarm object with an
* expiration=0. We cannot share disabled timers across threads because we record the
* previous timer to continue afterwards with the actual timer.
*/
return this != NEVER_EXPIRES && expiration != 0 && System.currentTimeMillis() > expiration;
}
public long elapsed() {
return this == NEVER_EXPIRES ? -1 : System.currentTimeMillis() - start();
}
private long start() {
return this == NEVER_EXPIRES ? -1 : expiration - (long) (period * 1000);
}
public boolean isEnabled() {
return this != NEVER_EXPIRES;
}
/**
* Checks whether this alarm {@link #hasExpired()} and if so, raises a bailout exception.
*/
private void checkExpiration() {
public void checkExpiration() {
if (hasExpired()) {
throw new PermanentBailoutException("Compilation exceeded %.3f seconds", period);
// update the timing of the current phase node to have exact information in the phase
// times
updateCurrentPhaseNodeTime();
throw new PermanentBailoutException("Compilation exceeded %.3f seconds. %n Phase timings %s", period, elapsedPhaseTreeAsString());
}
}
@Override
public void close() {
currentAlarm.set(previous);
resetProgressDetection();
}
/**
* Expiration period (in seconds) of this alarm.
*/
private final double period;
private double period;
/**
* The time at which this alarm expires.
*/
private final long expiration;
private long expiration;
/**
* The previously installed alarm.
* Signal the execution of the phase identified by {@code name} starts.
*/
private final CompilationAlarm previous;
public void enterPhase(String name) {
if (!isEnabled()) {
return;
}
PhaseTreeNode node = new PhaseTreeNode(name);
node.parent = currentNode;
node.time = elapsed();
currentNode.addChild(node);
currentNode = node;
}
/**
* Signal the execution of the phase identified by {@code name} is over.
*/
public void exitPhase(String name) {
if (!isEnabled()) {
return;
}
assert currentNode.name.equals(name) : Assertions.errorMessage("Must see the same phase that was opened in the close operation", name, elapsedPhaseTreeAsString());
updateCurrentPhaseNodeTime();
currentNode = currentNode.parent;
}
private void updateCurrentPhaseNodeTime() {
final long duration = elapsed() - currentNode.time;
currentNode.time = duration;
}
/**
* The phase tree root node during compilation. Special marker node to avoid null checking
* logic. Note that the {@link PhaseTreeNode#time} of the root is only set and calculated when
* the tree is printed from the root.
*/
private PhaseTreeNode root = new PhaseTreeNode("Root");
/**
* The current tree node to add children to. That is, the phase that currently runs in the
* compiler.
*/
private PhaseTreeNode currentNode = root;
/**
* Tree data structure representing phase nesting and the respective wall clock time of each
* phase.
*/
private class PhaseTreeNode {
/**
* Link to the parent node.
*/
private PhaseTreeNode parent;
/**
* All children of this node.
*/
private PhaseTreeNode[] children;
/**
* The next free index to add child nodes.
*/
private int childIndex = 0;
/**
* The name of this node, normally the {@link BasePhase#contractorName()}.
*/
private final String name;
/**
* The wall clock time spent in this phase. Note this value is only correct after a phase
* regularly finished.
*/
private long time = -1L;
PhaseTreeNode(String name) {
this.name = name;
}
private void addChild(PhaseTreeNode child) {
if (children == null) {
children = new PhaseTreeNode[CHILD_TREE_INIT_SIZE];
children[childIndex++] = child;
return;
}
// double the array if it needs expanding
if (childIndex >= children.length) {
children = Arrays.copyOf(children, children.length * 2);
}
children[childIndex++] = child;
}
@Override
public String toString() {
return name + "->" + time + "ns";
}
}
/**
* Initial size of a {@link PhaseTreeNode} children array.
*/
private static final int CHILD_TREE_INIT_SIZE = 2;
/**
* Recursively print the phase tree represented by {@code node}.
*/
private void printTree(String indent, StringBuilder sb, PhaseTreeNode node) {
sb.append(indent);
if (node == root) {
// only update the root timing incrementally when needed
root.time = elapsed();
}
sb.append(node);
sb.append(System.lineSeparator());
if (node.children != null) {
for (int i = 0; i < node.childIndex; i++) {
printTree(indent + "\t", sb, node.children[i]);
}
}
}
public StringBuilder elapsedPhaseTreeAsString() {
StringBuilder sb = new StringBuilder();
printTree("", sb, root);
return sb;
}
/**
* Starts an alarm for setting a time limit on a compilation if there isn't already an active
* alarm and {@link CompilationAlarm.Options#CompilationExpirationPeriod}{@code > 0}. The
* returned value should be used in a try-with-resource statement to disable the alarm once the
* returned value can be used in a try-with-resource statement to disable the alarm once the
* compilation is finished.
*
* @return a {@link CompilationAlarm} if there was no current alarm for the calling thread
@ -149,9 +328,12 @@ public final class CompilationAlarm implements AutoCloseable {
if (Assertions.detailedAssertionsEnabled(options)) {
period *= 2;
}
CompilationAlarm current = new CompilationAlarm(period);
currentAlarm.set(current);
return current;
CompilationAlarm current = currentAlarm.get();
if (current == null) {
current = new CompilationAlarm(period);
currentAlarm.set(current);
return current;
}
}
return null;
}

31
compiler/src/jdk.graal.compiler/src/jdk/graal/compiler/debug/DebugContext.java
View File

@ -51,6 +51,7 @@ import org.graalvm.collections.EconomicMap;
import org.graalvm.collections.EconomicSet;
import org.graalvm.collections.Pair;
import jdk.graal.compiler.core.common.util.CompilationAlarm;
import jdk.graal.compiler.graphio.GraphOutput;
import jdk.graal.compiler.options.OptionKey;
import jdk.graal.compiler.options.OptionValues;
@ -455,10 +456,36 @@ public final class DebugContext implements AutoCloseable {
* ends
*/
public CompilerPhaseScope enterCompilerPhase(CharSequence phaseName) {
CompilationAlarm.current().enterPhase(phaseName.toString());
if (compilationListener != null) {
return enterCompilerPhase(() -> phaseName);
return new DecoratingCompilerPhaseScope(() -> {
CompilationAlarm.current().exitPhase(phaseName.toString());
}, enterCompilerPhase(() -> phaseName));
}
return null;
return new CompilerPhaseScope() {
@Override
public void close() {
CompilationAlarm.current().exitPhase(phaseName.toString());
}
};
}
private static class DecoratingCompilerPhaseScope implements CompilerPhaseScope {
final Runnable closeAction;
final CompilerPhaseScope wrapped;
DecoratingCompilerPhaseScope(Runnable closeAction, CompilerPhaseScope wrapped) {
this.closeAction = closeAction;
this.wrapped = wrapped;
}
@Override
public void close() {
closeAction.run();
wrapped.close();
}
}
/**

9
compiler/src/jdk.graal.compiler/src/jdk/graal/compiler/printer/GraphPrinterDumpHandler.java
View File

@ -39,6 +39,7 @@ import java.util.Map;
import java.util.WeakHashMap;
import jdk.graal.compiler.core.common.CompilationIdentifier;
import jdk.graal.compiler.core.common.util.CompilationAlarm;
import jdk.graal.compiler.debug.DebugContext;
import jdk.graal.compiler.debug.DebugDumpHandler;
import jdk.graal.compiler.debug.DebugDumpScope;
@ -199,6 +200,14 @@ public final class GraphPrinterDumpHandler implements DebugDumpHandler {
}
properties.put("StageFlags", structuredGraph.getGraphState().getStageFlags());
properties.put("speculationLog", structuredGraph.getSpeculationLog() != null ? structuredGraph.getSpeculationLog().toString() : "null");
CompilationAlarm currentAlarm = CompilationAlarm.current();
if (currentAlarm.isEnabled()) {
properties.put("elapsedCompilationAlarm", currentAlarm.elapsed());
if (currentAlarm.elapsedPhaseTreeAsString() != null) {
properties.put("elapsedPhaseTimes", currentAlarm.elapsedPhaseTreeAsString().toString());
}
}
}
if (PrintUnmodifiedGraphs.getValue(options) || lastGraph != graph || lastModCount != graph.getEdgeModificationCount()) {
printer.print(debug, graph, properties, nextDumpId(), format, arguments);