Fix GC policy timers and enable timer assertions.

Author: peter-hofer

substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/AbstractCollectionPolicy.java

@@ -320,7 +320,7 @@ public int getTenuringAge() {
     }
 
     @Override
-    public void onCollectionBegin(boolean completeCollection, long requestingNanoTime) {
+    public void onCollectionBegin(boolean completeCollection, long beginNanoTime) {
         // Capture the fraction of bytes in aligned chunks at the start to include all allocated
         // (also dead) objects, because we use it to reserve aligned chunks for future allocations
         UnsignedWord youngChunkBytes = GCImpl.getAccounting().getYoungChunkBytesBefore();

substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/AdaptiveCollectionPolicy.java

@@ -28,6 +28,7 @@
 
 import org.graalvm.word.UnsignedWord;
 
+import com.oracle.svm.core.Isolates;
 import com.oracle.svm.core.Uninterruptible;
 import com.oracle.svm.core.heap.GCCause;
 import com.oracle.svm.core.util.BasedOnJDKFile;
@@ -356,6 +357,10 @@ private double decayingGcCost() { // decaying_gc_cost and decaying_major_gc_cost
         double decayedMajorGcCost = majorGcCost();
         double avgMajorInterval = avgMajorIntervalSeconds.getAverage();
         if (USE_ADAPTIVE_SIZE_DECAY_MAJOR_GC_COST && ADAPTIVE_SIZE_MAJOR_GC_DECAY_TIME_SCALE > 0 && avgMajorInterval > 0) {
+            /*
+             * This seems pointless or flawed for major GCs because this method is called at the end
+             * when majorTimer has only just been restarted.
+             */
             double secondsSinceMajor = secondsSinceMajorGc();
             if (secondsSinceMajor > 0 && secondsSinceMajor > ADAPTIVE_SIZE_MAJOR_GC_DECAY_TIME_SCALE * avgMajorInterval) {
                 double decayed = decayedMajorGcCost * (ADAPTIVE_SIZE_MAJOR_GC_DECAY_TIME_SCALE * avgMajorInterval) / secondsSinceMajor;
@@ -393,24 +398,31 @@ private static UnsignedWord spaceIncrement(UnsignedWord curSize, UnsignedWord pe
         return curSize.unsignedDivide(100).multiply(percentChange);
     }
 
+    /**
+     * Should not be called during a major collection itself because then, {@link #majorTimer} is
+     * repurposed to measure collection time (rather than time between collections).
+     */
     private double secondsSinceMajorGc() { // time_since_major_gc
-        return TimeUtils.nanosToSecondsDouble(System.nanoTime() - majorTimer.startedNanos());
+        return TimeUtils.nanosToSecondsDouble(System.nanoTime() - majorTimer.lastStartedNanoTime());
     }
 
     @Override
-    public void onCollectionBegin(boolean completeCollection, long requestingNanoTime) { // {major,minor}_collection_begin
+    public void onCollectionBegin(boolean completeCollection, long beginNanoTime) { // {major,minor}_collection_begin
         Timer timer = completeCollection ? majorTimer : minorTimer;
-        timer.stopAt(requestingNanoTime);
+        if (!timer.wasStartedAtLeastOnce()) {
+            long origin = Isolates.isStartTimeAssigned() ? Isolates.getStartTimeNanos() : beginNanoTime;
+            timer.startAt(origin);
+        }
+        timer.stopAt(beginNanoTime);
         if (completeCollection) {
-            latestMajorMutatorIntervalNanos = timer.totalNanos();
+            latestMajorMutatorIntervalNanos = timer.lastIntervalNanos();
         } else {
-            latestMinorMutatorIntervalNanos = timer.totalNanos();
+            latestMinorMutatorIntervalNanos = timer.lastIntervalNanos();
         }
 
-        timer.reset();
         timer.start(); // measure collection pause
 
-        super.onCollectionBegin(completeCollection, requestingNanoTime);
+        super.onCollectionBegin(completeCollection, beginNanoTime);
     }
 
     @Override
@@ -420,13 +432,13 @@ public void onCollectionEnd(boolean completeCollection, GCCause cause) { // {maj
 
         if (completeCollection) {
             updateCollectionEndAverages(avgMajorGcCost, avgMajorPause, majorCostEstimator, avgMajorIntervalSeconds,
-                            cause, latestMajorMutatorIntervalNanos, timer.totalNanos(), promoSize);
+                            cause, latestMajorMutatorIntervalNanos, timer.lastIntervalNanos(), promoSize);
             majorCount++;
             minorCountSinceMajorCollection = 0;
 
         } else {
             updateCollectionEndAverages(avgMinorGcCost, avgMinorPause, minorCostEstimator, null,
-                            cause, latestMinorMutatorIntervalNanos, timer.totalNanos(), edenSize);
+                            cause, latestMinorMutatorIntervalNanos, timer.lastIntervalNanos(), edenSize);
             minorCount++;
             minorCountSinceMajorCollection++;
 

substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/BasicCollectionPolicies.java

@@ -196,7 +196,7 @@ public int getTenuringAge() {
         }
 
         @Override
-        public void onCollectionBegin(boolean completeCollection, long requestingNanoTime) {
+        public void onCollectionBegin(boolean completeCollection, long beginNanoTime) {
         }
 
         @Override

substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/CollectionPolicy.java

@@ -209,7 +209,7 @@ static boolean shouldCollectYoungGenSeparately(boolean defaultValue) {
     int getTenuringAge();
 
     /** Called at the beginning of a collection, in the safepoint operation. */
-    void onCollectionBegin(boolean completeCollection, long requestingNanoTime);
+    void onCollectionBegin(boolean completeCollection, long beginNanoTime);
 
     /** Called before the end of a collection, in the safepoint operation. */
     void onCollectionEnd(boolean completeCollection, GCCause cause);

substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/GCImpl.java

@@ -238,8 +238,23 @@ private void collectOperation(CollectionVMOperationData data) {
         assert getCollectionEpoch().equal(data.getRequestingEpoch()) ||
                         data.getForceFullGC() && GCImpl.getAccounting().getCompleteCollectionCount() == data.getCompleteCollectionCount() : "unnecessary GC?";
 
-        timers.mutator.stopAt(data.getRequestingNanoTime());
+        /*
+         * We use the time of the GC request as the beginning of the collection because it includes
+         * the delay of entering a safepoint, which we want the policy to consider for GC cost.
+         * Other VM operations can run in between, but we expect them to have insignificant impact.
+         */
+        long beginNanoTime = data.getRequestingNanoTime();
+        if (getCollectionEpoch().notEqual(data.getRequestingEpoch())) {
+            /* Another GC happened since the GC request, use the current time instead. */
+            beginNanoTime = System.nanoTime();
+        }
+        if (!timers.mutator.wasStartedAtLeastOnce()) {
+            long origin = Isolates.isStartTimeAssigned() ? Isolates.getStartTimeNanos() : beginNanoTime;
+            timers.mutator.startAt(origin);
+        }
+        timers.mutator.stopAt(beginNanoTime);
         timers.resetAllExceptMutator();
+
         /* The type of collection will be determined later on. */
         completeCollection = false;
 
@@ -256,7 +271,7 @@ assert getCollectionEpoch().equal(data.getRequestingEpoch()) ||
 
             verifyHeap(Before);
 
-            boolean outOfMemory = collectImpl(cause, data.getRequestingNanoTime(), data.getForceFullGC());
+            boolean outOfMemory = collectImpl(cause, beginNanoTime, data.getForceFullGC());
             data.setOutOfMemory(outOfMemory);
 
             verifyHeap(After);
@@ -277,18 +292,17 @@ assert getCollectionEpoch().equal(data.getRequestingEpoch()) ||
         timers.mutator.start();
     }
 
-    private boolean collectImpl(GCCause cause, long requestingNanoTime, boolean forceFullGC) {
+    private boolean collectImpl(GCCause cause, long beginNanoTime, boolean forceFullGC) {
         boolean outOfMemory;
         long startTicks = JfrTicks.elapsedTicks();
         try {
-            outOfMemory = doCollectImpl(cause, requestingNanoTime, forceFullGC, false);
+            outOfMemory = doCollectImpl(cause, beginNanoTime, forceFullGC, false);
             if (outOfMemory) {
-                // Avoid running out of memory with a full GC that reclaims softly reachable
-                // objects
+                // Avoid running out of memory with a full GC that reclaims softly reachable objects
                 ReferenceObjectProcessing.setSoftReferencesAreWeak(true);
                 try {
                     verifyHeap(During);
-                    outOfMemory = doCollectImpl(cause, requestingNanoTime, true, true);
+                    outOfMemory = doCollectImpl(cause, System.nanoTime(), true, true);
                 } finally {
                     ReferenceObjectProcessing.setSoftReferencesAreWeak(false);
                 }
@@ -299,7 +313,7 @@ private boolean collectImpl(GCCause cause, long requestingNanoTime, boolean forc
         return outOfMemory;
     }
 
-    private boolean doCollectImpl(GCCause cause, long requestingNanoTime, boolean forceFullGC, boolean forceNoIncremental) {
+    private boolean doCollectImpl(GCCause cause, long initialBeginNanoTime, boolean forceFullGC, boolean forceNoIncremental) {
         checkSanityBeforeCollection();
 
         ChunkBasedCommittedMemoryProvider.get().beforeGarbageCollection();
@@ -310,19 +324,21 @@ private boolean doCollectImpl(GCCause cause, long requestingNanoTime, boolean fo
         if (incremental) {
             long startTicks = JfrGCEvents.startGCPhasePause();
             try {
-                outOfMemory = doCollectOnce(cause, requestingNanoTime, false, false);
+                outOfMemory = doCollectOnce(cause, initialBeginNanoTime, false, false);
             } finally {
                 JfrGCEvents.emitGCPhasePauseEvent(getCollectionEpoch(), "Incremental GC", startTicks);
             }
         }
         if (!incremental || outOfMemory || forceFullGC || policy.shouldCollectCompletely(incremental)) {
-            if (incremental) { // uncommit unaligned chunks
-                ChunkBasedCommittedMemoryProvider.get().uncommitUnusedMemory();
+            long beginNanoTime = initialBeginNanoTime;
+            if (incremental) {
+                beginNanoTime = System.nanoTime();
+                ChunkBasedCommittedMemoryProvider.get().uncommitUnusedMemory(); // unaligned chunks
                 verifyHeap(During);
             }
             long startTicks = JfrGCEvents.startGCPhasePause();
             try {
-                outOfMemory = doCollectOnce(cause, requestingNanoTime, true, incremental);
+                outOfMemory = doCollectOnce(cause, beginNanoTime, true, incremental);
             } finally {
                 JfrGCEvents.emitGCPhasePauseEvent(getCollectionEpoch(), "Full GC", startTicks);
             }
@@ -335,13 +351,13 @@ private boolean doCollectImpl(GCCause cause, long requestingNanoTime, boolean fo
         return outOfMemory;
     }
 
-    private boolean doCollectOnce(GCCause cause, long requestingNanoTime, boolean complete, boolean followsIncremental) {
+    private boolean doCollectOnce(GCCause cause, long beginNanoTime, boolean complete, boolean followsIncremental) {
         assert !followsIncremental || complete : "An incremental collection cannot be followed by another incremental collection";
         assert !completeCollection || complete : "After a complete collection, no further incremental collections may happen";
         completeCollection = complete;
 
         accounting.beforeCollectOnce(completeCollection);
-        policy.onCollectionBegin(completeCollection, requestingNanoTime);
+        policy.onCollectionBegin(completeCollection, beginNanoTime);
 
         doCollectCore(!complete);
         if (complete) {

substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/LibGraalCollectionPolicy.java

@@ -110,9 +110,9 @@ protected UnsignedWord getYoungSizeLimit(UnsignedWord maxHeap) {
     }
 
     @Override
-    public void onCollectionBegin(boolean completeCollection, long requestingNanoTime) {
+    public void onCollectionBegin(boolean completeCollection, long beginNanoTime) {
         sizeBefore = GCImpl.getChunkBytes();
-        super.onCollectionBegin(completeCollection, requestingNanoTime);
+        super.onCollectionBegin(completeCollection, beginNanoTime);
     }
 
     @Override

substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/ProportionateSpacesPolicy.java

@@ -85,7 +85,7 @@ public boolean shouldCollectCompletely(boolean followingIncrementalCollection) {
     }
 
     @Override
-    public void onCollectionBegin(boolean completeCollection, long requestingNanoTime) {
+    public void onCollectionBegin(boolean completeCollection, long beginNanoTime) {
     }
 
     @Override

substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/Isolates.java

@@ -76,6 +76,7 @@ public class Isolates {
     /* Only used if SpawnIsolates is disabled. */
     private static final CGlobalData<Pointer> SINGLE_ISOLATE_ALREADY_CREATED = CGlobalDataFactory.createWord();
 
+    private static boolean startTimesAssigned;
     private static long startTimeNanos;
     private static long initDoneTimeMillis;
     private static long isolateId = -1;
@@ -110,31 +111,35 @@ public static void assignIsolateId(boolean isFirstIsolate) {
     }
 
     public static void assignStartTime() {
-        assert startTimeNanos == 0 : startTimeNanos;
-        assert initDoneTimeMillis == 0 : initDoneTimeMillis;
+        assert !startTimesAssigned;
         startTimeNanos = System.nanoTime();
         initDoneTimeMillis = TimeUtils.currentTimeMillis();
+        startTimesAssigned = true;
     }
 
     /** Epoch-based timestamp. If possible, {@link #getStartTimeNanos()} should be used instead. */
     @Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true)
     public static long getInitDoneTimeMillis() {
-        assert initDoneTimeMillis != 0;
+        assert startTimesAssigned;
         return initDoneTimeMillis;
     }
 
     @Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true)
     public static long getUptimeMillis() {
-        assert startTimeNanos != 0;
-        return TimeUtils.millisSinceNanos(startTimeNanos);
+        return TimeUtils.millisSinceNanos(getStartTimeNanos());
     }
 
     @Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true)
     public static long getStartTimeNanos() {
-        assert startTimeNanos != 0;
+        assert startTimesAssigned;
         return startTimeNanos;
     }
 
+    @Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true)
+    public static boolean isStartTimeAssigned() {
+        return startTimesAssigned;
+    }
+
     /**
      * Gets an identifier for the current isolate that is guaranteed to be unique for the first
      * {@code 2^64 - 1} isolates in the process.