[GR-64493] Metric improvements

compiler/mx.compiler/suite.py

@@ -574,6 +574,7 @@
         "name" : "jdk.graal.compiler",
         "exports" : [
           """* to jdk.graal.compiler.libgraal,
+                  jdk.graal.compiler.management,
                   com.oracle.graal.graal_enterprise,
                   org.graalvm.nativeimage.pointsto,
                   org.graalvm.nativeimage.builder,
@@ -594,7 +595,7 @@
           "jdk.graal.compiler.nodes.graphbuilderconf to org.graalvm.nativeimage.driver,org.graalvm.nativeimage.librarysupport",
           "jdk.graal.compiler.options                to org.graalvm.nativeimage.driver,org.graalvm.nativeimage.junitsupport",
           "jdk.graal.compiler.phases.common          to org.graalvm.nativeimage.agent.tracing,org.graalvm.nativeimage.configure",
-          "jdk.graal.compiler.serviceprovider        to jdk.graal.compiler.management,org.graalvm.nativeimage.driver,org.graalvm.nativeimage.agent.jvmtibase,org.graalvm.nativeimage.agent.diagnostics",
+          "jdk.graal.compiler.serviceprovider        to org.graalvm.nativeimage.driver,org.graalvm.nativeimage.agent.jvmtibase,org.graalvm.nativeimage.agent.diagnostics",
           "jdk.graal.compiler.util.json              to org.graalvm.nativeimage.librarysupport,org.graalvm.nativeimage.agent.tracing,org.graalvm.nativeimage.configure,org.graalvm.nativeimage.driver",
         ],
         "uses" : [

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

@@ -27,18 +27,20 @@
 import static jdk.graal.compiler.serviceprovider.GraalServices.getCurrentThreadId;
 
 import java.io.IOException;
+import java.lang.management.GarbageCollectorMXBean;
 import java.lang.management.ManagementFactory;
 import java.nio.file.Files;
 import java.nio.file.Path;
 import java.util.List;
+import java.util.concurrent.TimeUnit;
 
-import com.sun.management.HotSpotDiagnosticMXBean;
-import jdk.graal.compiler.serviceprovider.JMXService;
-import jdk.graal.compiler.serviceprovider.ServiceProvider;
+import javax.management.MBeanServer;
 
+import com.sun.management.HotSpotDiagnosticMXBean;
 import com.sun.management.ThreadMXBean;
 
-import javax.management.MBeanServer;
+import jdk.graal.compiler.serviceprovider.JMXService;
+import jdk.graal.compiler.serviceprovider.ServiceProvider;
 
 /**
  * Implementation of {@link JMXService}.
@@ -96,6 +98,62 @@ protected void dumpHeap(String outputFile, boolean live) throws IOException {
         }
     }
 
+    /**
+     * Reports information about time in the garbage collector.
+     */
+    static class GCTimeStatisticsImpl implements GCTimeStatistics {
+
+        private final List<GarbageCollectorMXBean> gcs;
+        private final long startTimeNanos;
+        private final long beforeCount;
+        private final long beforeMillis;
+
+        GCTimeStatisticsImpl(List<GarbageCollectorMXBean> gcs) {
+            this.gcs = gcs;
+            long totalCount = 0;
+            long totalMillis = 0;
+            for (GarbageCollectorMXBean gc : gcs) {
+                totalCount += gc.getCollectionCount();
+                totalMillis += gc.getCollectionTime();
+            }
+            beforeCount = totalCount;
+            beforeMillis = totalMillis;
+            startTimeNanos = System.nanoTime();
+        }
+
+        @Override
+        public long getGCTimeMills() {
+            long afterMillis = 0;
+            for (GarbageCollectorMXBean gc : gcs) {
+                afterMillis += gc.getCollectionTime();
+            }
+            return afterMillis - beforeMillis;
+        }
+
+        @Override
+        public long getGCCount() {
+            long afterCount = 0;
+            for (GarbageCollectorMXBean gc : gcs) {
+                afterCount += gc.getCollectionCount();
+            }
+            return afterCount - beforeCount;
+        }
+
+        @Override
+        public long getElapsedTimeMillis() {
+            return TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startTimeNanos);
+        }
+    }
+
+    @Override
+    protected GCTimeStatistics getGCTimeStatistics() {
+        List<GarbageCollectorMXBean> gcs = ManagementFactory.getGarbageCollectorMXBeans();
+        if (gcs != null) {
+            return new GCTimeStatisticsImpl(gcs);
+        }
+        return null;
+    }
+
     private void initHotSpotMXBean() {
         if (hotspotMXBean == null) {
             synchronized (this) {

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

@@ -38,6 +38,7 @@
 import jdk.graal.compiler.options.OptionType;
 import jdk.graal.compiler.options.OptionValues;
 import jdk.graal.compiler.serviceprovider.GraalServices;
+import jdk.graal.compiler.serviceprovider.JMXService;
 import jdk.vm.ci.meta.ResolvedJavaMethod;
 
 /**
@@ -73,6 +74,11 @@ public static class Options {
     private CompilationAlarm(double period) {
         this.previous = currentAlarm.get();
         reset(period);
+        JMXService.GCTimeStatistics timing = null;
+        if (period != 0) {
+            timing = GraalServices.getGCTimeStatistics();
+        }
+        this.gcTiming = timing;
     }
 
     /**
@@ -190,7 +196,13 @@ public void checkExpiration() {
             cloneTree.durationNS = elapsed();
             printTree("", sb, cloneTree, true);
 
-            throw new PermanentBailoutException("Compilation exceeded %.3f seconds. %n Phase timings:%n %s <===== TIMEOUT HERE", period, sb.toString().trim());
+            // Include information about time spent in the GC if it's available.
+            String gcMessage = "";
+            if (gcTiming != null) {
+                gcMessage = String.format(" (GC time is %s ms of %s ms elapsed)", gcTiming.getGCTimeMills(), gcTiming.getElapsedTimeMillis());
+            }
+
+            throw new PermanentBailoutException("Compilation exceeded %.3f seconds%s. %n Phase timings:%n %s <===== TIMEOUT HERE", period, gcMessage, sb.toString().trim());
         }
     }
 
@@ -210,6 +222,11 @@ public void close() {
      */
     private long expirationNS;
 
+    /**
+     * Time spent in the garbage collector if it's available.
+     */
+    private final JMXService.GCTimeStatistics gcTiming;
+
     /**
      * Signal the execution of the phase identified by {@code name} starts.
      */

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

@@ -48,6 +48,16 @@ public TimeUnit getTimeUnit() {
             return accm.getTimeUnit();
         }
 
+        @Override
+        public void add(DebugContext debug, long value, TimeUnit units) {
+            accm.add(debug, value, units);
+        }
+
+        @Override
+        public boolean isEnabled(DebugContext debug) {
+            return accm.isEnabled(debug);
+        }
+
         @Override
         public DebugCloseable start(DebugContext debug) {
             return accm.start(debug);
@@ -90,6 +100,18 @@ public DebugCloseable start(DebugContext debug) {
         }
     }
 
+    @Override
+    public void add(DebugContext debug, long value, TimeUnit units) {
+        if (debug.isTimerEnabled(this)) {
+            addToCurrentValue(debug, getTimeUnit().convert(value, units));
+        }
+    }
+
+    @Override
+    public boolean isEnabled(DebugContext debug) {
+        return debug.isTimerEnabled(this);
+    }
+
     @Override
     public TimerKey getFlat() {
         return (FlatTimer) flat;

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

@@ -36,7 +36,6 @@
 import java.util.Map;
 
 import jdk.graal.compiler.options.OptionValues;
-
 import jdk.vm.ci.code.BailoutException;
 import jdk.vm.ci.meta.JavaMethod;
 
@@ -47,7 +46,7 @@ final class DebugConfigImpl implements DebugConfig {
     private final DebugFilter countFilter;
     private final DebugFilter logFilter;
     private final DebugFilter trackMemUseFilter;
-    private final DebugFilter timerFilter;
+    private final DebugFilter timeFilter;
     private final DebugFilter dumpFilter;
     private final DebugFilter verifyFilter;
     private final MethodFilter methodFilter;
@@ -76,7 +75,7 @@ final class DebugConfigImpl implements DebugConfig {
                     String logFilter,
                     String countFilter,
                     String trackMemUseFilter,
-                    String timerFilter,
+                    String timeFilter,
                     String dumpFilter,
                     String verifyFilter,
                     String methodFilter,
@@ -87,7 +86,7 @@ final class DebugConfigImpl implements DebugConfig {
         this.logFilter = DebugFilter.parse(logFilter);
         this.countFilter = DebugFilter.parse(countFilter);
         this.trackMemUseFilter = DebugFilter.parse(trackMemUseFilter);
-        this.timerFilter = DebugFilter.parse(timerFilter);
+        this.timeFilter = DebugFilter.parse(timeFilter);
         this.dumpFilter = DebugFilter.parse(dumpFilter);
         this.verifyFilter = DebugFilter.parse(verifyFilter);
         if (methodFilter == null || methodFilter.isEmpty()) {
@@ -147,7 +146,7 @@ public boolean isVerifyEnabled(DebugContext.Scope scope) {
 
     @Override
     public boolean isTimeEnabled(DebugContext.Scope scope) {
-        return isEnabled(scope, timerFilter);
+        return isEnabled(scope, timeFilter);
     }
 
     @Override
@@ -161,13 +160,14 @@ public PrintStream output() {
     }
 
     private boolean isEnabled(DebugContext.Scope scope, DebugFilter filter) {
-        return getLevel(scope, filter) > 0;
+        return getLevel(scope, filter) >= 0;
     }
 
     private int getLevel(DebugContext.Scope scope, DebugFilter filter) {
         int level;
         if (filter == null) {
-            level = 0;
+            // null means the value has not been set
+            level = -1;
         } else {
             level = filter.matchLevel(scope);
         }
@@ -219,7 +219,7 @@ public String toString() {
         sb.append("Debug config:");
         add(sb, "Log", logFilter);
         add(sb, "Count", countFilter);
-        add(sb, "Time", timerFilter);
+        add(sb, "Time", timeFilter);
         add(sb, "Dump", dumpFilter);
         add(sb, "MethodFilter", methodFilter);
         return sb.toString();

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

@@ -665,7 +665,7 @@ private DebugContext(Description description,
             }
             currentScope = new ScopeImpl(this, Thread.currentThread(), DebugOptions.DisableIntercept.getValue(options));
             currentScope.updateFlags(currentConfig);
-            metricsEnabled = true;
+            metricsEnabled = !disableConfig;
         } else {
             metricsEnabled = immutable.hasUnscopedMetrics() || immutable.listMetrics;
         }
@@ -764,11 +764,15 @@ public boolean isVerifyEnabled() {
     }
 
     public boolean isCountEnabled() {
-        return currentScope != null && currentScope.isCountEnabled();
+        return currentScope != null && currentScope.isCountEnabled() || immutable.unscopedCounters != null;
+    }
+
+    public boolean isTimeEnabled() {
+        return currentScope != null && currentScope.isTimeEnabled() || immutable.unscopedTimers != null;
     }
 
     public boolean isMemUseTrackingEnabled() {
-        return currentScope != null && currentScope.isMemUseTrackingEnabled();
+        return currentScope != null && currentScope.isMemUseTrackingEnabled() || immutable.unscopedMemUseTrackers != null;
     }
 
     public boolean isDumpEnabledForMethod() {
@@ -1887,6 +1891,28 @@ public static CounterKey counter(CharSequence name) {
         return createCounter("%s", name, null);
     }
 
+    public static CountingTimerKey countingTimer(CharSequence name) {
+        return new CountingTimerKey(name);
+    }
+
+    /**
+     * Tracks both the number of times a timer was started and the elapsed time.
+     */
+    public static class CountingTimerKey {
+        CounterKey count;
+        TimerKey time;
+
+        CountingTimerKey(CharSequence name) {
+            count = DebugContext.counter(name + "Count");
+            time = DebugContext.timer(name + "Time");
+        }
+
+        public DebugCloseable start(DebugContext debug) {
+            count.add(debug, 1);
+            return time.start(debug);
+        }
+    }
+
     /**
      * Gets a tally of the metric values in this context and a given tally.
      *
@@ -2316,7 +2342,7 @@ public void printMetrics(Description desc) {
             ByteArrayOutputStream baos = new ByteArrayOutputStream(metricsBufSize);
             PrintStream out = new PrintStream(baos);
             if (metricsFile.endsWith(".csv") || metricsFile.endsWith(".CSV")) {
-                printMetricsCSV(out, compilable, identity, compilationNr, desc.identifier);
+                printMetricsCSV(out, compilable, identity, compilationNr, desc.identifier, DebugOptions.OmitZeroMetrics.getValue(getOptions()));
             } else {
                 printMetrics(out, compilable, identity, compilationNr, desc.identifier);
             }
@@ -2345,8 +2371,9 @@ public void printMetrics(Description desc) {
      * @param compilationNr where this compilation lies in the ordered sequence of all compilations
      *            identified by {@code identity}
      * @param compilationId the runtime issued identifier for the compilation
+     * @param skipZero
      */
-    private void printMetricsCSV(PrintStream out, Object compilable, Integer identity, int compilationNr, String compilationId) {
+    private void printMetricsCSV(PrintStream out, Object compilable, Integer identity, int compilationNr, String compilationId, boolean skipZero) {
         String compilableName = compilable instanceof JavaMethod ? ((JavaMethod) compilable).format("%H.%n(%p)%R") : String.valueOf(compilable);
         String csvFormat = CSVUtil.buildFormatString("%s", "%s", "%d", "%s");
         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
         for (MetricKey key : KeyRegistry.getKeys()) {
             int index = ((AbstractKey) key).getIndex();
             if (index < metricValues.length) {
-                Pair<String, String> valueAndUnit = key.toCSVFormat(metricValues[index]);
-                CSVUtil.Escape.println(out, format, CSVUtil.Escape.escape(key.getName()), valueAndUnit.getLeft(), valueAndUnit.getRight());
+                long metricValue = metricValues[index];
+                if (skipZero && metricValue == 0) {
+                    continue;
+                }
+                Pair<String, String> valueAndUnit = key.toCSVFormat(metricValue);
+                CSVUtil.Escape.println(out, format, key.getName(), valueAndUnit.getLeft(), valueAndUnit.getRight());
             }
         }
     }

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

@@ -195,9 +195,12 @@ public enum OptimizationLogTarget {
                    "will not include metrics for compiler code that is not executed.", type = OptionType.Debug)
     public static final OptionKey<Boolean> ListMetrics = new OptionKey<>(false);
     @Option(help = """
-                   File to which metrics are dumped per compilation.
-                   A CSV format is used if the file ends with .csv otherwise a more
-                   human readable format is used. The fields in the CSV format are:
+                   File to which metrics are dumped per compilation at shutdown.
+                   A %p in the name will be replaced with a string identifying the process, usually the process id.
+                   A CSV format is used if the file ends with .csv otherwise a more human readable format is used.
+                   An empty argument causes metrics to be dumped to the console.
+
+                   The fields in the CSV format are:
                               compilable - method being compiled
                      compilable_identity - identity hash code of compilable
                           compilation_nr - where this compilation lies in the ordered
@@ -207,10 +210,16 @@ public enum OptimizationLogTarget {
                              metric_name - name of metric
                             metric_value - value of metric""", type = OptionType.Debug)
      public static final OptionKey<String> MetricsFile = new OptionKey<>(null);
-    @Option(help = "File to which aggregated metrics are dumped at shutdown. A CSV format is used if the file ends with .csv " +
-                   "otherwise a more human readable format is used. If not specified, metrics are dumped to the console.", type = OptionType.Debug)
+    @Option(help = """
+                   File to which aggregated metrics are dumped at shutdown.
+                   A %p in the name will be replaced with a string identifying the process, usually the process id.
+                   A CSV format is used if the file ends with .csv otherwise a more human readable format is used.
+                   An empty argument causes metrics to be dumped to the console.""", type = OptionType.Debug)
     public static final OptionKey<String> AggregatedMetricsFile = new OptionKey<>(null);
 
+    @Option(help = "Omit metrics with a zero value when writing CSV files.", type = OptionType.Debug)
+    public static final OptionKey<Boolean> OmitZeroMetrics = new OptionKey<>(true);
+
     @Option(help = "Enable debug output for stub code generation and snippet preparation.", type = OptionType.Debug)
     public static final OptionKey<Boolean> DebugStubsAndSnippets = new OptionKey<>(false);
     @Option(help = "Send compiler IR to dump handlers on error.", type = OptionType.Debug)