Skip to content

Commit ba71c4b

Browse files
peter-hoferpeter-hofer
committed
[GR-63365] Fix GC policy timers and enable timer assertions.
PullRequest: graal/22370
2 parents 5a24737 + e560402 commit ba71c4b

File tree

9 files changed

+106
-87
lines changed

9 files changed

+106
-87
lines changed

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -320,7 +320,7 @@ public int getTenuringAge() {
320320
}
321321

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

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

Lines changed: 21 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,7 @@
2828

2929
import org.graalvm.word.UnsignedWord;
3030

31+
import com.oracle.svm.core.Isolates;
3132
import com.oracle.svm.core.Uninterruptible;
3233
import com.oracle.svm.core.heap.GCCause;
3334
import com.oracle.svm.core.util.BasedOnJDKFile;
@@ -356,6 +357,10 @@ private double decayingGcCost() { // decaying_gc_cost and decaying_major_gc_cost
356357
double decayedMajorGcCost = majorGcCost();
357358
double avgMajorInterval = avgMajorIntervalSeconds.getAverage();
358359
if (USE_ADAPTIVE_SIZE_DECAY_MAJOR_GC_COST && ADAPTIVE_SIZE_MAJOR_GC_DECAY_TIME_SCALE > 0 && avgMajorInterval > 0) {
360+
/*
361+
* This seems pointless or flawed for major GCs because this method is called at the end
362+
* when majorTimer has only just been restarted.
363+
*/
359364
double secondsSinceMajor = secondsSinceMajorGc();
360365
if (secondsSinceMajor > 0 && secondsSinceMajor > ADAPTIVE_SIZE_MAJOR_GC_DECAY_TIME_SCALE * avgMajorInterval) {
361366
double decayed = decayedMajorGcCost * (ADAPTIVE_SIZE_MAJOR_GC_DECAY_TIME_SCALE * avgMajorInterval) / secondsSinceMajor;
@@ -393,24 +398,31 @@ private static UnsignedWord spaceIncrement(UnsignedWord curSize, UnsignedWord pe
393398
return curSize.unsignedDivide(100).multiply(percentChange);
394399
}
395400

401+
/**
402+
* Should not be called during a major collection itself because then, {@link #majorTimer} is
403+
* repurposed to measure collection time (rather than time between collections).
404+
*/
396405
private double secondsSinceMajorGc() { // time_since_major_gc
397-
return TimeUtils.nanosToSecondsDouble(System.nanoTime() - majorTimer.startedNanos());
406+
return TimeUtils.nanosToSecondsDouble(System.nanoTime() - majorTimer.lastStartedNanoTime());
398407
}
399408

400409
@Override
401-
public void onCollectionBegin(boolean completeCollection, long requestingNanoTime) { // {major,minor}_collection_begin
410+
public void onCollectionBegin(boolean completeCollection, long beginNanoTime) { // {major,minor}_collection_begin
402411
Timer timer = completeCollection ? majorTimer : minorTimer;
403-
timer.stopAt(requestingNanoTime);
412+
if (!timer.wasStartedAtLeastOnce()) {
413+
long origin = Isolates.isStartTimeAssigned() ? Isolates.getStartTimeNanos() : beginNanoTime;
414+
timer.startAt(origin);
415+
}
416+
timer.stopAt(beginNanoTime);
404417
if (completeCollection) {
405-
latestMajorMutatorIntervalNanos = timer.totalNanos();
418+
latestMajorMutatorIntervalNanos = timer.lastIntervalNanos();
406419
} else {
407-
latestMinorMutatorIntervalNanos = timer.totalNanos();
420+
latestMinorMutatorIntervalNanos = timer.lastIntervalNanos();
408421
}
409422

410-
timer.reset();
411423
timer.start(); // measure collection pause
412424

413-
super.onCollectionBegin(completeCollection, requestingNanoTime);
425+
super.onCollectionBegin(completeCollection, beginNanoTime);
414426
}
415427

416428
@Override
@@ -420,13 +432,13 @@ public void onCollectionEnd(boolean completeCollection, GCCause cause) { // {maj
420432

421433
if (completeCollection) {
422434
updateCollectionEndAverages(avgMajorGcCost, avgMajorPause, majorCostEstimator, avgMajorIntervalSeconds,
423-
cause, latestMajorMutatorIntervalNanos, timer.totalNanos(), promoSize);
435+
cause, latestMajorMutatorIntervalNanos, timer.lastIntervalNanos(), promoSize);
424436
majorCount++;
425437
minorCountSinceMajorCollection = 0;
426438

427439
} else {
428440
updateCollectionEndAverages(avgMinorGcCost, avgMinorPause, minorCostEstimator, null,
429-
cause, latestMinorMutatorIntervalNanos, timer.totalNanos(), edenSize);
441+
cause, latestMinorMutatorIntervalNanos, timer.lastIntervalNanos(), edenSize);
430442
minorCount++;
431443
minorCountSinceMajorCollection++;
432444

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -196,7 +196,7 @@ public int getTenuringAge() {
196196
}
197197

198198
@Override
199-
public void onCollectionBegin(boolean completeCollection, long requestingNanoTime) {
199+
public void onCollectionBegin(boolean completeCollection, long beginNanoTime) {
200200
}
201201

202202
@Override

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -209,7 +209,7 @@ static boolean shouldCollectYoungGenSeparately(boolean defaultValue) {
209209
int getTenuringAge();
210210

211211
/** Called at the beginning of a collection, in the safepoint operation. */
212-
void onCollectionBegin(boolean completeCollection, long requestingNanoTime);
212+
void onCollectionBegin(boolean completeCollection, long beginNanoTime);
213213

214214
/** Called before the end of a collection, in the safepoint operation. */
215215
void onCollectionEnd(boolean completeCollection, GCCause cause);

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

Lines changed: 30 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -239,8 +239,23 @@ private void collectOperation(CollectionVMOperationData data) {
239239
assert getCollectionEpoch().equal(data.getRequestingEpoch()) ||
240240
data.getForceFullGC() && GCImpl.getAccounting().getCompleteCollectionCount() == data.getCompleteCollectionCount() : "unnecessary GC?";
241241

242-
timers.mutator.stopAt(data.getRequestingNanoTime());
242+
/*
243+
* We use the time of the GC request as the beginning of the collection because it includes
244+
* the delay of entering a safepoint, which we want the policy to consider for GC cost.
245+
* Other VM operations can run in between, but we expect them to have insignificant impact.
246+
*/
247+
long beginNanoTime = data.getRequestingNanoTime();
248+
if (getCollectionEpoch().notEqual(data.getRequestingEpoch())) {
249+
/* Another GC happened since the GC request, use the current time instead. */
250+
beginNanoTime = System.nanoTime();
251+
}
252+
if (!timers.mutator.wasStartedAtLeastOnce()) {
253+
long origin = Isolates.isStartTimeAssigned() ? Isolates.getStartTimeNanos() : beginNanoTime;
254+
timers.mutator.startAt(origin);
255+
}
256+
timers.mutator.stopAt(beginNanoTime);
243257
timers.resetAllExceptMutator();
258+
244259
/* The type of collection will be determined later on. */
245260
completeCollection = false;
246261

@@ -257,7 +272,7 @@ assert getCollectionEpoch().equal(data.getRequestingEpoch()) ||
257272

258273
verifyHeap(Before);
259274

260-
boolean outOfMemory = collectImpl(cause, data.getRequestingNanoTime(), data.getForceFullGC());
275+
boolean outOfMemory = collectImpl(cause, beginNanoTime, data.getForceFullGC());
261276
data.setOutOfMemory(outOfMemory);
262277

263278
verifyHeap(After);
@@ -278,18 +293,17 @@ assert getCollectionEpoch().equal(data.getRequestingEpoch()) ||
278293
timers.mutator.start();
279294
}
280295

281-
private boolean collectImpl(GCCause cause, long requestingNanoTime, boolean forceFullGC) {
296+
private boolean collectImpl(GCCause cause, long beginNanoTime, boolean forceFullGC) {
282297
boolean outOfMemory;
283298
long startTicks = JfrTicks.elapsedTicks();
284299
try {
285-
outOfMemory = doCollectImpl(cause, requestingNanoTime, forceFullGC, false);
300+
outOfMemory = doCollectImpl(cause, beginNanoTime, forceFullGC, false);
286301
if (outOfMemory) {
287-
// Avoid running out of memory with a full GC that reclaims softly reachable
288-
// objects
302+
// Avoid running out of memory with a full GC that reclaims softly reachable objects
289303
ReferenceObjectProcessing.setSoftReferencesAreWeak(true);
290304
try {
291305
verifyHeap(During);
292-
outOfMemory = doCollectImpl(cause, requestingNanoTime, true, true);
306+
outOfMemory = doCollectImpl(cause, System.nanoTime(), true, true);
293307
} finally {
294308
ReferenceObjectProcessing.setSoftReferencesAreWeak(false);
295309
}
@@ -300,7 +314,7 @@ private boolean collectImpl(GCCause cause, long requestingNanoTime, boolean forc
300314
return outOfMemory;
301315
}
302316

303-
private boolean doCollectImpl(GCCause cause, long requestingNanoTime, boolean forceFullGC, boolean forceNoIncremental) {
317+
private boolean doCollectImpl(GCCause cause, long initialBeginNanoTime, boolean forceFullGC, boolean forceNoIncremental) {
304318
checkSanityBeforeCollection();
305319

306320
ChunkBasedCommittedMemoryProvider.get().beforeGarbageCollection();
@@ -311,19 +325,21 @@ private boolean doCollectImpl(GCCause cause, long requestingNanoTime, boolean fo
311325
if (incremental) {
312326
long startTicks = JfrGCEvents.startGCPhasePause();
313327
try {
314-
outOfMemory = doCollectOnce(cause, requestingNanoTime, false, false);
328+
outOfMemory = doCollectOnce(cause, initialBeginNanoTime, false, false);
315329
} finally {
316330
JfrGCEvents.emitGCPhasePauseEvent(getCollectionEpoch(), "Incremental GC", startTicks);
317331
}
318332
}
319333
if (!incremental || outOfMemory || forceFullGC || policy.shouldCollectCompletely(incremental)) {
320-
if (incremental) { // uncommit unaligned chunks
321-
ChunkBasedCommittedMemoryProvider.get().uncommitUnusedMemory();
334+
long beginNanoTime = initialBeginNanoTime;
335+
if (incremental) {
336+
beginNanoTime = System.nanoTime();
337+
ChunkBasedCommittedMemoryProvider.get().uncommitUnusedMemory(); // unaligned chunks
322338
verifyHeap(During);
323339
}
324340
long startTicks = JfrGCEvents.startGCPhasePause();
325341
try {
326-
outOfMemory = doCollectOnce(cause, requestingNanoTime, true, incremental);
342+
outOfMemory = doCollectOnce(cause, beginNanoTime, true, incremental);
327343
} finally {
328344
JfrGCEvents.emitGCPhasePauseEvent(getCollectionEpoch(), "Full GC", startTicks);
329345
}
@@ -336,13 +352,13 @@ private boolean doCollectImpl(GCCause cause, long requestingNanoTime, boolean fo
336352
return outOfMemory;
337353
}
338354

339-
private boolean doCollectOnce(GCCause cause, long requestingNanoTime, boolean complete, boolean followsIncremental) {
355+
private boolean doCollectOnce(GCCause cause, long beginNanoTime, boolean complete, boolean followsIncremental) {
340356
assert !followsIncremental || complete : "An incremental collection cannot be followed by another incremental collection";
341357
assert !completeCollection || complete : "After a complete collection, no further incremental collections may happen";
342358
completeCollection = complete;
343359

344360
accounting.beforeCollectOnce(completeCollection);
345-
policy.onCollectionBegin(completeCollection, requestingNanoTime);
361+
policy.onCollectionBegin(completeCollection, beginNanoTime);
346362

347363
doCollectCore(!complete);
348364
if (complete) {

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

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -110,9 +110,9 @@ protected UnsignedWord getYoungSizeLimit(UnsignedWord maxHeap) {
110110
}
111111

112112
@Override
113-
public void onCollectionBegin(boolean completeCollection, long requestingNanoTime) {
113+
public void onCollectionBegin(boolean completeCollection, long beginNanoTime) {
114114
sizeBefore = GCImpl.getChunkBytes();
115-
super.onCollectionBegin(completeCollection, requestingNanoTime);
115+
super.onCollectionBegin(completeCollection, beginNanoTime);
116116
}
117117

118118
@Override

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -85,7 +85,7 @@ public boolean shouldCollectCompletely(boolean followingIncrementalCollection) {
8585
}
8686

8787
@Override
88-
public void onCollectionBegin(boolean completeCollection, long requestingNanoTime) {
88+
public void onCollectionBegin(boolean completeCollection, long beginNanoTime) {
8989
}
9090

9191
@Override

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

Lines changed: 11 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -76,6 +76,7 @@ public class Isolates {
7676
/* Only used if SpawnIsolates is disabled. */
7777
private static final CGlobalData<Pointer> SINGLE_ISOLATE_ALREADY_CREATED = CGlobalDataFactory.createWord();
7878

79+
private static boolean startTimesAssigned;
7980
private static long startTimeNanos;
8081
private static long initDoneTimeMillis;
8182
private static long isolateId = -1;
@@ -110,31 +111,35 @@ public static void assignIsolateId(boolean isFirstIsolate) {
110111
}
111112

112113
public static void assignStartTime() {
113-
assert startTimeNanos == 0 : startTimeNanos;
114-
assert initDoneTimeMillis == 0 : initDoneTimeMillis;
114+
assert !startTimesAssigned;
115115
startTimeNanos = System.nanoTime();
116116
initDoneTimeMillis = TimeUtils.currentTimeMillis();
117+
startTimesAssigned = true;
117118
}
118119

119120
/** Epoch-based timestamp. If possible, {@link #getStartTimeNanos()} should be used instead. */
120121
@Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true)
121122
public static long getInitDoneTimeMillis() {
122-
assert initDoneTimeMillis != 0;
123+
assert startTimesAssigned;
123124
return initDoneTimeMillis;
124125
}
125126

126127
@Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true)
127128
public static long getUptimeMillis() {
128-
assert startTimeNanos != 0;
129-
return TimeUtils.millisSinceNanos(startTimeNanos);
129+
return TimeUtils.millisSinceNanos(getStartTimeNanos());
130130
}
131131

132132
@Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true)
133133
public static long getStartTimeNanos() {
134-
assert startTimeNanos != 0;
134+
assert startTimesAssigned;
135135
return startTimeNanos;
136136
}
137137

138+
@Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true)
139+
public static boolean isStartTimeAssigned() {
140+
return startTimesAssigned;
141+
}
142+
138143
/**
139144
* Gets an identifier for the current isolate that is guaranteed to be unique for the first
140145
* {@code 2^64 - 1} isolates in the process.

0 commit comments

Comments
 (0)