Skip to content

Commit 7daf335

Browse files
tkrodrigueztkrodriguez
committed
[GR-64493] Metric improvements
PullRequest: graal/20977
2 parents e1e9a19 + 09228d5 commit 7daf335

File tree

16 files changed

+352
-106
lines changed

16 files changed

+352
-106
lines changed

‎compiler/mx.compiler/suite.py

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -493,6 +493,7 @@
493493
"name" : "jdk.graal.compiler",
494494
"exports" : [
495495
"""* to jdk.graal.compiler.libgraal,
496+
jdk.graal.compiler.management,
496497
com.oracle.graal.graal_enterprise,
497498
org.graalvm.nativeimage.pointsto,
498499
org.graalvm.nativeimage.builder,
@@ -513,7 +514,7 @@
513514
"jdk.graal.compiler.nodes.graphbuilderconf to org.graalvm.nativeimage.driver,org.graalvm.nativeimage.librarysupport",
514515
"jdk.graal.compiler.options to org.graalvm.nativeimage.driver,org.graalvm.nativeimage.junitsupport",
515516
"jdk.graal.compiler.phases.common to org.graalvm.nativeimage.agent.tracing,org.graalvm.nativeimage.configure",
516-
"jdk.graal.compiler.serviceprovider to jdk.graal.compiler.management,org.graalvm.nativeimage.driver,org.graalvm.nativeimage.agent.jvmtibase,org.graalvm.nativeimage.agent.diagnostics",
517+
"jdk.graal.compiler.serviceprovider to org.graalvm.nativeimage.driver,org.graalvm.nativeimage.agent.jvmtibase,org.graalvm.nativeimage.agent.diagnostics",
517518
"jdk.graal.compiler.util.json to org.graalvm.nativeimage.librarysupport,org.graalvm.nativeimage.agent.tracing,org.graalvm.nativeimage.configure,org.graalvm.nativeimage.driver",
518519
],
519520
"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.test/src/jdk/graal/compiler/debug/test/DebugContextTest.java

Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -337,4 +337,27 @@ public void testDebugConfig() {
337337
Assert.assertTrue(options2.toString().contains("MethodFilter=test"));
338338
Assert.assertTrue(options2.toString().contains("DumpOnError=true"));
339339
}
340+
341+
@Test
342+
public void testIsCountEnabled1() {
343+
EconomicMap<OptionKey<?>, Object> map = EconomicMap.create();
344+
map.put(DebugOptions.Count, "");
345+
OptionValues options = new OptionValues(map);
346+
DebugContext debug = new Builder(options).build();
347+
try (Scope _ = debug.scope("Scope")) {
348+
Assert.assertTrue(debug.isCountEnabled());
349+
}
350+
}
351+
352+
@Test
353+
public void testIsCountEnabled2() {
354+
EconomicMap<OptionKey<?>, Object> map = EconomicMap.create();
355+
map.put(DebugOptions.Counters, "");
356+
OptionValues options = new OptionValues(map);
357+
DebugContext debug = new Builder(options).build();
358+
try (Scope _ = debug.scope("Scope")) {
359+
Assert.assertTrue(debug.isCountEnabled());
360+
}
361+
}
362+
340363
}

‎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: 9 additions & 11 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,16 +160,15 @@ 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) >= 1;
165164
}
166165

167166
private int getLevel(DebugContext.Scope scope, DebugFilter filter) {
168-
int level;
169167
if (filter == null) {
170-
level = 0;
171-
} else {
172-
level = filter.matchLevel(scope);
168+
// null means the value has not been set
169+
return -1;
173170
}
171+
int level = filter.matchLevel(scope);
174172
if (level >= 0 && !checkMethodFilter(scope)) {
175173
level = -1;
176174
}
@@ -219,7 +217,7 @@ public String toString() {
219217
sb.append("Debug config:");
220218
add(sb, "Log", logFilter);
221219
add(sb, "Count", countFilter);
222-
add(sb, "Time", timerFilter);
220+
add(sb, "Time", timeFilter);
223221
add(sb, "Dump", dumpFilter);
224222
add(sb, "MethodFilter", methodFilter);
225223
return sb.toString();

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

Lines changed: 38 additions & 7 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
}
@@ -764,11 +764,15 @@ public boolean isVerifyEnabled() {
764764
}
765765

766766
public boolean isCountEnabled() {
767-
return currentScope != null && currentScope.isCountEnabled();
767+
return currentScope != null && currentScope.isCountEnabled() || immutable.unscopedCounters != null;
768+
}
769+
770+
public boolean isTimeEnabled() {
771+
return currentScope != null && currentScope.isTimeEnabled() || immutable.unscopedTimers != null;
768772
}
769773

770774
public boolean isMemUseTrackingEnabled() {
771-
return currentScope != null && currentScope.isMemUseTrackingEnabled();
775+
return currentScope != null && currentScope.isMemUseTrackingEnabled() || immutable.unscopedMemUseTrackers != null;
772776
}
773777

774778
public boolean isDumpEnabledForMethod() {
@@ -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
}

0 commit comments

Comments
 (0)