Skip to content

Commit f39921e

Browse files
tkrodrigueztkrodriguez
committed
Metric improvements
1 parent 73fd090 commit f39921e

File tree

15 files changed

+326
-101
lines changed

15 files changed

+326
-101
lines changed

‎compiler/mx.compiler/suite.py

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -574,6 +574,7 @@
574574
"name" : "jdk.graal.compiler",
575575
"exports" : [
576576
"""* to jdk.graal.compiler.libgraal,
577+
jdk.graal.compiler.management,
577578
com.oracle.graal.graal_enterprise,
578579
org.graalvm.nativeimage.pointsto,
579580
org.graalvm.nativeimage.builder,
@@ -594,7 +595,7 @@
594595
"jdk.graal.compiler.nodes.graphbuilderconf to org.graalvm.nativeimage.driver,org.graalvm.nativeimage.librarysupport",
595596
"jdk.graal.compiler.options to org.graalvm.nativeimage.driver,org.graalvm.nativeimage.junitsupport",
596597
"jdk.graal.compiler.phases.common to org.graalvm.nativeimage.agent.tracing,org.graalvm.nativeimage.configure",
597-
"jdk.graal.compiler.serviceprovider to jdk.graal.compiler.management,org.graalvm.nativeimage.driver,org.graalvm.nativeimage.agent.jvmtibase,org.graalvm.nativeimage.agent.diagnostics",
598+
"jdk.graal.compiler.serviceprovider to org.graalvm.nativeimage.driver,org.graalvm.nativeimage.agent.jvmtibase,org.graalvm.nativeimage.agent.diagnostics",
598599
"jdk.graal.compiler.util.json to org.graalvm.nativeimage.librarysupport,org.graalvm.nativeimage.agent.tracing,org.graalvm.nativeimage.configure,org.graalvm.nativeimage.driver",
599600
],
600601
"uses" : [

‎compiler/src/jdk.graal.compiler.management/src/jdk/graal/compiler/management/JMXServiceProvider.java

Lines changed: 62 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -27,18 +27,20 @@
2727
import static jdk.graal.compiler.serviceprovider.GraalServices.getCurrentThreadId;
2828

2929
import java.io.IOException;
30+
import java.lang.management.GarbageCollectorMXBean;
3031
import java.lang.management.ManagementFactory;
3132
import java.nio.file.Files;
3233
import java.nio.file.Path;
3334
import java.util.List;
35+
import java.util.concurrent.TimeUnit;
3436

35-
import com.sun.management.HotSpotDiagnosticMXBean;
36-
import jdk.graal.compiler.serviceprovider.JMXService;
37-
import jdk.graal.compiler.serviceprovider.ServiceProvider;
37+
import javax.management.MBeanServer;
3838

39+
import com.sun.management.HotSpotDiagnosticMXBean;
3940
import com.sun.management.ThreadMXBean;
4041

41-
import javax.management.MBeanServer;
42+
import jdk.graal.compiler.serviceprovider.JMXService;
43+
import jdk.graal.compiler.serviceprovider.ServiceProvider;
4244

4345
/**
4446
* Implementation of {@link JMXService}.
@@ -96,6 +98,62 @@ protected void dumpHeap(String outputFile, boolean live) throws IOException {
9698
}
9799
}
98100

101+
/**
102+
* Reports information about time in the garbage collector.
103+
*/
104+
static class GCTimeStatisticsImpl implements GCTimeStatistics {
105+
106+
private final List<GarbageCollectorMXBean> gcs;
107+
private final long startTimeNanos;
108+
private final long beforeCount;
109+
private final long beforeMillis;
110+
111+
GCTimeStatisticsImpl(List<GarbageCollectorMXBean> gcs) {
112+
this.gcs = gcs;
113+
long totalCount = 0;
114+
long totalMillis = 0;
115+
for (GarbageCollectorMXBean gc : gcs) {
116+
totalCount += gc.getCollectionCount();
117+
totalMillis += gc.getCollectionTime();
118+
}
119+
beforeCount = totalCount;
120+
beforeMillis = totalMillis;
121+
startTimeNanos = System.nanoTime();
122+
}
123+
124+
@Override
125+
public long getGCTimeMills() {
126+
long afterMillis = 0;
127+
for (GarbageCollectorMXBean gc : gcs) {
128+
afterMillis += gc.getCollectionTime();
129+
}
130+
return afterMillis - beforeMillis;
131+
}
132+
133+
@Override
134+
public long getGCCount() {
135+
long afterCount = 0;
136+
for (GarbageCollectorMXBean gc : gcs) {
137+
afterCount += gc.getCollectionCount();
138+
}
139+
return afterCount - beforeCount;
140+
}
141+
142+
@Override
143+
public long getElapsedTimeMillis() {
144+
return TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startTimeNanos);
145+
}
146+
}
147+
148+
@Override
149+
protected GCTimeStatistics getGCTimeStatistics() {
150+
List<GarbageCollectorMXBean> gcs = ManagementFactory.getGarbageCollectorMXBeans();
151+
if (gcs != null) {
152+
return new GCTimeStatisticsImpl(gcs);
153+
}
154+
return null;
155+
}
156+
99157
private void initHotSpotMXBean() {
100158
if (hotspotMXBean == null) {
101159
synchronized (this) {

‎compiler/src/jdk.graal.compiler/src/jdk/graal/compiler/core/common/util/CompilationAlarm.java

Lines changed: 18 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -38,6 +38,7 @@
3838
import jdk.graal.compiler.options.OptionType;
3939
import jdk.graal.compiler.options.OptionValues;
4040
import jdk.graal.compiler.serviceprovider.GraalServices;
41+
import jdk.graal.compiler.serviceprovider.JMXService;
4142
import jdk.vm.ci.meta.ResolvedJavaMethod;
4243

4344
/**
@@ -73,6 +74,11 @@ public static class Options {
7374
private CompilationAlarm(double period) {
7475
this.previous = currentAlarm.get();
7576
reset(period);
77+
JMXService.GCTimeStatistics timing = null;
78+
if (period != 0) {
79+
timing = GraalServices.getGCTimeStatistics();
80+
}
81+
this.gcTiming = timing;
7682
}
7783

7884
/**
@@ -190,7 +196,13 @@ public void checkExpiration() {
190196
cloneTree.durationNS = elapsed();
191197
printTree("", sb, cloneTree, true);
192198

193-
throw new PermanentBailoutException("Compilation exceeded %.3f seconds. %n Phase timings:%n %s <===== TIMEOUT HERE", period, sb.toString().trim());
199+
// Include information about time spent in the GC if it's available.
200+
String gcMessage = "";
201+
if (gcTiming != null) {
202+
gcMessage = String.format(" (GC time is %s ms of %s ms elapsed)", gcTiming.getGCTimeMills(), gcTiming.getElapsedTimeMillis());
203+
}
204+
205+
throw new PermanentBailoutException("Compilation exceeded %.3f seconds%s. %n Phase timings:%n %s <===== TIMEOUT HERE", period, gcMessage, sb.toString().trim());
194206
}
195207
}
196208

@@ -210,6 +222,11 @@ public void close() {
210222
*/
211223
private long expirationNS;
212224

225+
/**
226+
* Time spent in the garbage collector if it's available.
227+
*/
228+
private final JMXService.GCTimeStatistics gcTiming;
229+
213230
/**
214231
* Signal the execution of the phase identified by {@code name} starts.
215232
*/

‎compiler/src/jdk.graal.compiler/src/jdk/graal/compiler/debug/BaseTimerKey.java

Lines changed: 22 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -48,6 +48,16 @@ public TimeUnit getTimeUnit() {
4848
return accm.getTimeUnit();
4949
}
5050

51+
@Override
52+
public void add(DebugContext debug, long value, TimeUnit units) {
53+
accm.add(debug, value, units);
54+
}
55+
56+
@Override
57+
public boolean isEnabled(DebugContext debug) {
58+
return accm.isEnabled(debug);
59+
}
60+
5161
@Override
5262
public DebugCloseable start(DebugContext debug) {
5363
return accm.start(debug);
@@ -90,6 +100,18 @@ public DebugCloseable start(DebugContext debug) {
90100
}
91101
}
92102

103+
@Override
104+
public void add(DebugContext debug, long value, TimeUnit units) {
105+
if (debug.isTimerEnabled(this)) {
106+
addToCurrentValue(debug, getTimeUnit().convert(value, units));
107+
}
108+
}
109+
110+
@Override
111+
public boolean isEnabled(DebugContext debug) {
112+
return debug.isTimerEnabled(this);
113+
}
114+
93115
@Override
94116
public TimerKey getFlat() {
95117
return (FlatTimer) flat;

‎compiler/src/jdk.graal.compiler/src/jdk/graal/compiler/debug/DebugConfigImpl.java

Lines changed: 8 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -36,7 +36,6 @@
3636
import java.util.Map;
3737

3838
import jdk.graal.compiler.options.OptionValues;
39-
4039
import jdk.vm.ci.code.BailoutException;
4140
import jdk.vm.ci.meta.JavaMethod;
4241

@@ -47,7 +46,7 @@ final class DebugConfigImpl implements DebugConfig {
4746
private final DebugFilter countFilter;
4847
private final DebugFilter logFilter;
4948
private final DebugFilter trackMemUseFilter;
50-
private final DebugFilter timerFilter;
49+
private final DebugFilter timeFilter;
5150
private final DebugFilter dumpFilter;
5251
private final DebugFilter verifyFilter;
5352
private final MethodFilter methodFilter;
@@ -76,7 +75,7 @@ final class DebugConfigImpl implements DebugConfig {
7675
String logFilter,
7776
String countFilter,
7877
String trackMemUseFilter,
79-
String timerFilter,
78+
String timeFilter,
8079
String dumpFilter,
8180
String verifyFilter,
8281
String methodFilter,
@@ -87,7 +86,7 @@ final class DebugConfigImpl implements DebugConfig {
8786
this.logFilter = DebugFilter.parse(logFilter);
8887
this.countFilter = DebugFilter.parse(countFilter);
8988
this.trackMemUseFilter = DebugFilter.parse(trackMemUseFilter);
90-
this.timerFilter = DebugFilter.parse(timerFilter);
89+
this.timeFilter = DebugFilter.parse(timeFilter);
9190
this.dumpFilter = DebugFilter.parse(dumpFilter);
9291
this.verifyFilter = DebugFilter.parse(verifyFilter);
9392
if (methodFilter == null || methodFilter.isEmpty()) {
@@ -147,7 +146,7 @@ public boolean isVerifyEnabled(DebugContext.Scope scope) {
147146

148147
@Override
149148
public boolean isTimeEnabled(DebugContext.Scope scope) {
150-
return isEnabled(scope, timerFilter);
149+
return isEnabled(scope, timeFilter);
151150
}
152151

153152
@Override
@@ -161,13 +160,14 @@ public PrintStream output() {
161160
}
162161

163162
private boolean isEnabled(DebugContext.Scope scope, DebugFilter filter) {
164-
return getLevel(scope, filter) > 0;
163+
return getLevel(scope, filter) >= 0;
165164
}
166165

167166
private int getLevel(DebugContext.Scope scope, DebugFilter filter) {
168167
int level;
169168
if (filter == null) {
170-
level = 0;
169+
// null means the value has not been set
170+
level = -1;
171171
} else {
172172
level = filter.matchLevel(scope);
173173
}
@@ -219,7 +219,7 @@ public String toString() {
219219
sb.append("Debug config:");
220220
add(sb, "Log", logFilter);
221221
add(sb, "Count", countFilter);
222-
add(sb, "Time", timerFilter);
222+
add(sb, "Time", timeFilter);
223223
add(sb, "Dump", dumpFilter);
224224
add(sb, "MethodFilter", methodFilter);
225225
return sb.toString();

‎compiler/src/jdk.graal.compiler/src/jdk/graal/compiler/debug/DebugContext.java

Lines changed: 36 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -665,7 +665,7 @@ private DebugContext(Description description,
665665
}
666666
currentScope = new ScopeImpl(this, Thread.currentThread(), DebugOptions.DisableIntercept.getValue(options));
667667
currentScope.updateFlags(currentConfig);
668-
metricsEnabled = true;
668+
metricsEnabled = !disableConfig;
669669
} else {
670670
metricsEnabled = immutable.hasUnscopedMetrics() || immutable.listMetrics;
671671
}
@@ -767,6 +767,10 @@ public boolean isCountEnabled() {
767767
return currentScope != null && currentScope.isCountEnabled();
768768
}
769769

770+
public boolean isTimeEnabled() {
771+
return currentScope != null && currentScope.isTimeEnabled();
772+
}
773+
770774
public boolean isMemUseTrackingEnabled() {
771775
return currentScope != null && currentScope.isMemUseTrackingEnabled();
772776
}
@@ -1887,6 +1891,28 @@ public static CounterKey counter(CharSequence name) {
18871891
return createCounter("%s", name, null);
18881892
}
18891893

1894+
public static CountingTimerKey countingTimer(CharSequence name) {
1895+
return new CountingTimerKey(name);
1896+
}
1897+
1898+
/**
1899+
* Tracks both the number of times a timer was started and the elapsed time.
1900+
*/
1901+
public static class CountingTimerKey {
1902+
CounterKey count;
1903+
TimerKey time;
1904+
1905+
CountingTimerKey(CharSequence name) {
1906+
count = DebugContext.counter(name + "Count");
1907+
time = DebugContext.timer(name + "Time");
1908+
}
1909+
1910+
public DebugCloseable start(DebugContext debug) {
1911+
count.add(debug, 1);
1912+
return time.start(debug);
1913+
}
1914+
}
1915+
18901916
/**
18911917
* Gets a tally of the metric values in this context and a given tally.
18921918
*
@@ -2316,7 +2342,7 @@ public void printMetrics(Description desc) {
23162342
ByteArrayOutputStream baos = new ByteArrayOutputStream(metricsBufSize);
23172343
PrintStream out = new PrintStream(baos);
23182344
if (metricsFile.endsWith(".csv") || metricsFile.endsWith(".CSV")) {
2319-
printMetricsCSV(out, compilable, identity, compilationNr, desc.identifier);
2345+
printMetricsCSV(out, compilable, identity, compilationNr, desc.identifier, DebugOptions.OmitZeroMetrics.getValue(getOptions()));
23202346
} else {
23212347
printMetrics(out, compilable, identity, compilationNr, desc.identifier);
23222348
}
@@ -2345,8 +2371,9 @@ public void printMetrics(Description desc) {
23452371
* @param compilationNr where this compilation lies in the ordered sequence of all compilations
23462372
* identified by {@code identity}
23472373
* @param compilationId the runtime issued identifier for the compilation
2374+
* @param skipZero
23482375
*/
2349-
private void printMetricsCSV(PrintStream out, Object compilable, Integer identity, int compilationNr, String compilationId) {
2376+
private void printMetricsCSV(PrintStream out, Object compilable, Integer identity, int compilationNr, String compilationId, boolean skipZero) {
23502377
String compilableName = compilable instanceof JavaMethod ? ((JavaMethod) compilable).format("%H.%n(%p)%R") : String.valueOf(compilable);
23512378
String csvFormat = CSVUtil.buildFormatString("%s", "%s", "%d", "%s");
23522379
String format = String.format(csvFormat, CSVUtil.Escape.escapeArgsFormatString(compilableName, identity, compilationNr, compilationId));
@@ -2355,8 +2382,12 @@ private void printMetricsCSV(PrintStream out, Object compilable, Integer identit
23552382
for (MetricKey key : KeyRegistry.getKeys()) {
23562383
int index = ((AbstractKey) key).getIndex();
23572384
if (index < metricValues.length) {
2358-
Pair<String, String> valueAndUnit = key.toCSVFormat(metricValues[index]);
2359-
CSVUtil.Escape.println(out, format, CSVUtil.Escape.escape(key.getName()), valueAndUnit.getLeft(), valueAndUnit.getRight());
2385+
long metricValue = metricValues[index];
2386+
if (skipZero && metricValue == 0) {
2387+
continue;
2388+
}
2389+
Pair<String, String> valueAndUnit = key.toCSVFormat(metricValue);
2390+
CSVUtil.Escape.println(out, format, key.getName(), valueAndUnit.getLeft(), valueAndUnit.getRight());
23602391
}
23612392
}
23622393
}

‎compiler/src/jdk.graal.compiler/src/jdk/graal/compiler/debug/DebugOptions.java

Lines changed: 14 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -195,9 +195,12 @@ public enum OptimizationLogTarget {
195195
"will not include metrics for compiler code that is not executed.", type = OptionType.Debug)
196196
public static final OptionKey<Boolean> ListMetrics = new OptionKey<>(false);
197197
@Option(help = """
198-
File to which metrics are dumped per compilation.
199-
A CSV format is used if the file ends with .csv otherwise a more
200-
human readable format is used. The fields in the CSV format are:
198+
File to which metrics are dumped per compilation at shutdown.
199+
A %p in the name will be replaced with a string identifying the process, usually the process id.
200+
A CSV format is used if the file ends with .csv otherwise a more human readable format is used.
201+
An empty argument causes metrics to be dumped to the console.
202+
203+
The fields in the CSV format are:
201204
compilable - method being compiled
202205
compilable_identity - identity hash code of compilable
203206
compilation_nr - where this compilation lies in the ordered
@@ -207,10 +210,16 @@ public enum OptimizationLogTarget {
207210
metric_name - name of metric
208211
metric_value - value of metric""", type = OptionType.Debug)
209212
public static final OptionKey<String> MetricsFile = new OptionKey<>(null);
210-
@Option(help = "File to which aggregated metrics are dumped at shutdown. A CSV format is used if the file ends with .csv " +
211-
"otherwise a more human readable format is used. If not specified, metrics are dumped to the console.", type = OptionType.Debug)
213+
@Option(help = """
214+
File to which aggregated metrics are dumped at shutdown.
215+
A %p in the name will be replaced with a string identifying the process, usually the process id.
216+
A CSV format is used if the file ends with .csv otherwise a more human readable format is used.
217+
An empty argument causes metrics to be dumped to the console.""", type = OptionType.Debug)
212218
public static final OptionKey<String> AggregatedMetricsFile = new OptionKey<>(null);
213219

220+
@Option(help = "Omit metrics with a zero value when writing CSV files.", type = OptionType.Debug)
221+
public static final OptionKey<Boolean> OmitZeroMetrics = new OptionKey<>(true);
222+
214223
@Option(help = "Enable debug output for stub code generation and snippet preparation.", type = OptionType.Debug)
215224
public static final OptionKey<Boolean> DebugStubsAndSnippets = new OptionKey<>(false);
216225
@Option(help = "Send compiler IR to dump handlers on error.", type = OptionType.Debug)

‎compiler/src/jdk.graal.compiler/src/jdk/graal/compiler/debug/GlobalMetrics.java

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,9 @@
3535
import org.graalvm.collections.EconomicMap;
3636
import org.graalvm.collections.MapCursor;
3737
import org.graalvm.collections.Pair;
38+
3839
import jdk.graal.compiler.options.OptionValues;
40+
import jdk.graal.compiler.serviceprovider.GraalServices;
3941
import jdk.graal.compiler.serviceprovider.IsolateUtil;
4042

4143
/**
@@ -87,7 +89,11 @@ private static PrintStream openPrintStream(String metricsFile, Path[] outPath) t
8789
}
8890
}
8991

90-
static Path generateFileName(String metricsFile) {
92+
static Path generateFileName(String nameTemplate) {
93+
String metricsFile = nameTemplate;
94+
if (metricsFile.contains("%p")) {
95+
metricsFile = metricsFile.replace("%p", GraalServices.getExecutionID());
96+
}
9197
Path path;
9298
if (IsolateUtil.getIsolateAddress() != 0L) {
9399
long isolateID = IsolateUtil.getIsolateID();

0 commit comments

Comments
 (0)