diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/AbstractCollectionPolicy.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/AbstractCollectionPolicy.java index fd8670301112..9ff4478e676e 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/AbstractCollectionPolicy.java +++ b/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(); diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/AdaptiveCollectionPolicy.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/AdaptiveCollectionPolicy.java index 9d83e35ef955..cb68b13bd8f9 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/AdaptiveCollectionPolicy.java +++ b/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++; diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/BasicCollectionPolicies.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/BasicCollectionPolicies.java index 8023715ea030..f84b08238937 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/BasicCollectionPolicies.java +++ b/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 diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/CollectionPolicy.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/CollectionPolicy.java index 4f446021466c..a8c22dcf5d68 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/CollectionPolicy.java +++ b/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); diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/GCImpl.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/GCImpl.java index dab9ee137f8a..0d46b2c66257 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/GCImpl.java +++ b/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) { diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/LibGraalCollectionPolicy.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/LibGraalCollectionPolicy.java index 623e0d9c5003..40e3944b7c7e 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/LibGraalCollectionPolicy.java +++ b/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 diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/ProportionateSpacesPolicy.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/ProportionateSpacesPolicy.java index beebfea4d001..099eaac47f9d 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/ProportionateSpacesPolicy.java +++ b/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 diff --git a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/Isolates.java b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/Isolates.java index 6260c3129520..7f120a28fe49 100644 --- a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/Isolates.java +++ b/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 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. diff --git a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/util/Timer.java b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/util/Timer.java index b503138c991a..637951ad1bdf 100644 --- a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/util/Timer.java +++ b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/util/Timer.java @@ -24,20 +24,19 @@ */ package com.oracle.svm.core.util; -import com.oracle.svm.core.Isolates; -import com.oracle.svm.core.Uninterruptible; - import static com.oracle.svm.core.Uninterruptible.CALLED_FROM_UNINTERRUPTIBLE_CODE; +import com.oracle.svm.core.Uninterruptible; + /** * An uninterruptible nanosecond-precision timer that can be started repeatedly. */ public class Timer implements AutoCloseable { private final String name; - private long startedNanos; - private long stoppedNanos; - private boolean wasStarted; - private boolean wasStopped; + private long lastStartedNanos; + private long lastStoppedNanos; + private boolean startedAtLeastOnce; + private boolean running; private long totalElapsedNanos; public Timer(String name) { @@ -54,32 +53,36 @@ public Timer start() { return startAt(System.nanoTime()); } + @Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true) + public boolean wasStartedAtLeastOnce() { + return startedAtLeastOnce; + } + + @Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true) + public boolean isRunning() { + return running; + } + @Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true) public Timer startAt(long nanoTime) { - /* - * GR-63365: assert !wasStarted : "Timer already started"; - */ - startedNanos = nanoTime; - wasStarted = true; - stoppedNanos = 0L; - wasStopped = false; + assert !running : "Timer already running"; + lastStartedNanos = nanoTime; + startedAtLeastOnce = true; + lastStoppedNanos = 0L; + running = true; return this; } @Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true) - public long startedNanos() { - if (!wasStarted) { - /* If a timer was not started, pretend it was started at the start of the VM. */ - assert startedNanos == 0; - return Isolates.getStartTimeNanos(); - } - return startedNanos; + public long lastStartedNanoTime() { + assert startedAtLeastOnce : "Timer not started"; + return lastStartedNanos; } @Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true) - public long stoppedNanos() { - assert wasStopped : "Timer not stopped"; - return stoppedNanos; + public long lastStoppedNanoTime() { + assert startedAtLeastOnce && !running : "Timer not stopped"; + return lastStoppedNanos; } @Override @@ -95,26 +98,16 @@ public void stop() { @Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true) public void stopAt(long nanoTime) { - /* - * GR-63365: assert !wasStopped : "Timer already stopped"; - */ - stoppedNanos = nanoTime; - wasStopped = true; - /* - * GR-63365: assert stoppedNanos >= startedNanos() : "Invalid stop time"; - */ - totalElapsedNanos += stoppedNanos - startedNanos(); + assert running : "Timer not running"; + assert nanoTime >= lastStartedNanoTime() : "Invalid stop time"; + lastStoppedNanos = nanoTime; + running = false; + totalElapsedNanos += lastStoppedNanos - lastStartedNanoTime(); } @Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true) public long lastIntervalNanos() { - assert wasStopped : "Timer not stopped"; - return stoppedNanos() - startedNanos(); - } - - @Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true) - public long lastIntervalMillis() { - return TimeUtils.roundNanosToMillis(lastIntervalNanos()); + return lastStoppedNanoTime() - lastStartedNanoTime(); } @Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true) @@ -122,20 +115,13 @@ public long totalNanos() { return totalElapsedNanos; } - @Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true) - public long totalMillis() { - return TimeUtils.roundNanosToMillis(totalNanos()); - } - @Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true) public void reset() { - /* - * GR-63365: assert wasStopped : "Attempting to reset a started timer"; - */ - startedNanos = 0L; - wasStarted = false; - stoppedNanos = 0L; - wasStopped = false; + assert !running : "Attempting to reset a running timer"; + lastStartedNanos = 0L; + startedAtLeastOnce = false; + lastStoppedNanos = 0L; + running = false; totalElapsedNanos = 0L; } }