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 1f8e4b4308fd..dc8a0018e351 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 @@ -91,7 +91,7 @@ public boolean shouldCollectOnAllocation() { if (sizes == null) { return false; // updateSizeParameters() has never been called } - UnsignedWord edenUsed = HeapImpl.getHeapImpl().getAccounting().getEdenUsedBytes(); + UnsignedWord edenUsed = HeapImpl.getAccounting().getEdenUsedBytes(); return edenUsed.aboveOrEqual(edenSize); } @@ -144,8 +144,6 @@ protected void guaranteeSizeParametersInitialized() { @Override public void updateSizeParameters() { - PhysicalMemory.tryInitialize(); - SizeParameters params = computeSizeParameters(sizes); SizeParameters previous = sizes; if (previous != null && params.equal(previous)) { @@ -301,7 +299,7 @@ public int getTenuringAge() { public void onCollectionBegin(boolean completeCollection, long requestingNanoTime) { // 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.getGCImpl().getAccounting().getYoungChunkBytesBefore(); + UnsignedWord youngChunkBytes = GCImpl.getAccounting().getYoungChunkBytesBefore(); if (youngChunkBytes.notEqual(0)) { UnsignedWord youngAlignedChunkBytes = HeapImpl.getHeapImpl().getYoungGeneration().getAlignedChunkBytes(); avgYoungGenAlignedChunkFraction.sample(UnsignedUtils.toDouble(youngAlignedChunkBytes) / UnsignedUtils.toDouble(youngChunkBytes)); diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/AbstractMemoryPoolMXBean.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/AbstractMemoryPoolMXBean.java index f2a23be29ba3..1fc938b07098 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/AbstractMemoryPoolMXBean.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/AbstractMemoryPoolMXBean.java @@ -69,7 +69,9 @@ UnsignedWord getInitialValue() { abstract UnsignedWord getMaximumValue(); - abstract void afterCollection(GCAccounting accounting); + abstract void beforeCollection(); + + abstract void afterCollection(); MemoryUsage memoryUsage(UnsignedWord usedAndCommitted) { return new MemoryUsage(getInitialValue().rawValue(), usedAndCommitted.rawValue(), usedAndCommitted.rawValue(), getMaximumValue().rawValue()); 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 9175c859012b..d168ca473233 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 @@ -420,7 +420,7 @@ public void onCollectionEnd(boolean completeCollection, GCCause cause) { // {maj timer.reset(); timer.open(); - GCAccounting accounting = GCImpl.getGCImpl().getAccounting(); + GCAccounting accounting = GCImpl.getAccounting(); UnsignedWord oldLive = accounting.getOldGenerationAfterChunkBytes(); oldSizeExceededInPreviousCollection = oldLive.aboveThan(oldSize); 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 150aa514aac1..5ccb2f470eee 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 @@ -58,7 +58,7 @@ protected static UnsignedWord m(long bytes) { @Override public boolean shouldCollectOnAllocation() { - UnsignedWord youngUsed = HeapImpl.getHeapImpl().getAccounting().getYoungUsedBytes(); + UnsignedWord youngUsed = HeapImpl.getAccounting().getYoungUsedBytes(); return youngUsed.aboveOrEqual(getMaximumYoungGenerationSize()); } @@ -79,12 +79,6 @@ public void ensureSizeParametersInitialized() { @Override public void updateSizeParameters() { - // Sample the physical memory size, before the first GC but after some allocation. - UnsignedWord allocationBeforeUpdate = WordFactory.unsigned(SerialAndEpsilonGCOptions.AllocationBeforePhysicalMemorySize.getValue()); - if (GCImpl.getGCImpl().getCollectionEpoch().equal(WordFactory.zero()) && - HeapImpl.getHeapImpl().getAccounting().getYoungUsedBytes().aboveOrEqual(allocationBeforeUpdate)) { - PhysicalMemory.tryInitialize(); - } // Size parameters are recomputed from current values whenever they are queried } @@ -287,7 +281,7 @@ public boolean shouldCollectCompletely(boolean followingIncrementalCollection) { private UnsignedWord estimateUsedHeapAtNextIncrementalCollection() { UnsignedWord currentYoungBytes = HeapImpl.getHeapImpl().getYoungGeneration().getChunkBytes(); UnsignedWord maxYoungBytes = getMaximumYoungGenerationSize(); - UnsignedWord oldBytes = GCImpl.getGCImpl().getAccounting().getOldGenerationAfterChunkBytes(); + UnsignedWord oldBytes = GCImpl.getAccounting().getOldGenerationAfterChunkBytes(); return currentYoungBytes.add(maxYoungBytes).add(oldBytes); } @@ -295,7 +289,7 @@ private static boolean enoughTimeSpentOnIncrementalGCs() { int incrementalWeight = SerialGCOptions.PercentTimeInIncrementalCollection.getValue(); assert incrementalWeight >= 0 && incrementalWeight <= 100 : "BySpaceAndTimePercentTimeInIncrementalCollection should be in the range [0..100]."; - GCAccounting accounting = GCImpl.getGCImpl().getAccounting(); + GCAccounting accounting = GCImpl.getAccounting(); long actualIncrementalNanos = accounting.getIncrementalCollectionTotalNanos(); long completeNanos = accounting.getCompleteCollectionTotalNanos(); long totalNanos = actualIncrementalNanos + completeNanos; diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/ChunksAccounting.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/ChunksAccounting.java index 68c036cb640b..18f6f399f54f 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/ChunksAccounting.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/ChunksAccounting.java @@ -30,7 +30,6 @@ import org.graalvm.word.WordFactory; import com.oracle.svm.core.Uninterruptible; -import com.oracle.svm.core.log.Log; /** * Accounting for a {@link Space} or {@link Generation}. For the eden space, the values are @@ -84,12 +83,6 @@ public UnsignedWord getUnalignedChunkBytes() { return unalignedChunkBytes; } - void report(Log reportLog) { - reportLog.string("aligned: ").unsigned(getAlignedChunkBytes()).string("/").unsigned(alignedCount); - reportLog.string(" "); - reportLog.string("unaligned: ").unsigned(unalignedChunkBytes).string("/").unsigned(unalignedCount); - } - @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) void noteAlignedHeapChunk() { alignedCount++; diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/CompleteGarbageCollectorMXBean.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/CompleteGarbageCollectorMXBean.java index 5dc995d17974..c94f2f39d819 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/CompleteGarbageCollectorMXBean.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/CompleteGarbageCollectorMXBean.java @@ -48,12 +48,12 @@ public CompleteGarbageCollectorMXBean() { @Override public long getCollectionCount() { - return HeapImpl.getGCImpl().getAccounting().getCompleteCollectionCount(); + return GCImpl.getAccounting().getCompleteCollectionCount(); } @Override public long getCollectionTime() { - long nanos = HeapImpl.getGCImpl().getAccounting().getCompleteCollectionTotalNanos(); + long nanos = GCImpl.getAccounting().getCompleteCollectionTotalNanos(); return TimeUtils.roundNanosToMillis(nanos); } diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/GCAccounting.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/GCAccounting.java index 2e6fe5860f86..0a861933dd07 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/GCAccounting.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/GCAccounting.java @@ -33,7 +33,10 @@ import com.oracle.svm.core.Uninterruptible; /** - * This data is only updated during a GC. + * Note that this data may be updated up to 3 times during a single VM operation (incremental GC, + * full GC, full GC that treats soft references as weak). Therefore, this class should only be used + * by GC internal code that is aware of this (could result in incorrect "before"/"after" values + * otherwise). Non-GC code should use the class {@link HeapAccounting} instead. * * ChunkBytes refer to bytes reserved (but maybe not occupied). ObjectBytes refer to bytes occupied * by objects. @@ -50,10 +53,7 @@ public final class GCAccounting { private boolean lastIncrementalCollectionOverflowedSurvivors = false; /* Before and after measures. */ - private UnsignedWord edenChunkBytesBefore = WordFactory.zero(); - private UnsignedWord edenChunkBytesAfter = WordFactory.zero(); private UnsignedWord youngChunkBytesBefore = WordFactory.zero(); - private UnsignedWord youngChunkBytesAfter = WordFactory.zero(); private UnsignedWord oldChunkBytesBefore = WordFactory.zero(); private UnsignedWord oldChunkBytesAfter = WordFactory.zero(); @@ -78,10 +78,6 @@ public long getIncrementalCollectionTotalNanos() { return incrementalCollectionTotalNanos; } - UnsignedWord getTotalAllocatedChunkBytes() { - return totalAllocatedChunkBytes; - } - public long getCompleteCollectionCount() { return completeCollectionCount; } @@ -90,6 +86,10 @@ public long getCompleteCollectionTotalNanos() { return completeCollectionTotalNanos; } + UnsignedWord getTotalAllocatedChunkBytes() { + return totalAllocatedChunkBytes; + } + UnsignedWord getTotalCollectedChunkBytes() { return totalCollectedChunkBytes; } @@ -102,26 +102,14 @@ UnsignedWord getAllocatedObjectBytes() { return allocatedObjectBytes; } - public UnsignedWord getOldGenerationAfterChunkBytes() { + UnsignedWord getOldGenerationAfterChunkBytes() { return oldChunkBytesAfter; } - UnsignedWord getEdenChunkBytesBefore() { - return edenChunkBytesBefore; - } - - UnsignedWord getEdenChunkBytesAfter() { - return edenChunkBytesAfter; - } - UnsignedWord getYoungChunkBytesBefore() { return youngChunkBytesBefore; } - UnsignedWord getYoungChunkBytesAfter() { - return youngChunkBytesAfter; - } - UnsignedWord getLastIncrementalCollectionPromotedChunkBytes() { return lastIncrementalCollectionPromotedChunkBytes; } @@ -136,7 +124,6 @@ void beforeCollection(boolean completeCollection) { YoungGeneration youngGen = heap.getYoungGeneration(); OldGeneration oldGen = heap.getOldGeneration(); - edenChunkBytesBefore = youngGen.getEden().getChunkBytes(); youngChunkBytesBefore = youngGen.getChunkBytes(); oldChunkBytesBefore = oldGen.getChunkBytes(); @@ -192,8 +179,7 @@ private void afterCollectionCommon() { YoungGeneration youngGen = heap.getYoungGeneration(); OldGeneration oldGen = heap.getOldGeneration(); - edenChunkBytesAfter = youngGen.getEden().getChunkBytes(); - youngChunkBytesAfter = youngGen.getChunkBytes(); + UnsignedWord youngChunkBytesAfter = youngGen.getChunkBytes(); oldChunkBytesAfter = oldGen.getChunkBytes(); UnsignedWord beforeChunkBytes = youngChunkBytesBefore.add(oldChunkBytesBefore); @@ -211,9 +197,14 @@ private void afterCollectionCommon() { if (SerialGCOptions.PrintGCSummary.getValue()) { UnsignedWord afterObjectBytesAfter = youngGen.computeObjectBytes().add(oldGen.computeObjectBytes()); UnsignedWord beforeObjectBytes = youngObjectBytesBefore.add(oldObjectBytesBefore); - assert beforeObjectBytes.aboveOrEqual(afterObjectBytesAfter); - UnsignedWord collectedObjectBytes = beforeObjectBytes.subtract(afterObjectBytesAfter); - totalCollectedObjectBytes = totalCollectedObjectBytes.add(collectedObjectBytes); + /* + * Object size may increase (e.g., identity hashcode field may be added to promoted + * objects). + */ + if (beforeObjectBytes.aboveOrEqual(afterObjectBytesAfter)) { + UnsignedWord collectedObjectBytes = beforeObjectBytes.subtract(afterObjectBytesAfter); + totalCollectedObjectBytes = totalCollectedObjectBytes.add(collectedObjectBytes); + } } } } 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 65415bf20647..818188e9a5d4 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 @@ -44,6 +44,7 @@ import org.graalvm.word.WordFactory; import com.oracle.svm.core.AlwaysInline; +import com.oracle.svm.core.Isolates; import com.oracle.svm.core.NeverInline; import com.oracle.svm.core.RuntimeAssertionsSupport; import com.oracle.svm.core.SubstrateGCOptions; @@ -61,6 +62,7 @@ import com.oracle.svm.core.deopt.Deoptimizer; import com.oracle.svm.core.genscavenge.AlignedHeapChunk.AlignedHeader; import com.oracle.svm.core.genscavenge.BasicCollectionPolicies.NeverCollect; +import com.oracle.svm.core.genscavenge.HeapAccounting.HeapSizes; import com.oracle.svm.core.genscavenge.HeapChunk.Header; import com.oracle.svm.core.genscavenge.UnalignedHeapChunk.UnalignedHeader; import com.oracle.svm.core.genscavenge.remset.RememberedSet; @@ -70,6 +72,7 @@ import com.oracle.svm.core.heap.GCCause; import com.oracle.svm.core.heap.NoAllocationVerifier; import com.oracle.svm.core.heap.OutOfMemoryUtil; +import com.oracle.svm.core.heap.PhysicalMemory; import com.oracle.svm.core.heap.ReferenceHandler; import com.oracle.svm.core.heap.ReferenceMapIndex; import com.oracle.svm.core.heap.RestrictHeapAccess; @@ -83,7 +86,6 @@ import com.oracle.svm.core.snippets.ImplicitExceptions; import com.oracle.svm.core.stack.JavaStackWalk; import com.oracle.svm.core.stack.JavaStackWalker; -import com.oracle.svm.core.stack.ThreadStackPrinter; import com.oracle.svm.core.thread.JavaVMOperation; import com.oracle.svm.core.thread.NativeVMOperation; import com.oracle.svm.core.thread.NativeVMOperationData; @@ -98,6 +100,9 @@ * Garbage collector (incremental or complete) for {@link HeapImpl}. */ public final class GCImpl implements GC { + private static final long K = 1024; + static final long M = K * K; + private final GreyToBlackObjRefVisitor greyToBlackObjRefVisitor = new GreyToBlackObjRefVisitor(); private final GreyToBlackObjectVisitor greyToBlackObjectVisitor = new GreyToBlackObjectVisitor(greyToBlackObjRefVisitor); private final RuntimeCodeCacheWalker runtimeCodeCacheWalker = new RuntimeCodeCacheWalker(greyToBlackObjRefVisitor); @@ -111,8 +116,6 @@ public final class GCImpl implements GC { private final CollectionPolicy policy; private boolean completeCollection = false; - private UnsignedWord sizeBefore = WordFactory.zero(); - private boolean collectionInProgress = false; private UnsignedWord collectionEpoch = WordFactory.zero(); private long lastWholeHeapExaminedTimeMillis = -1; @@ -144,7 +147,7 @@ public void collect(GCCause cause) { public void maybeCollectOnAllocation() { boolean outOfMemory = false; if (hasNeverCollectPolicy()) { - UnsignedWord edenUsed = HeapImpl.getHeapImpl().getAccounting().getEdenUsedBytes(); + UnsignedWord edenUsed = HeapImpl.getAccounting().getEdenUsedBytes(); outOfMemory = edenUsed.aboveThan(GCImpl.getPolicy().getMaximumHeapSize()); } else if (getPolicy().shouldCollectOnAllocation()) { outOfMemory = collectWithoutAllocating(GenScavengeGCCause.OnAllocation, false); @@ -193,35 +196,34 @@ private void enqueueCollectOperation(CollectionVMOperationData data) { /** The body of the VMOperation to do the collection. */ private void collectOperation(CollectionVMOperationData data) { - assert VMOperation.isGCInProgress() : "Collection should be a VMOperation."; + assert VMOperation.isGCInProgress(); assert getCollectionEpoch().equal(data.getRequestingEpoch()); timers.mutator.closeAt(data.getRequestingNanoTime()); - startCollectionOrExit(); - timers.resetAllExceptMutator(); - /* Flush all TLAB chunks to eden. */ - ThreadLocalAllocation.disableAndFlushForAllThreads(); - + JfrGCHeapSummaryEvent.emit(JfrGCWhen.BEFORE_GC); GCCause cause = GCCause.fromId(data.getCauseId()); - printGCBefore(cause.getName()); + printGCBefore(cause); + + ThreadLocalAllocation.disableAndFlushForAllThreads(); + GenScavengeMemoryPoolMXBeans.notifyBeforeCollection(); + HeapImpl.getAccounting().notifyBeforeCollection(); - JfrGCHeapSummaryEvent.emit(JfrGCWhen.BEFORE_GC); boolean outOfMemory = collectImpl(cause, data.getRequestingNanoTime(), data.getForceFullGC()); - JfrGCHeapSummaryEvent.emit(JfrGCWhen.AFTER_GC); + data.setOutOfMemory(outOfMemory); - printGCAfter(cause.getName()); + HeapImpl.getAccounting().notifyAfterCollection(); + GenScavengeMemoryPoolMXBeans.notifyAfterCollection(); - finishCollection(); - timers.mutator.open(); + printGCAfter(cause); + JfrGCHeapSummaryEvent.emit(JfrGCWhen.AFTER_GC); - data.setOutOfMemory(outOfMemory); + collectionEpoch = collectionEpoch.add(1); + timers.mutator.open(); } private boolean collectImpl(GCCause cause, long requestingNanoTime, boolean forceFullGC) { - HeapImpl.getHeapImpl().getAccounting().notifyBeforeCollection(); - boolean outOfMemory; long startTicks = JfrTicks.elapsedTicks(); try { @@ -239,9 +241,6 @@ private boolean collectImpl(GCCause cause, long requestingNanoTime, boolean forc } finally { JfrGCEvents.emitGarbageCollectionEvent(getCollectionEpoch(), cause, startTicks); } - - HeapImpl.getHeapImpl().getAccounting().notifyAfterCollection(this.accounting); - GenScavengeMemoryPoolMXBeans.notifyAfterCollection(this.accounting); return outOfMemory; } @@ -354,8 +353,9 @@ private String getGCKind() { } /** - * This value is only updated during a GC. Be careful when calling this method during a GC as it - * might wrongly include chunks that will be freed at the end of the GC. + * This value is only updated during a GC, so it may be outdated if called from outside the GC + * VM operation. Also be careful when calling this method during a GC as it might wrongly + * include chunks that will be freed at the end of the GC. */ public static UnsignedWord getChunkBytes() { UnsignedWord youngBytes = HeapImpl.getHeapImpl().getYoungGeneration().getChunkBytes(); @@ -363,83 +363,64 @@ public static UnsignedWord getChunkBytes() { return youngBytes.add(oldBytes); } - private void printGCBefore(String cause) { - Log verboseGCLog = Log.log(); - HeapImpl heap = HeapImpl.getHeapImpl(); - sizeBefore = ((SubstrateGCOptions.PrintGC.getValue() || SerialGCOptions.PrintHeapShape.getValue()) ? getChunkBytes() : WordFactory.zero()); - if (SubstrateGCOptions.VerboseGC.getValue() && getCollectionEpoch().equal(0)) { - verboseGCLog.string("[Heap policy parameters: ").newline(); - verboseGCLog.string(" YoungGenerationSize: ").unsigned(getPolicy().getMaximumYoungGenerationSize()).newline(); - verboseGCLog.string(" MaximumHeapSize: ").unsigned(getPolicy().getMaximumHeapSize()).newline(); - verboseGCLog.string(" MinimumHeapSize: ").unsigned(getPolicy().getMinimumHeapSize()).newline(); - verboseGCLog.string(" AlignedChunkSize: ").unsigned(HeapParameters.getAlignedHeapChunkSize()).newline(); - verboseGCLog.string(" LargeArrayThreshold: ").unsigned(HeapParameters.getLargeArrayThreshold()).string("]").newline(); - if (SerialGCOptions.PrintHeapShape.getValue()) { - HeapImpl.getHeapImpl().logImageHeapPartitionBoundaries(verboseGCLog); - } + private void printGCBefore(GCCause cause) { + if (!SubstrateGCOptions.VerboseGC.getValue()) { + return; } - if (SubstrateGCOptions.VerboseGC.getValue()) { - verboseGCLog.string("["); - verboseGCLog.string("["); - long startTime = System.nanoTime(); - if (SerialGCOptions.PrintGCTimeStamps.getValue()) { - verboseGCLog.unsigned(TimeUtils.roundNanosToMillis(Timer.getTimeSinceFirstAllocation(startTime))).string(" msec: "); + + if (getCollectionEpoch().equal(0)) { + printGCPrefixAndTime().string("Using ").string(getName()).newline(); + Log log = printGCPrefixAndTime().spaces(2).string("Memory: "); + if (!PhysicalMemory.isInitialized()) { + log.string("unknown").newline(); } else { - verboseGCLog.unsigned(startTime); + log.rational(PhysicalMemory.getCachedSize(), M, 0).string("M").newline(); } - verboseGCLog.string(" GC:").string(" before").string(" epoch: ").unsigned(getCollectionEpoch()).string(" cause: ").string(cause); - if (SerialGCOptions.PrintHeapShape.getValue()) { - heap.report(verboseGCLog); - } - verboseGCLog.string("]").newline(); + printGCPrefixAndTime().spaces(2).string("Heap policy: ").string(getPolicy().getName()).newline(); + printGCPrefixAndTime().spaces(2).string("Maximum young generation size: ").rational(getPolicy().getMaximumYoungGenerationSize(), M, 0).string("M").newline(); + printGCPrefixAndTime().spaces(2).string("Maximum heap size: ").rational(getPolicy().getMaximumHeapSize(), M, 0).string("M").newline(); + printGCPrefixAndTime().spaces(2).string("Minimum heap size: ").rational(getPolicy().getMinimumHeapSize(), M, 0).string("M").newline(); + printGCPrefixAndTime().spaces(2).string("Aligned chunk size: ").rational(HeapParameters.getAlignedHeapChunkSize(), K, 0).string("K").newline(); + printGCPrefixAndTime().spaces(2).string("Large array threshold: ").rational(HeapParameters.getLargeArrayThreshold(), K, 0).string("K").newline(); } + + printGCPrefixAndTime().string(cause.getName()).newline(); } - private void printGCAfter(String cause) { - Log verboseGCLog = Log.log(); - HeapImpl heap = HeapImpl.getHeapImpl(); - if (SubstrateGCOptions.PrintGC.getValue() || SubstrateGCOptions.VerboseGC.getValue()) { - if (SubstrateGCOptions.PrintGC.getValue()) { - Log printGCLog = Log.log(); - UnsignedWord sizeAfter = getChunkBytes(); - printGCLog.string("["); - if (SerialGCOptions.PrintGCTimeStamps.getValue()) { - long finishNanos = timers.collection.getClosedTime(); - printGCLog.unsigned(TimeUtils.roundNanosToMillis(Timer.getTimeSinceFirstAllocation(finishNanos))).string(" msec: "); - } - printGCLog.string(completeCollection ? "Full GC" : "Incremental GC"); - printGCLog.string(" (").string(cause).string(") "); - printGCLog.unsigned(sizeBefore.unsignedDivide(1024)); - printGCLog.string("K->"); - printGCLog.unsigned(sizeAfter.unsignedDivide(1024)).string("K, "); - printGCLog.rational(timers.collection.getMeasuredNanos(), TimeUtils.nanosPerSecond, 7).string(" secs"); - printGCLog.string("]").newline(); + private void printGCAfter(GCCause cause) { + HeapAccounting heapAccounting = HeapImpl.getAccounting(); + HeapSizes beforeGc = heapAccounting.getHeapSizesBeforeGc(); + + if (SubstrateGCOptions.VerboseGC.getValue()) { + printHeapSizeChange("Eden", beforeGc.eden, heapAccounting.getEdenUsedBytes()); + printHeapSizeChange("Survivor", beforeGc.survivor, heapAccounting.getSurvivorUsedBytes()); + printHeapSizeChange("Old", beforeGc.old, heapAccounting.getOldUsedBytes()); + printHeapSizeChange("Free", beforeGc.free, heapAccounting.getBytesInUnusedChunks()); + + if (SerialGCOptions.PrintGCTimes.getValue()) { + timers.logAfterCollection(Log.log()); } - if (SubstrateGCOptions.VerboseGC.getValue()) { - verboseGCLog.string(" ["); - long finishNanos = timers.collection.getClosedTime(); - if (SerialGCOptions.PrintGCTimeStamps.getValue()) { - verboseGCLog.unsigned(TimeUtils.roundNanosToMillis(Timer.getTimeSinceFirstAllocation(finishNanos))).string(" msec: "); - } else { - verboseGCLog.unsigned(finishNanos); - } - verboseGCLog.string(" GC:").string(" after ").string(" epoch: ").unsigned(getCollectionEpoch()).string(" cause: ").string(cause); - verboseGCLog.string(" policy: "); - verboseGCLog.string(getPolicy().getName()); - verboseGCLog.string(" type: ").string(completeCollection ? "complete" : "incremental"); - if (SerialGCOptions.PrintHeapShape.getValue()) { - heap.report(verboseGCLog); - } - if (!SerialGCOptions.PrintGCTimes.getValue()) { - verboseGCLog.newline(); - verboseGCLog.string(" collection time: ").unsigned(timers.collection.getMeasuredNanos()).string(" nanoSeconds"); - } else { - timers.logAfterCollection(verboseGCLog); - } - verboseGCLog.string("]"); - verboseGCLog.string("]").newline(); + + if (SerialGCOptions.TraceHeapChunks.getValue()) { + HeapImpl.getHeapImpl().logChunks(Log.log()); } } + + if (SubstrateGCOptions.PrintGC.getValue() || SubstrateGCOptions.VerboseGC.getValue()) { + String collectionType = completeCollection ? "Full GC" : "Incremental GC"; + printGCPrefixAndTime().string(collectionType).string(" (").string(cause.getName()).string(") ") + .rational(beforeGc.totalUsed(), M, 2).string("M->").rational(heapAccounting.getUsedBytes(), M, 2).string("M ") + .rational(timers.collection.getMeasuredNanos(), TimeUtils.nanosPerMilli, 3).string("ms").newline(); + } + } + + private void printHeapSizeChange(String text, UnsignedWord before, UnsignedWord after) { + printGCPrefixAndTime().string(" ").string(text).string(": ").rational(before, M, 2).string("M->").rational(after, M, 2).string("M").newline(); + } + + private Log printGCPrefixAndTime() { + long uptimeMs = Isolates.getCurrentUptimeMillis(); + return Log.log().string("[").rational(uptimeMs, TimeUtils.millisPerSecond, 3).string("s").string("] GC(").unsigned(collectionEpoch).string(") "); } private static void precondition() { @@ -451,62 +432,10 @@ private static void postcondition() { HeapImpl heap = HeapImpl.getHeapImpl(); YoungGeneration youngGen = heap.getYoungGeneration(); OldGeneration oldGen = heap.getOldGeneration(); - verbosePostCondition(); assert youngGen.getEden().isEmpty() : "youngGen.getEden() should be empty after a collection."; assert oldGen.getToSpace().isEmpty() : "oldGen.getToSpace() should be empty after a collection."; } - private static void verbosePostCondition() { - /* - * Note to self: I can get output similar to this *all the time* by running with - * -R:+VerboseGC -R:+PrintHeapShape -R:+TraceHeapChunks - */ - final boolean forceForTesting = false; - if (runtimeAssertions() || forceForTesting) { - HeapImpl heap = HeapImpl.getHeapImpl(); - YoungGeneration youngGen = heap.getYoungGeneration(); - OldGeneration oldGen = heap.getOldGeneration(); - - Log log = Log.log(); - if ((!youngGen.getEden().isEmpty()) || forceForTesting) { - log.string("[GCImpl.postcondition: Eden space should be empty after a collection.").newline(); - /* Print raw fields before trying to walk the chunk lists. */ - log.string(" These should all be 0:").newline(); - log.string(" Eden space first AlignedChunk: ").zhex(youngGen.getEden().getFirstAlignedHeapChunk()).newline(); - log.string(" Eden space last AlignedChunk: ").zhex(youngGen.getEden().getLastAlignedHeapChunk()).newline(); - log.string(" Eden space first UnalignedChunk: ").zhex(youngGen.getEden().getFirstUnalignedHeapChunk()).newline(); - log.string(" Eden space last UnalignedChunk: ").zhex(youngGen.getEden().getLastUnalignedHeapChunk()).newline(); - youngGen.getEden().report(log, true).newline(); - log.string("]").newline(); - } - for (int i = 0; i < HeapParameters.getMaxSurvivorSpaces(); i++) { - if ((!youngGen.getSurvivorToSpaceAt(i).isEmpty()) || forceForTesting) { - log.string("[GCImpl.postcondition: Survivor toSpace should be empty after a collection.").newline(); - /* Print raw fields before trying to walk the chunk lists. */ - log.string(" These should all be 0:").newline(); - log.string(" Survivor space ").signed(i).string(" first AlignedChunk: ").zhex(youngGen.getSurvivorToSpaceAt(i).getFirstAlignedHeapChunk()).newline(); - log.string(" Survivor space ").signed(i).string(" last AlignedChunk: ").zhex(youngGen.getSurvivorToSpaceAt(i).getLastAlignedHeapChunk()).newline(); - log.string(" Survivor space ").signed(i).string(" first UnalignedChunk: ").zhex(youngGen.getSurvivorToSpaceAt(i).getFirstUnalignedHeapChunk()).newline(); - log.string(" Survivor space ").signed(i).string(" last UnalignedChunk: ").zhex(youngGen.getSurvivorToSpaceAt(i).getLastUnalignedHeapChunk()).newline(); - youngGen.getSurvivorToSpaceAt(i).report(log, true).newline(); - log.string("]").newline(); - } - } - if ((!oldGen.getToSpace().isEmpty()) || forceForTesting) { - log.string("[GCImpl.postcondition: oldGen toSpace should be empty after a collection.").newline(); - /* Print raw fields before trying to walk the chunk lists. */ - log.string(" These should all be 0:").newline(); - log.string(" oldGen toSpace first AlignedChunk: ").zhex(oldGen.getToSpace().getFirstAlignedHeapChunk()).newline(); - log.string(" oldGen toSpace last AlignedChunk: ").zhex(oldGen.getToSpace().getLastAlignedHeapChunk()).newline(); - log.string(" oldGen.toSpace first UnalignedChunk: ").zhex(oldGen.getToSpace().getFirstUnalignedHeapChunk()).newline(); - log.string(" oldGen.toSpace last UnalignedChunk: ").zhex(oldGen.getToSpace().getLastUnalignedHeapChunk()).newline(); - oldGen.getToSpace().report(log, true).newline(); - oldGen.getFromSpace().report(log, true).newline(); - log.string("]").newline(); - } - } - } - @Fold static boolean runtimeAssertions() { return RuntimeAssertionsSupport.singleton().desiredAssertionStatus(GCImpl.class); @@ -1174,22 +1103,6 @@ private void releaseSpaces() { } } - @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) - boolean isCollectionInProgress() { - return collectionInProgress; - } - - private void startCollectionOrExit() { - CollectionInProgressError.exitIf(collectionInProgress); - collectionInProgress = true; - } - - private void finishCollection() { - assert collectionInProgress; - collectionEpoch = collectionEpoch.add(1); - collectionInProgress = false; - } - /** * Inside a VMOperation, we are not allowed to do certain things, e.g., perform synchronization * (because it can deadlock when a lock is held outside the VMOperation). Similar restrictions @@ -1219,15 +1132,16 @@ public long getMillisSinceLastWholeHeapExamined() { long startMillis; if (lastWholeHeapExaminedTimeMillis < 0) { // no full GC has yet been run, use time since the first allocation - startMillis = HeapImpl.getChunkProvider().getFirstAllocationTime() / 1_000_000; + startMillis = Isolates.getCurrentStartTimeMillis(); } else { startMillis = lastWholeHeapExaminedTimeMillis; } return System.currentTimeMillis() - startMillis; } - public GCAccounting getAccounting() { - return accounting; + @Fold + public static GCAccounting getAccounting() { + return GCImpl.getGCImpl().accounting; } @Fold @@ -1245,27 +1159,6 @@ GreyToBlackObjectVisitor getGreyToBlackObjectVisitor() { return greyToBlackObjectVisitor; } - /** Signals that a collection is already in progress. */ - @SuppressWarnings("serial") - static final class CollectionInProgressError extends Error { - static void exitIf(boolean state) { - if (state) { - /* Throw an error to capture the stack backtrace. */ - Log failure = Log.log(); - failure.string("[CollectionInProgressError:"); - failure.newline(); - ThreadStackPrinter.printBacktrace(); - failure.string("]").newline(); - throw CollectionInProgressError.SINGLETON; - } - } - - private CollectionInProgressError() { - } - - private static final CollectionInProgressError SINGLETON = new CollectionInProgressError(); - } - private static class CollectionVMOperation extends NativeVMOperation { private final NoAllocationVerifier noAllocationVerifier = NoAllocationVerifier.factory("CollectionVMOperation", false); @@ -1410,59 +1303,55 @@ private static > T getLast(T chunks) { } } - private void printGCSummary() { + private static void printGCSummary() { if (!SerialGCOptions.PrintGCSummary.getValue()) { return; } - Log log = Log.log(); - final String prefix = "PrintGCSummary: "; - - log.string(prefix).string("MaximumYoungGenerationSize: ").unsigned(getPolicy().getMaximumYoungGenerationSize()).newline(); - log.string(prefix).string("MinimumHeapSize: ").unsigned(getPolicy().getMinimumHeapSize()).newline(); - log.string(prefix).string("MaximumHeapSize: ").unsigned(getPolicy().getMaximumHeapSize()).newline(); - log.string(prefix).string("AlignedChunkSize: ").unsigned(HeapParameters.getAlignedHeapChunkSize()).newline(); - - FlushTLABsOperation vmOp = new FlushTLABsOperation(); + PrintGCSummaryOperation vmOp = new PrintGCSummaryOperation(); vmOp.enqueue(); - - HeapImpl heap = HeapImpl.getHeapImpl(); - Space edenSpace = heap.getYoungGeneration().getEden(); - UnsignedWord youngChunkBytes = edenSpace.getChunkBytes(); - UnsignedWord youngObjectBytes = edenSpace.computeObjectBytes(); - - UnsignedWord allocatedChunkBytes = accounting.getTotalAllocatedChunkBytes().add(youngChunkBytes); - UnsignedWord allocatedObjectBytes = accounting.getAllocatedObjectBytes().add(youngObjectBytes); - - log.string(prefix).string("CollectedTotalChunkBytes: ").signed(accounting.getTotalCollectedChunkBytes()).newline(); - log.string(prefix).string("CollectedTotalObjectBytes: ").signed(accounting.getTotalCollectedObjectBytes()).newline(); - log.string(prefix).string("AllocatedNormalChunkBytes: ").signed(allocatedChunkBytes).newline(); - log.string(prefix).string("AllocatedNormalObjectBytes: ").signed(allocatedObjectBytes).newline(); - - long incrementalNanos = accounting.getIncrementalCollectionTotalNanos(); - log.string(prefix).string("IncrementalGCCount: ").signed(accounting.getIncrementalCollectionCount()).newline(); - log.string(prefix).string("IncrementalGCNanos: ").signed(incrementalNanos).newline(); - long completeNanos = accounting.getCompleteCollectionTotalNanos(); - log.string(prefix).string("CompleteGCCount: ").signed(accounting.getCompleteCollectionCount()).newline(); - log.string(prefix).string("CompleteGCNanos: ").signed(completeNanos).newline(); - - long gcNanos = incrementalNanos + completeNanos; - long mutatorNanos = timers.mutator.getMeasuredNanos(); - long totalNanos = gcNanos + mutatorNanos; - long roundedGCLoad = (0 < totalNanos ? TimeUtils.roundedDivide(100 * gcNanos, totalNanos) : 0); - log.string(prefix).string("GCNanos: ").signed(gcNanos).newline(); - log.string(prefix).string("TotalNanos: ").signed(totalNanos).newline(); - log.string(prefix).string("GCLoadPercent: ").signed(roundedGCLoad).newline(); } - private static class FlushTLABsOperation extends JavaVMOperation { - protected FlushTLABsOperation() { - super(VMOperationInfos.get(FlushTLABsOperation.class, "Flush TLABs", SystemEffect.SAFEPOINT)); + private static class PrintGCSummaryOperation extends JavaVMOperation { + protected PrintGCSummaryOperation() { + super(VMOperationInfos.get(PrintGCSummaryOperation.class, "Print GC summary", SystemEffect.SAFEPOINT)); } @Override protected void operate() { ThreadLocalAllocation.disableAndFlushForAllThreads(); + + Log log = Log.log(); + log.string("GC summary").indent(true); + HeapImpl heap = HeapImpl.getHeapImpl(); + Space edenSpace = heap.getYoungGeneration().getEden(); + UnsignedWord youngChunkBytes = edenSpace.getChunkBytes(); + UnsignedWord youngObjectBytes = edenSpace.computeObjectBytes(); + + GCAccounting accounting = GCImpl.getAccounting(); + UnsignedWord allocatedChunkBytes = accounting.getTotalAllocatedChunkBytes().add(youngChunkBytes); + UnsignedWord allocatedObjectBytes = accounting.getAllocatedObjectBytes().add(youngObjectBytes); + + log.string("Collected chunk bytes: ").rational(accounting.getTotalCollectedChunkBytes(), M, 2).string("M").newline(); + log.string("Collected object bytes: ").rational(accounting.getTotalCollectedObjectBytes(), M, 2).string("M").newline(); + log.string("Allocated chunk bytes: ").rational(allocatedChunkBytes, M, 2).string("M").newline(); + log.string("Allocated object bytes: ").rational(allocatedObjectBytes, M, 2).string("M").newline(); + + long incrementalNanos = accounting.getIncrementalCollectionTotalNanos(); + log.string("Incremental GC count: ").signed(accounting.getIncrementalCollectionCount()).newline(); + log.string("Incremental GC time: ").rational(incrementalNanos, TimeUtils.nanosPerSecond, 3).string("s").newline(); + long completeNanos = accounting.getCompleteCollectionTotalNanos(); + log.string("Complete GC count: ").signed(accounting.getCompleteCollectionCount()).newline(); + log.string("Complete GC time: ").rational(completeNanos, TimeUtils.nanosPerSecond, 3).string("s").newline(); + + long gcNanos = incrementalNanos + completeNanos; + + long mutatorNanos = GCImpl.getGCImpl().timers.mutator.getMeasuredNanos(); + long totalNanos = gcNanos + mutatorNanos; + long roundedGCLoad = (0 < totalNanos ? TimeUtils.roundedDivide(100 * gcNanos, totalNanos) : 0); + log.string("GC time: ").rational(gcNanos, TimeUtils.nanosPerSecond, 3).string("s").newline(); + log.string("Run time: ").rational(totalNanos, TimeUtils.nanosPerSecond, 3).string("s").newline(); + log.string("GC load: ").signed(roundedGCLoad).string("%").indent(false); } } } diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/GenScavengeGCCause.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/GenScavengeGCCause.java index 3b921c4b1f1a..6db07ba2fb21 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/GenScavengeGCCause.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/GenScavengeGCCause.java @@ -27,7 +27,7 @@ import com.oracle.svm.core.heap.GCCause; final class GenScavengeGCCause extends GCCause { - public static final GCCause OnAllocation = new GenScavengeGCCause("CollectOnAllocation", 10); + public static final GCCause OnAllocation = new GenScavengeGCCause("Collect on allocation", 10); private GenScavengeGCCause(String name, int id) { super(name, id); diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/GenScavengeMemoryPoolMXBeans.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/GenScavengeMemoryPoolMXBeans.java index 5b224465dd72..c60fce4681b1 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/GenScavengeMemoryPoolMXBeans.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/GenScavengeMemoryPoolMXBeans.java @@ -66,9 +66,15 @@ public static MemoryPoolMXBean[] createMemoryPoolMXBeans() { return mxBeans; } - public static void notifyAfterCollection(GCAccounting accounting) { + public static void notifyBeforeCollection() { for (AbstractMemoryPoolMXBean mxBean : mxBeans) { - mxBean.afterCollection(accounting); + mxBean.beforeCollection(); + } + } + + public static void notifyAfterCollection() { + for (AbstractMemoryPoolMXBean mxBean : mxBeans) { + mxBean.afterCollection(); } } @@ -79,6 +85,16 @@ static final class EdenMemoryPoolMXBean extends AbstractMemoryPoolMXBean { super(EDEN_SPACE, managerNames); } + @Override + void beforeCollection() { + updatePeakUsage(HeapImpl.getAccounting().getEdenUsedBytes()); + } + + @Override + void afterCollection() { + /* Nothing to do. */ + } + @Override UnsignedWord computeInitialValue() { return GCImpl.getPolicy().getInitialEdenSize(); @@ -89,11 +105,6 @@ UnsignedWord getMaximumValue() { return GCImpl.getPolicy().getMaximumEdenSize(); } - @Override - void afterCollection(GCAccounting accounting) { - updatePeakUsage(accounting.getEdenChunkBytesBefore()); - } - @Override public MemoryUsage getUsage() { return memoryUsage(getCurrentUsage()); @@ -111,7 +122,7 @@ public MemoryUsage getCollectionUsage() { } private static UnsignedWord getCurrentUsage() { - return HeapImpl.getHeapImpl().getAccounting().getEdenUsedBytes(); + return HeapImpl.getAccounting().getEdenUsedBytes(); } } @@ -122,6 +133,16 @@ static final class SurvivorMemoryPoolMXBean extends AbstractMemoryPoolMXBean { super(SURVIVOR_SPACE, managerNames); } + @Override + void beforeCollection() { + /* Nothing to do. */ + } + + @Override + void afterCollection() { + updatePeakUsage(HeapImpl.getAccounting().getSurvivorUsedBytes()); + } + @Override UnsignedWord computeInitialValue() { return GCImpl.getPolicy().getInitialSurvivorSize(); @@ -132,11 +153,6 @@ UnsignedWord getMaximumValue() { return GCImpl.getPolicy().getMaximumSurvivorSize(); } - @Override - void afterCollection(GCAccounting accounting) { - updatePeakUsage(accounting.getYoungChunkBytesAfter()); - } - @Override public MemoryUsage getUsage() { return getCollectionUsage(); @@ -149,7 +165,7 @@ public MemoryUsage getPeakUsage() { @Override public MemoryUsage getCollectionUsage() { - return memoryUsage(GCImpl.getGCImpl().getAccounting().getYoungChunkBytesAfter()); + return memoryUsage(HeapImpl.getAccounting().getSurvivorUsedBytes()); } } @@ -160,6 +176,16 @@ static final class OldGenerationMemoryPoolMXBean extends AbstractMemoryPoolMXBea super(OLD_GEN_SPACE, managerNames); } + @Override + void beforeCollection() { + /* Nothing to do. */ + } + + @Override + void afterCollection() { + updatePeakUsage(HeapImpl.getAccounting().getOldUsedBytes()); + } + @Override UnsignedWord computeInitialValue() { return GCImpl.getPolicy().getInitialOldSize(); @@ -170,11 +196,6 @@ UnsignedWord getMaximumValue() { return GCImpl.getPolicy().getMaximumOldSize(); } - @Override - void afterCollection(GCAccounting accounting) { - updatePeakUsage(accounting.getOldGenerationAfterChunkBytes()); - } - @Override public MemoryUsage getUsage() { return getCollectionUsage(); @@ -187,7 +208,7 @@ public MemoryUsage getPeakUsage() { @Override public MemoryUsage getCollectionUsage() { - return memoryUsage(GCImpl.getGCImpl().getAccounting().getOldGenerationAfterChunkBytes()); + return memoryUsage(HeapImpl.getAccounting().getOldUsedBytes()); } } @@ -198,6 +219,16 @@ static final class EpsilonMemoryPoolMXBean extends AbstractMemoryPoolMXBean { super(EPSILON_HEAP, managerNames); } + @Override + void beforeCollection() { + throw VMError.shouldNotReachHereAtRuntime(); // ExcludeFromJacocoGeneratedReport + } + + @Override + void afterCollection() { + throw VMError.shouldNotReachHereAtRuntime(); // ExcludeFromJacocoGeneratedReport + } + @Override UnsignedWord computeInitialValue() { return GCImpl.getPolicy().getMinimumHeapSize(); @@ -208,15 +239,10 @@ UnsignedWord getMaximumValue() { return GCImpl.getPolicy().getMaximumHeapSize(); } - @Override - void afterCollection(GCAccounting accounting) { - throw VMError.shouldNotReachHereAtRuntime(); // ExcludeFromJacocoGeneratedReport - } - @Override public MemoryUsage getUsage() { - HeapImpl heapImpl = HeapImpl.getHeapImpl(); - return memoryUsage(heapImpl.getUsedBytes(), heapImpl.getCommittedBytes()); + HeapAccounting accounting = HeapImpl.getAccounting(); + return memoryUsage(accounting.getUsedBytes(), accounting.getCommittedBytes()); } @Override diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/Generation.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/Generation.java index e487a4c7f1d2..f109d30f4f3d 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/Generation.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/Generation.java @@ -53,8 +53,11 @@ public String getName() { return name; } - /** Report some statistics about the Generation to a Log. */ - public abstract Log report(Log log, boolean traceHeapChunks); + /** Print some heap statistics to a log. */ + public abstract void logUsage(Log log); + + /** Print some information about the chunks to the log. */ + public abstract void logChunks(Log log); /** * Promote an Object to this Generation, typically by copying and leaving a forwarding pointer diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapAccounting.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapAccounting.java index 0b38c250835d..e1b3153abcce 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapAccounting.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapAccounting.java @@ -33,6 +33,8 @@ import com.oracle.svm.core.thread.VMOperation; /** + * Provides data for the heap monitoring. All sizes are on chunk (and not on object) granularity. + * * @see GCAccounting * @see ChunksAccounting */ @@ -40,6 +42,8 @@ public final class HeapAccounting { private final UninterruptibleUtils.AtomicUnsigned edenUsedBytes = new UninterruptibleUtils.AtomicUnsigned(); private final UninterruptibleUtils.AtomicUnsigned youngUsedBytes = new UninterruptibleUtils.AtomicUnsigned(); + private final HeapSizes beforeGc = new HeapSizes(); + /* During a GC, the values are invalid. They are updated once the GC ends. */ private boolean invalidData; @@ -49,18 +53,36 @@ public final class HeapAccounting { public void notifyBeforeCollection() { assert VMOperation.isGCInProgress(); + assert !invalidData; + + /* Cache the values right before the GC. */ + beforeGc.eden = getEdenUsedBytes(); + beforeGc.survivor = getSurvivorUsedBytes(); + beforeGc.old = getOldUsedBytes(); + beforeGc.free = getBytesInUnusedChunks(); + + /* Sizes must match because TLABs were already added to eden. */ + assert edenUsedBytes.get().equal(HeapImpl.getHeapImpl().getYoungGeneration().getEden().getChunkBytes()); + assert youngUsedBytes.get().equal(HeapImpl.getHeapImpl().getYoungGeneration().getChunkBytes()); + invalidData = true; } - public void notifyAfterCollection(GCAccounting accounting) { + public void notifyAfterCollection() { assert VMOperation.isGCInProgress() : "would cause races otherwise"; assert invalidData; - youngUsedBytes.set(accounting.getYoungChunkBytesAfter()); - edenUsedBytes.set(accounting.getEdenChunkBytesAfter()); + youngUsedBytes.set(HeapImpl.getHeapImpl().getYoungGeneration().getChunkBytes()); + edenUsedBytes.set(HeapImpl.getHeapImpl().getYoungGeneration().getEden().getChunkBytes()); + assert edenUsedBytes.get().equal(0); + invalidData = false; } + HeapSizes getHeapSizesBeforeGc() { + return beforeGc; + } + @Uninterruptible(reason = "Must be done during TLAB registration to not race with a potential collection.", callerMustBe = true) public void increaseEdenUsedBytes(UnsignedWord value) { youngUsedBytes.addAndGet(value); @@ -68,19 +90,64 @@ public void increaseEdenUsedBytes(UnsignedWord value) { } @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) - public UnsignedWord getYoungUsedBytes() { + public UnsignedWord getEdenUsedBytes() { assert !invalidData : "value is incorrect during a GC"; - return youngUsedBytes.get(); + return edenUsedBytes.get(); + } + + @Uninterruptible(reason = "Necessary to return a reasonably consistent value (a GC can change the queried values).") + @SuppressWarnings("static-method") + public UnsignedWord getSurvivorUsedBytes() { + return HeapImpl.getHeapImpl().getYoungGeneration().getSurvivorChunkBytes(); + } + + @Uninterruptible(reason = "Necessary to return a reasonably consistent value (a GC can change the queried values).") + @SuppressWarnings("static-method") + public UnsignedWord getSurvivorUsedBytes(int survivorIndex) { + return HeapImpl.getHeapImpl().getYoungGeneration().getSurvivorChunkBytes(survivorIndex); } @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) - public UnsignedWord getEdenUsedBytes() { + public UnsignedWord getYoungUsedBytes() { assert !invalidData : "value is incorrect during a GC"; - return edenUsedBytes.get(); + return youngUsedBytes.get(); } + @Uninterruptible(reason = "Necessary to return a reasonably consistent value (a GC can change the queried values).") @SuppressWarnings("static-method") - public UnsignedWord getSurvivorSpaceAfterChunkBytes(int survivorIndex) { - return HeapImpl.getHeapImpl().getYoungGeneration().getSurvivorFromSpaceAt(survivorIndex).getChunkBytes(); + public UnsignedWord getOldUsedBytes() { + return HeapImpl.getHeapImpl().getOldGeneration().getChunkBytes(); + } + + @Uninterruptible(reason = "Necessary to return a reasonably consistent value (a GC can change the queried values).") + @SuppressWarnings("static-method") + public UnsignedWord getUsedBytes() { + return getOldUsedBytes().add(getYoungUsedBytes()); + } + + @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) + @SuppressWarnings("static-method") + public UnsignedWord getBytesInUnusedChunks() { + return HeapImpl.getChunkProvider().getBytesInUnusedChunks(); + } + + @Uninterruptible(reason = "Necessary to return a reasonably consistent value (a GC can change the queried values).") + public UnsignedWord getCommittedBytes() { + return getUsedBytes().add(getBytesInUnusedChunks()); + } + + static class HeapSizes { + UnsignedWord eden; + UnsignedWord survivor; + UnsignedWord old; + UnsignedWord free; + + @Platforms(Platform.HOSTED_ONLY.class) + HeapSizes() { + } + + public UnsignedWord totalUsed() { + return eden.add(survivor).add(old); + } } } diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapChunkLogging.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapChunkLogging.java index 63204dfdd285..41297bf827ea 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapChunkLogging.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapChunkLogging.java @@ -24,19 +24,27 @@ */ package com.oracle.svm.core.genscavenge; +import static com.oracle.svm.core.log.Log.RIGHT_ALIGN; + +import org.graalvm.word.Pointer; +import org.graalvm.word.UnsignedWord; + import com.oracle.svm.core.log.Log; class HeapChunkLogging { private static final int MAX_CHUNKS_TO_PRINT = 64 * 1024; - public static void logChunks(Log log, AlignedHeapChunk.AlignedHeader firstChunk) { + public static void logChunks(Log log, AlignedHeapChunk.AlignedHeader firstChunk, String shortSpaceName, boolean isFromSpace) { if (firstChunk.isNonNull()) { - log.newline().string("aligned chunks:").redent(true); - int i = 0; AlignedHeapChunk.AlignedHeader chunk = firstChunk; while (chunk.isNonNull() && i < MAX_CHUNKS_TO_PRINT) { - log.newline().zhex(chunk).string(" (").zhex(AlignedHeapChunk.getObjectsStart(chunk)).string("-").zhex(HeapChunk.getTopPointer(chunk)).string(")"); + Pointer bottom = AlignedHeapChunk.getObjectsStart(chunk); + Pointer top = HeapChunk.getTopPointer(chunk); + Pointer end = AlignedHeapChunk.getObjectsEnd(chunk); + + logChunk(log, chunk, bottom, top, end, true, shortSpaceName, isFromSpace); + chunk = HeapChunk.getNext(chunk); i++; } @@ -44,19 +52,20 @@ public static void logChunks(Log log, AlignedHeapChunk.AlignedHeader firstChunk) assert i == MAX_CHUNKS_TO_PRINT; log.newline().string("... (truncated)"); } - - log.redent(false); } } - public static void logChunks(Log log, UnalignedHeapChunk.UnalignedHeader firstChunk) { + public static void logChunks(Log log, UnalignedHeapChunk.UnalignedHeader firstChunk, String shortSpaceName, boolean isFromSpace) { if (firstChunk.isNonNull()) { - log.newline().string("unaligned chunks:").redent(true); - int i = 0; UnalignedHeapChunk.UnalignedHeader chunk = firstChunk; while (chunk.isNonNull() && i < MAX_CHUNKS_TO_PRINT) { - log.newline().zhex(chunk).string(" (").zhex(UnalignedHeapChunk.getObjectStart(chunk)).string("-").zhex(HeapChunk.getTopPointer(chunk)).string(")"); + Pointer bottom = UnalignedHeapChunk.getObjectStart(chunk); + Pointer top = HeapChunk.getTopPointer(chunk); + Pointer end = UnalignedHeapChunk.getObjectEnd(chunk); + + logChunk(log, chunk, bottom, top, end, false, shortSpaceName, isFromSpace); + chunk = HeapChunk.getNext(chunk); i++; } @@ -64,8 +73,19 @@ public static void logChunks(Log log, UnalignedHeapChunk.UnalignedHeader firstCh assert i == MAX_CHUNKS_TO_PRINT; log.newline().string("... (truncated)"); } - - log.redent(false); } } + + private static void logChunk(Log log, HeapChunk.Header chunk, Pointer bottom, Pointer top, Pointer end, boolean isAligned, String shortSpaceName, boolean isFromSpace) { + UnsignedWord used = top.subtract(bottom); + UnsignedWord capacity = end.subtract(bottom); + UnsignedWord usedPercent = used.multiply(100).unsignedDivide(capacity); + + log.string("|").zhex(chunk).string("|").zhex(bottom).string(", ").zhex(top).string(", ").zhex(end); + log.string("|").unsigned(usedPercent, 3, RIGHT_ALIGN).string("%"); + log.string("|").string(shortSpaceName, 3, RIGHT_ALIGN); + log.string("|").string(isAligned ? "A" : "U"); + log.string("|").string(isFromSpace ? "" : "T"); + log.newline(); + } } diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapChunkProvider.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapChunkProvider.java index f94172566a49..8ecfb4dfb037 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapChunkProvider.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapChunkProvider.java @@ -32,7 +32,6 @@ import org.graalvm.word.WordFactory; import com.oracle.svm.core.FrameAccess; -import com.oracle.svm.core.MemoryWalker; import com.oracle.svm.core.SubstrateOptions; import com.oracle.svm.core.Uninterruptible; import com.oracle.svm.core.genscavenge.AlignedHeapChunk.AlignedHeader; @@ -71,14 +70,6 @@ final class HeapChunkProvider { */ private final AtomicUnsigned bytesInUnusedAlignedChunks = new AtomicUnsigned(); - /** - * The time of the first allocation, as the basis for computing deltas. - * - * We do not care if we race on initializing the field, since the times will be similar in that - * case anyway. - */ - private long firstAllocationTime; - @Platforms(Platform.HOSTED_ONLY.class) HeapChunkProvider() { } @@ -99,7 +90,6 @@ AlignedHeader produceAlignedChunk() { AlignedHeader result = popUnusedAlignedChunk(); if (result.isNull()) { /* Unused list was empty, need to allocate memory. */ - noteFirstAllocationTime(); result = (AlignedHeader) CommittedMemoryProvider.get().allocateAlignedChunk(chunkSize, HeapParameters.getAlignedHeapChunkAlignment()); if (result.isNull()) { throw OutOfMemoryUtil.reportOutOfMemoryError(ALIGNED_OUT_OF_MEMORY_ERROR); @@ -249,10 +239,10 @@ private void freeUnusedAlignedChunksAtSafepoint(UnsignedWord count) { } /** Acquire an UnalignedHeapChunk from the operating system. */ + @SuppressWarnings("static-method") UnalignedHeader produceUnalignedChunk(UnsignedWord objectSize) { UnsignedWord chunkSize = UnalignedHeapChunk.getChunkSizeForObject(objectSize); - noteFirstAllocationTime(); UnalignedHeader result = (UnalignedHeader) CommittedMemoryProvider.get().allocateUnalignedChunk(chunkSize); if (result.isNull()) { throw OutOfMemoryUtil.reportOutOfMemoryError(UNALIGNED_OUT_OF_MEMORY_ERROR); @@ -289,39 +279,8 @@ private static void zap(Header chunk, WordBase value) { } } - Log report(Log log, boolean traceHeapChunks) { - log.string("Unused:").indent(true); - log.string("aligned: ").signed(bytesInUnusedAlignedChunks.get()) - .string("/") - .signed(bytesInUnusedAlignedChunks.get().unsignedDivide(HeapParameters.getAlignedHeapChunkSize())); - if (traceHeapChunks) { - AlignedHeapChunk.AlignedHeader firstChunk = unusedAlignedChunks.get(); - HeapChunkLogging.logChunks(log, firstChunk); - } - log.redent(false); - return log; - } - - boolean walkHeapChunks(MemoryWalker.Visitor visitor) { - assert VMOperation.isInProgressAtSafepoint(); - boolean continueVisiting = true; - MemoryWalker.HeapChunkAccess access = AlignedHeapChunk.getMemoryWalkerAccess(); - for (AlignedHeapChunk.AlignedHeader aChunk = unusedAlignedChunks.get(); continueVisiting && aChunk.isNonNull(); aChunk = HeapChunk.getNext(aChunk)) { - continueVisiting = visitor.visitHeapChunk(aChunk, access); - } - return continueVisiting; - } - - @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) - private void noteFirstAllocationTime() { - if (firstAllocationTime == 0L) { - firstAllocationTime = System.nanoTime(); - } - } - - @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) - long getFirstAllocationTime() { - return firstAllocationTime; + void logFreeChunks(Log log) { + HeapChunkLogging.logChunks(log, unusedAlignedChunks.get(), "F", true); } @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapImpl.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapImpl.java index 4f3b501a0dd1..acfefb4cb7ea 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapImpl.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapImpl.java @@ -125,6 +125,7 @@ public HeapImpl(int pageSize) { this.runtimeCodeInfoGcSupport = new RuntimeCodeInfoGCSupportImpl(); HeapParameters.initialize(); DiagnosticThunkRegistry.singleton().register(new DumpHeapSettingsAndStatistics()); + DiagnosticThunkRegistry.singleton().register(new DumpHeapUsage()); DiagnosticThunkRegistry.singleton().register(new DumpChunkInformation()); } @@ -231,14 +232,14 @@ public RuntimeCodeInfoGCSupport getRuntimeCodeInfoGCSupport() { } @Fold - public HeapAccounting getAccounting() { - return accounting; + public static HeapAccounting getAccounting() { + return getHeapImpl().accounting; } @Override @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) public boolean isAllocationDisallowed() { - return NoAllocationVerifier.isActive() || SafepointBehavior.ignoresSafepoints() || gcImpl.isCollectionInProgress(); + return NoAllocationVerifier.isActive() || SafepointBehavior.ignoresSafepoints(); } /** A guard to place before an allocation, giving the call site and the allocation type. */ @@ -263,25 +264,15 @@ AtomicReference getPinHead() { return pinHead; } - @Uninterruptible(reason = "Necessary to return a reasonably consistent value (a GC can change the queried values).") - public UnsignedWord getUsedBytes() { - return getOldGeneration().getChunkBytes().add(getHeapImpl().getAccounting().getYoungUsedBytes()); + void logUsage(Log log) { + youngGeneration.logUsage(log); + oldGeneration.logUsage(log); } - @Uninterruptible(reason = "Necessary to return a reasonably consistent value (a GC can change the queried values).") - public UnsignedWord getCommittedBytes() { - return getUsedBytes().add(getChunkProvider().getBytesInUnusedChunks()); - } - - void report(Log log) { - report(log, SerialGCOptions.TraceHeapChunks.getValue()); - } - - void report(Log log, boolean traceHeapChunks) { - log.string("Heap:").indent(true); - getYoungGeneration().report(log, traceHeapChunks).newline(); - getOldGeneration().report(log, traceHeapChunks).newline(); - getChunkProvider().report(log, traceHeapChunks).indent(false); + void logChunks(Log log) { + getYoungGeneration().logChunks(log); + getOldGeneration().logChunks(log); + getChunkProvider().logFreeChunks(log); } void logImageHeapPartitionBoundaries(Log log) { @@ -300,36 +291,30 @@ void logImageHeapPartitionBoundaries(Log log) { } /** Log the zap values to make it easier to search for them. */ - static Log zapValuesToLog(Log log) { + static void logZapValues(Log log) { if (HeapParameters.getZapProducedHeapChunks() || HeapParameters.getZapConsumedHeapChunks()) { - log.string("[Heap Chunk zap values: ").indent(true); /* Padded with spaces so the columns line up between the int and word variants. */ if (HeapParameters.getZapProducedHeapChunks()) { - log.string(" producedHeapChunkZapInt: ") - .string(" hex: ").spaces(8).hex(HeapParameters.getProducedHeapChunkZapInt()) - .string(" signed: ").spaces(9).signed(HeapParameters.getProducedHeapChunkZapInt()) - .string(" unsigned: ").spaces(10).unsigned(HeapParameters.getProducedHeapChunkZapInt()).newline(); - log.string(" producedHeapChunkZapWord:") - .string(" hex: ").hex(HeapParameters.getProducedHeapChunkZapWord()) - .string(" signed: ").signed(HeapParameters.getProducedHeapChunkZapWord()) - .string(" unsigned: ").unsigned(HeapParameters.getProducedHeapChunkZapWord()); - if (HeapParameters.getZapConsumedHeapChunks()) { - log.newline(); - } + log.string("producedHeapChunkZapInt: ") + .string(" hex: ").spaces(8).hex(HeapParameters.getProducedHeapChunkZapInt()) + .string(" signed: ").spaces(9).signed(HeapParameters.getProducedHeapChunkZapInt()) + .string(" unsigned: ").spaces(10).unsigned(HeapParameters.getProducedHeapChunkZapInt()).newline(); + log.string("producedHeapChunkZapWord:") + .string(" hex: ").hex(HeapParameters.getProducedHeapChunkZapWord()) + .string(" signed: ").signed(HeapParameters.getProducedHeapChunkZapWord()) + .string(" unsigned: ").unsigned(HeapParameters.getProducedHeapChunkZapWord()).newline(); } if (HeapParameters.getZapConsumedHeapChunks()) { - log.string(" consumedHeapChunkZapInt: ") - .string(" hex: ").spaces(8).hex(HeapParameters.getConsumedHeapChunkZapInt()) - .string(" signed: ").spaces(10).signed(HeapParameters.getConsumedHeapChunkZapInt()) - .string(" unsigned: ").spaces(10).unsigned(HeapParameters.getConsumedHeapChunkZapInt()).newline(); - log.string(" consumedHeapChunkZapWord:") - .string(" hex: ").hex(HeapParameters.getConsumedHeapChunkZapWord()) - .string(" signed: ").signed(HeapParameters.getConsumedHeapChunkZapWord()) - .string(" unsigned: ").unsigned(HeapParameters.getConsumedHeapChunkZapWord()); + log.string("consumedHeapChunkZapInt: ") + .string(" hex: ").spaces(8).hex(HeapParameters.getConsumedHeapChunkZapInt()) + .string(" signed: ").spaces(10).signed(HeapParameters.getConsumedHeapChunkZapInt()) + .string(" unsigned: ").spaces(10).unsigned(HeapParameters.getConsumedHeapChunkZapInt()).newline(); + log.string("consumedHeapChunkZapWord:") + .string(" hex: ").hex(HeapParameters.getConsumedHeapChunkZapWord()) + .string(" signed: ").signed(HeapParameters.getConsumedHeapChunkZapWord()) + .string(" unsigned: ").unsigned(HeapParameters.getConsumedHeapChunkZapWord()).newline(); } - log.redent(false).string("]"); } - return log; } @Override @@ -876,8 +861,6 @@ public int maxInvocationCount() { @Override @RestrictHeapAccess(access = RestrictHeapAccess.Access.NO_ALLOCATION, reason = "Must not allocate while printing diagnostics.") public void printDiagnostics(Log log, ErrorContext context, int maxDiagnosticLevel, int invocationCount) { - GCImpl gc = GCImpl.getGCImpl(); - log.string("Heap settings and statistics:").indent(true); log.string("Supports isolates: ").bool(SubstrateOptions.SpawnIsolates.getValue()).newline(); if (SubstrateOptions.SpawnIsolates.getValue()) { @@ -887,9 +870,27 @@ public void printDiagnostics(Log log, ErrorContext context, int maxDiagnosticLev log.string("Aligned chunk size: ").unsigned(HeapParameters.getAlignedHeapChunkSize()).newline(); log.string("Large array threshold: ").unsigned(HeapParameters.getLargeArrayThreshold()).newline(); - GCAccounting accounting = gc.getAccounting(); + GCAccounting accounting = GCImpl.getAccounting(); log.string("Incremental collections: ").unsigned(accounting.getIncrementalCollectionCount()).newline(); log.string("Complete collections: ").unsigned(accounting.getCompleteCollectionCount()).newline(); + + logZapValues(log); + + log.indent(false); + } + } + + private static class DumpHeapUsage extends DiagnosticThunk { + @Override + public int maxInvocationCount() { + return 1; + } + + @Override + @RestrictHeapAccess(access = RestrictHeapAccess.Access.NO_ALLOCATION, reason = "Must not allocate while printing diagnostics.") + public void printDiagnostics(Log log, ErrorContext context, int maxDiagnosticLevel, int invocationCount) { + log.string("Heap usage:").indent(true); + HeapImpl.getHeapImpl().logUsage(log); log.indent(false); } } @@ -905,9 +906,10 @@ public int maxInvocationCount() { public void printDiagnostics(Log log, ErrorContext context, int maxDiagnosticLevel, int invocationCount) { HeapImpl heap = HeapImpl.getHeapImpl(); heap.logImageHeapPartitionBoundaries(log); - zapValuesToLog(log).newline(); - heap.report(log, true); - log.newline(); + + log.string("Heap chunks: E=eden, S=survivor, O=old, F=free; A=aligned chunk, U=unaligned chunk; T=to space").indent(true); + heap.logChunks(log); + log.indent(false); } } } @@ -917,7 +919,7 @@ public void printDiagnostics(Log log, ErrorContext context, int maxDiagnosticLev final class Target_java_lang_Runtime { @Substitute private long freeMemory() { - return maxMemory() - HeapImpl.getHeapImpl().getUsedBytes().rawValue(); + return maxMemory() - HeapImpl.getAccounting().getUsedBytes().rawValue(); } @Substitute diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapImplMemoryMXBean.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapImplMemoryMXBean.java index 291d1d0674b9..bb3deca0387d 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapImplMemoryMXBean.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/HeapImplMemoryMXBean.java @@ -41,8 +41,8 @@ public HeapImplMemoryMXBean() { @Override public MemoryUsage getHeapMemoryUsage() { - long used = HeapImpl.getHeapImpl().getUsedBytes().rawValue(); - long committed = HeapImpl.getHeapImpl().getCommittedBytes().rawValue(); + long used = HeapImpl.getAccounting().getUsedBytes().rawValue(); + long committed = HeapImpl.getAccounting().getCommittedBytes().rawValue(); long max = GCImpl.getPolicy().getMaximumHeapSize().rawValue(); return new MemoryUsage(UNDEFINED_MEMORY_USAGE, used, committed, max); } diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/ImageHeapInfo.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/ImageHeapInfo.java index e78bea862c84..191748d82cc1 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/ImageHeapInfo.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/ImageHeapInfo.java @@ -223,6 +223,6 @@ public void print(Log log) { log.string("Writable Primitives: ").zhex(Word.objectToUntrackedPointer(firstWritablePrimitiveObject)).string(" - ").zhex(getObjectEnd(lastWritablePrimitiveObject)).newline(); log.string("Writable References: ").zhex(Word.objectToUntrackedPointer(firstWritableReferenceObject)).string(" - ").zhex(getObjectEnd(lastWritableReferenceObject)).newline(); log.string("Writable Huge: ").zhex(Word.objectToUntrackedPointer(firstWritableHugeObject)).string(" - ").zhex(getObjectEnd(lastWritableHugeObject)).newline(); - log.string("ReadOnly Huge: ").zhex(Word.objectToUntrackedPointer(firstReadOnlyHugeObject)).string(" - ").zhex(getObjectEnd(lastReadOnlyHugeObject)); + log.string("ReadOnly Huge: ").zhex(Word.objectToUntrackedPointer(firstReadOnlyHugeObject)).string(" - ").zhex(getObjectEnd(lastReadOnlyHugeObject)).newline(); } } diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/IncrementalGarbageCollectorMXBean.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/IncrementalGarbageCollectorMXBean.java index 5503e586f130..38f7305c177f 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/IncrementalGarbageCollectorMXBean.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/IncrementalGarbageCollectorMXBean.java @@ -48,12 +48,12 @@ public IncrementalGarbageCollectorMXBean() { @Override public long getCollectionCount() { - return HeapImpl.getGCImpl().getAccounting().getIncrementalCollectionCount(); + return GCImpl.getAccounting().getIncrementalCollectionCount(); } @Override public long getCollectionTime() { - long nanos = HeapImpl.getGCImpl().getAccounting().getIncrementalCollectionTotalNanos(); + long nanos = GCImpl.getAccounting().getIncrementalCollectionTotalNanos(); return TimeUtils.roundNanosToMillis(nanos); } diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/JfrGCHeapSummaryEvent.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/JfrGCHeapSummaryEvent.java index 604e4959ce0e..232456a9fc29 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/JfrGCHeapSummaryEvent.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/JfrGCHeapSummaryEvent.java @@ -39,7 +39,7 @@ class JfrGCHeapSummaryEvent { public static void emit(JfrGCWhen gcWhen) { if (HasJfrSupport.get()) { - emit0(GCImpl.getGCImpl().getCollectionEpoch(), JfrTicks.elapsedTicks(), HeapImpl.getHeapImpl().getCommittedBytes(), HeapImpl.getHeapImpl().getUsedBytes(), gcWhen); + emit0(GCImpl.getGCImpl().getCollectionEpoch(), JfrTicks.elapsedTicks(), HeapImpl.getAccounting().getCommittedBytes(), HeapImpl.getAccounting().getUsedBytes(), gcWhen); } } 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 ca364957b77e..d82bc8d953dc 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 @@ -76,7 +76,7 @@ public static final class Options { public boolean shouldCollectOnRequest(GCCause cause, boolean fullGC) { if (cause == GCCause.HintedGC) { guaranteeSizeParametersInitialized(); - UnsignedWord edenUsedBytes = HeapImpl.getHeapImpl().getAccounting().getEdenUsedBytes(); + UnsignedWord edenUsedBytes = HeapImpl.getAccounting().getEdenUsedBytes(); if (fullGC) { // For full GC request, we slightly lower the threshold to increase their // probability to be performed, as they are supposed to be issued at the lowest diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/OldGeneration.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/OldGeneration.java index 6ecf2f04d3fa..a9b7ccaf9049 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/OldGeneration.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/OldGeneration.java @@ -56,8 +56,8 @@ public final class OldGeneration extends Generation { OldGeneration(String name) { super(name); int age = HeapParameters.getMaxSurvivorSpaces() + 1; - this.fromSpace = new Space("oldFromSpace", true, age); - this.toSpace = new Space("oldToSpace", false, age); + this.fromSpace = new Space("Old", "O", true, age); + this.toSpace = new Space("Old To", "O", false, age); } @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) @@ -120,12 +120,15 @@ boolean scanGreyObjects() { } @Override - public Log report(Log log, boolean traceHeapChunks) { - log.string("Old generation: ").indent(true); - getFromSpace().report(log, traceHeapChunks).newline(); - getToSpace().report(log, traceHeapChunks).newline(); - log.redent(false); - return log; + public void logUsage(Log log) { + getFromSpace().logUsage(log, true); + getToSpace().logUsage(log, false); + } + + @Override + public void logChunks(Log log) { + getFromSpace().logChunks(log); + getToSpace().logChunks(log); } @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) 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 58ff2e67c927..adfe3dc0dc8f 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 @@ -90,7 +90,7 @@ public void onCollectionBegin(boolean completeCollection, long requestingNanoTim @Override public void onCollectionEnd(boolean completeCollection, GCCause cause) { - UnsignedWord oldLive = GCImpl.getGCImpl().getAccounting().getOldGenerationAfterChunkBytes(); + UnsignedWord oldLive = GCImpl.getAccounting().getOldGenerationAfterChunkBytes(); oldSizeExceededInPreviousCollection = oldLive.aboveThan(oldSize); boolean resizeOldOnlyForPromotions = !completeCollection; @@ -123,7 +123,7 @@ private void adjustDesiredTenuringThreshold() { // DefNewGeneration::adjust_desi private void computeNewOldGenSize(boolean resizeOnlyForPromotions) { // TenuredGeneration::compute_new_size_inner UnsignedWord capacityAtPrologue = oldSize; - UnsignedWord usedAfterGc = GCImpl.getGCImpl().getAccounting().getOldGenerationAfterChunkBytes(); + UnsignedWord usedAfterGc = GCImpl.getAccounting().getOldGenerationAfterChunkBytes(); if (oldSize.belowThan(usedAfterGc)) { oldSize = usedAfterGc; } diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/SerialAndEpsilonGCOptions.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/SerialAndEpsilonGCOptions.java index 7db109493358..cd2255a66f59 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/SerialAndEpsilonGCOptions.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/SerialAndEpsilonGCOptions.java @@ -69,9 +69,6 @@ protected void onValueUpdate(EconomicMap, Object> values, Long oldV @Option(help = "After use, Fill memory chunks with a sentinel value. Serial and epsilon GC only.", type = OptionType.Debug) // public static final HostedOptionKey ZapConsumedHeapChunks = new HostedOptionKey<>(false, SerialAndEpsilonGCOptions::serialOrEpsilonGCOnly); - @Option(help = "Bytes that can be allocated before (re-)querying the physical memory size. Serial and epsilon GC only.", type = OptionType.Debug) // - public static final HostedOptionKey AllocationBeforePhysicalMemorySize = new HostedOptionKey<>(1L * 1024L * 1024L, SerialAndEpsilonGCOptions::serialOrEpsilonGCOnly); - @Option(help = "Number of bytes at the beginning of each heap chunk that are not used for payload data, i.e., can be freely used as metadata by the heap chunk provider. Serial and epsilon GC only.", type = OptionType.Debug) // public static final HostedOptionKey HeapChunkHeaderPadding = new HostedOptionKey<>(0, SerialAndEpsilonGCOptions::serialOrEpsilonGCOnly); diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/SerialGCOptions.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/SerialGCOptions.java index edac8966b176..c0c37dbeee7c 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/SerialGCOptions.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/SerialGCOptions.java @@ -73,13 +73,11 @@ public Integer getValue(OptionValues values) { "for which a soft reference will keep its referent alive after its last access. Serial GC only.", type = OptionType.Expert) // public static final HostedOptionKey SoftRefLRUPolicyMSPerMB = new HostedOptionKey<>(1000, SerialGCOptions::serialGCOnly); - @Option(help = "Print the shape of the heap before and after each collection, if +VerboseGC. Serial GC only.", type = OptionType.Debug)// - public static final RuntimeOptionKey PrintHeapShape = new RuntimeOptionKey<>(false, SerialGCOptions::serialGCOnly); - @Option(help = "Print summary GC information after application main method returns. Serial GC only.", type = OptionType.Debug)// public static final RuntimeOptionKey PrintGCSummary = new RuntimeOptionKey<>(false, SerialGCOptions::serialGCOnly); - @Option(help = "Print a time stamp at each collection, if +PrintGC or +VerboseGC. Serial GC only.", type = OptionType.Debug)// + /* Will be removed as part of GR-48148. */ + @Option(help = "Deprecated. Print a time stamp at each collection, if +PrintGC or +VerboseGC. Serial GC only.", type = OptionType.Debug)// public static final RuntimeOptionKey PrintGCTimeStamps = new RuntimeOptionKey<>(false, SerialGCOptions::serialGCOnly); @Option(help = "Print the time for each of the phases of each collection, if +VerboseGC. Serial GC only.", type = OptionType.Debug)// @@ -106,7 +104,7 @@ public Integer getValue(OptionValues values) { @Option(help = "Verify write barriers. Serial GC only.", type = OptionType.Debug)// public static final HostedOptionKey VerifyWriteBarriers = new HostedOptionKey<>(false, SerialGCOptions::serialGCOnly); - @Option(help = "Trace heap chunks during collections, if +VerboseGC and +PrintHeapShape. Serial GC only.", type = OptionType.Debug) // + @Option(help = "Trace heap chunks during collections, if +VerboseGC. Serial GC only.", type = OptionType.Debug) // public static final RuntimeOptionKey TraceHeapChunks = new RuntimeOptionKey<>(false, SerialGCOptions::serialGCOnly); @Option(help = "Develop demographics of the object references visited. Serial GC only.", type = OptionType.Debug)// diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/Space.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/Space.java index 281dcbfc8e84..9a99d1d26245 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/Space.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/Space.java @@ -60,6 +60,7 @@ */ public final class Space { private final String name; + private final String shortName; private final boolean isFromSpace; private final int age; private final ChunksAccounting accounting; @@ -76,17 +77,18 @@ public final class Space { * collections so they should not move. */ @Platforms(Platform.HOSTED_ONLY.class) - Space(String name, boolean isFromSpace, int age) { - this(name, isFromSpace, age, null); + Space(String name, String shortName, boolean isFromSpace, int age) { + this(name, shortName, isFromSpace, age, null); } @Platforms(Platform.HOSTED_ONLY.class) - Space(String name, boolean isFromSpace, int age, ChunksAccounting accounting) { + Space(String name, String shortName, boolean isFromSpace, int age, ChunksAccounting parentAccounting) { assert name != null : "Space name should not be null."; this.name = name; + this.shortName = shortName; this.isFromSpace = isFromSpace; this.age = age; - this.accounting = new ChunksAccounting(accounting); + this.accounting = new ChunksAccounting(parentAccounting); } @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) @@ -94,6 +96,11 @@ public String getName() { return name; } + @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) + public String getShortName() { + return shortName; + } + @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) public boolean isEmpty() { return (getFirstAlignedHeapChunk().isNull() && getFirstUnalignedHeapChunk().isNull()); @@ -158,16 +165,18 @@ public boolean walkObjects(ObjectVisitor visitor) { return true; } - /** Report some statistics about this Space. */ - public Log report(Log log, boolean traceHeapChunks) { - log.string(getName()).string(":").indent(true); - accounting.report(log); - if (traceHeapChunks) { - HeapChunkLogging.logChunks(log, getFirstAlignedHeapChunk()); - HeapChunkLogging.logChunks(log, getFirstUnalignedHeapChunk()); + public void logUsage(Log log, boolean logIfEmpty) { + UnsignedWord chunkBytes = getChunkBytes(); + if (logIfEmpty || chunkBytes.aboveThan(0)) { + log.string(getName()).string(": ").rational(chunkBytes, GCImpl.M, 2).string("M (") + .rational(accounting.getAlignedChunkBytes(), GCImpl.M, 2).string("M in ").signed(accounting.getAlignedChunkCount()).string(" aligned chunks, ") + .rational(accounting.getUnalignedChunkBytes(), GCImpl.M, 2).string("M in ").signed(accounting.getUnalignedChunkCount()).string(" unaligned chunks)").newline(); } - log.redent(false); - return log; + } + + public void logChunks(Log log) { + HeapChunkLogging.logChunks(log, getFirstAlignedHeapChunk(), shortName, isFromSpace); + HeapChunkLogging.logChunks(log, getFirstUnalignedHeapChunk(), shortName, isFromSpace); } /** diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/ThreadLocalAllocation.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/ThreadLocalAllocation.java index e42ad9153ec2..be84e80e8d16 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/ThreadLocalAllocation.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/ThreadLocalAllocation.java @@ -351,7 +351,7 @@ private static Object allocateLargeArrayLikeObjectInNewTlab(DynamicHub hub, int tlab.setUnalignedChunk(newTlabChunk); allocatedBytes.set(allocatedBytes.get().add(size)); - HeapImpl.getHeapImpl().getAccounting().increaseEdenUsedBytes(size); + HeapImpl.getAccounting().increaseEdenUsedBytes(size); Pointer memory = UnalignedHeapChunk.allocateMemory(newTlabChunk, size); assert memory.isNonNull(); @@ -494,7 +494,7 @@ private static void registerNewAllocationChunk(Descriptor tlab, AlignedHeader ne HeapChunk.setNext(newChunk, tlab.getAlignedChunk()); tlab.setAlignedChunk(newChunk); - HeapImpl.getHeapImpl().getAccounting().increaseEdenUsedBytes(HeapParameters.getAlignedHeapChunkSize()); + HeapImpl.getAccounting().increaseEdenUsedBytes(HeapParameters.getAlignedHeapChunkSize()); tlab.setAllocationTop(HeapChunk.getTopPointer(newChunk), TLAB_TOP_IDENTITY); tlab.setAllocationEnd(HeapChunk.getEndPointer(newChunk), TLAB_END_IDENTITY); diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/Timers.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/Timers.java index a62552c92310..0e480fe082ae 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/Timers.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/Timers.java @@ -24,6 +24,7 @@ */ package com.oracle.svm.core.genscavenge; +import com.oracle.svm.core.Isolates; import com.oracle.svm.core.Uninterruptible; import com.oracle.svm.core.log.Log; @@ -87,7 +88,7 @@ public long getOpenedTime() { if (!wasOpened) { /* If a timer was not opened, pretend it was opened at the start of the VM. */ assert openNanos == 0; - return HeapImpl.getChunkProvider().getFirstAllocationTime(); + return Isolates.getCurrentStartNanoTime(); } return openNanos; } @@ -106,10 +107,6 @@ long getMeasuredNanos() { long getLastIntervalNanos() { return getClosedTime() - getOpenedTime(); } - - static long getTimeSinceFirstAllocation(long nanos) { - return nanos - HeapImpl.getChunkProvider().getFirstAllocationTime(); - } } /** Collection timers primarily for {@link GCImpl}. */ diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/YoungGeneration.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/YoungGeneration.java index d7f337a6a0b4..8b92be57c986 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/YoungGeneration.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/YoungGeneration.java @@ -49,7 +49,7 @@ public final class YoungGeneration extends Generation { @Platforms(Platform.HOSTED_ONLY.class) YoungGeneration(String name) { super(name); - this.eden = new Space("edenSpace", true, 0); + this.eden = new Space("Eden", "E", true, 0); this.maxSurvivorSpaces = HeapParameters.getMaxSurvivorSpaces(); this.survivorFromSpaces = new Space[maxSurvivorSpaces]; this.survivorToSpaces = new Space[maxSurvivorSpaces]; @@ -57,8 +57,8 @@ public final class YoungGeneration extends Generation { this.survivorsToSpacesAccounting = new ChunksAccounting(); for (int i = 0; i < maxSurvivorSpaces; i++) { int age = i + 1; - this.survivorFromSpaces[i] = new Space("Survivor-" + age + " From", true, age); - this.survivorToSpaces[i] = new Space("Survivor-" + age + " To", false, age, survivorsToSpacesAccounting); + this.survivorFromSpaces[i] = new Space("Survivor-" + age, "S" + age, true, age); + this.survivorToSpaces[i] = new Space("Survivor-" + age + " To", "S" + age, false, age, survivorsToSpacesAccounting); this.survivorGreyObjectsWalkers[i] = new GreyObjectsWalker(); } } @@ -98,21 +98,21 @@ public boolean walkObjects(ObjectVisitor visitor) { } @Override - public Log report(Log log, boolean traceHeapChunks) { - log.string("Young generation: ").indent(true); - log.string("Eden: ").indent(true); - getEden().report(log, traceHeapChunks); - log.redent(false).newline(); - log.string("Survivors: ").indent(true); + public void logUsage(Log log) { + getEden().logUsage(log, true); for (int i = 0; i < maxSurvivorSpaces; i++) { - this.survivorFromSpaces[i].report(log, traceHeapChunks).newline(); - this.survivorToSpaces[i].report(log, traceHeapChunks); - if (i < maxSurvivorSpaces - 1) { - log.newline(); - } + this.survivorFromSpaces[i].logUsage(log, false); + this.survivorToSpaces[i].logUsage(log, false); + } + } + + @Override + public void logChunks(Log log) { + getEden().logChunks(log); + for (int i = 0; i < maxSurvivorSpaces; i++) { + this.survivorFromSpaces[i].logChunks(log); + this.survivorToSpaces[i].logChunks(log); } - log.redent(false).redent(false); - return log; } @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) @@ -192,29 +192,41 @@ boolean scanGreyObjects() { } /** - * This value is only updated during a GC. Be careful when calling this method during a GC as it - * might wrongly include chunks that will be freed at the end of the GC. + * This value is only updated during a GC, so it may be outdated if called from outside the GC + * VM operation. Also be careful when calling this method during a GC as it might wrongly + * include chunks that will be freed at the end of the GC. */ UnsignedWord getChunkBytes() { return getEden().getChunkBytes().add(getSurvivorChunkBytes()); } - /** This value is only updated during a GC, be careful: see {@link #getChunkBytes}. */ + /** + * This value is only updated during a GC, be careful: see {@link #getChunkBytes}. + */ + @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) UnsignedWord getSurvivorChunkBytes() { UnsignedWord chunkBytes = WordFactory.zero(); for (int i = 0; i < maxSurvivorSpaces; i++) { - chunkBytes = chunkBytes.add(this.survivorFromSpaces[i].getChunkBytes()); - chunkBytes = chunkBytes.add(this.survivorToSpaces[i].getChunkBytes()); + chunkBytes = chunkBytes.add(getSurvivorChunkBytes(i)); } return chunkBytes; } - /** This value is only updated during a GC, be careful: see {@link #getChunkBytes}. */ + @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) + UnsignedWord getSurvivorChunkBytes(int survivorIndex) { + return survivorFromSpaces[survivorIndex].getChunkBytes().add(survivorToSpaces[survivorIndex].getChunkBytes()); + } + + /** + * This value is only updated during a GC, be careful: see {@link #getChunkBytes}. + */ UnsignedWord getAlignedChunkBytes() { return getEden().getAlignedChunkBytes().add(getSurvivorAlignedChunkBytes()); } - /** This value is only updated during a GC, be careful: see {@link #getChunkBytes}. */ + /** + * This value is only updated during a GC, be careful: see {@link #getChunkBytes}. + */ UnsignedWord getSurvivorAlignedChunkBytes() { UnsignedWord chunkBytes = WordFactory.zero(); for (int i = 0; i < maxSurvivorSpaces; i++) { diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/jvmstat/EpsilonGCPerfData.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/jvmstat/EpsilonGCPerfData.java index 3f5a2a796b79..5d3eaf9e7a74 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/jvmstat/EpsilonGCPerfData.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/jvmstat/EpsilonGCPerfData.java @@ -52,7 +52,7 @@ public void allocate() { @Override public void update() { long maxCapacity = GCImpl.getPolicy().getMaximumHeapSize().rawValue(); - long usedBytes = HeapImpl.getHeapImpl().getAccounting().getEdenUsedBytes().rawValue(); + long usedBytes = HeapImpl.getAccounting().getEdenUsedBytes().rawValue(); space.used.setValue(usedBytes); generation.capacity.setValue(usedBytes); diff --git a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/jvmstat/SerialGCPerfData.java b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/jvmstat/SerialGCPerfData.java index 4fe4410401eb..78fe00ccef7c 100644 --- a/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/jvmstat/SerialGCPerfData.java +++ b/substratevm/src/com.oracle.svm.core.genscavenge/src/com/oracle/svm/core/genscavenge/jvmstat/SerialGCPerfData.java @@ -93,8 +93,8 @@ public void allocate() { @Override public void update() { - GCAccounting accounting = GCImpl.getGCImpl().getAccounting(); - HeapAccounting heapAccounting = HeapImpl.getHeapImpl().getAccounting(); + GCAccounting accounting = GCImpl.getAccounting(); + HeapAccounting heapAccounting = HeapImpl.getAccounting(); CollectionPolicy policy = GCImpl.getPolicy(); policy.ensureSizeParametersInitialized(); @@ -107,7 +107,7 @@ public void update() { youngGen.spaces[0].used.setValue(heapAccounting.getEdenUsedBytes().rawValue()); for (int i = 1; i < youngGen.spaces.length; i++) { - youngGen.spaces[i].used.setValue(heapAccounting.getSurvivorSpaceAfterChunkBytes(i - 1).rawValue()); + youngGen.spaces[i].used.setValue(heapAccounting.getSurvivorUsedBytes(i - 1).rawValue()); } long maxOldSize = policy.getMaximumHeapSize().rawValue() - maxNewSize; @@ -117,7 +117,7 @@ public void update() { oldGen.capacity.setValue(policy.getOldGenerationCapacity().rawValue()); oldGen.maxCapacity.setValue(maxOldSize); - oldGen.spaces[0].used.setValue(accounting.getOldGenerationAfterChunkBytes().rawValue()); + oldGen.spaces[0].used.setValue(heapAccounting.getOldUsedBytes().rawValue()); } private static class PerfDataGCPolicy { 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 546cf43abd2e..e4c593128ba3 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 @@ -60,6 +60,8 @@ public class Isolates { public static final CGlobalData IMAGE_HEAP_WRITABLE_END = CGlobalDataFactory.forSymbol(IMAGE_HEAP_WRITABLE_END_SYMBOL_NAME); private static Boolean isCurrentFirst; + private static long startTimeMillis; + private static long startNanoTime; /** * Indicates if the current isolate is the first isolate in this process. If so, it can be @@ -77,6 +79,31 @@ public static void setCurrentIsFirstIsolate(boolean value) { isCurrentFirst = value; } + public static void setCurrentStartTime() { + assert startTimeMillis == 0; + assert startNanoTime == 0; + startTimeMillis = System.currentTimeMillis(); + startNanoTime = System.nanoTime(); + } + + @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) + public static long getCurrentStartTimeMillis() { + assert startTimeMillis != 0; + return startTimeMillis; + } + + @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) + public static long getCurrentUptimeMillis() { + assert startTimeMillis != 0; + return System.currentTimeMillis() - startTimeMillis; + } + + @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) + public static long getCurrentStartNanoTime() { + assert startNanoTime != 0; + return startNanoTime; + } + @Uninterruptible(reason = "Thread state not yet set up.") public static int checkIsolate(Isolate isolate) { if (SubstrateOptions.SpawnIsolates.getValue()) { diff --git a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/JavaMainWrapper.java b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/JavaMainWrapper.java index 1d35936412e0..9eed46291285 100644 --- a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/JavaMainWrapper.java +++ b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/JavaMainWrapper.java @@ -35,7 +35,6 @@ import java.util.List; import java.util.function.BooleanSupplier; -import com.oracle.svm.util.ClassUtil; import org.graalvm.compiler.serviceprovider.JavaVersionUtil; import org.graalvm.compiler.word.Word; import org.graalvm.nativeimage.CurrentIsolate; @@ -80,6 +79,7 @@ import com.oracle.svm.core.util.CounterSupport; import com.oracle.svm.core.util.UserError; import com.oracle.svm.core.util.VMError; +import com.oracle.svm.util.ClassUtil; import com.oracle.svm.util.ReflectionUtil; @InternalVMMethod @@ -235,6 +235,7 @@ private static int runCore0() { */ JavaMainSupport mainSupport = ImageSingletons.lookup(JavaMainSupport.class); invokeMain(mainSupport.mainArgs); + return 0; } catch (Throwable ex) { JavaThreads.dispatchUncaughtException(Thread.currentThread(), ex); diff --git a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/SubstrateDiagnostics.java b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/SubstrateDiagnostics.java index 0634c5e9e4e3..92ffd76b319b 100644 --- a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/SubstrateDiagnostics.java +++ b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/SubstrateDiagnostics.java @@ -72,7 +72,6 @@ import com.oracle.svm.core.heap.RestrictHeapAccess; import com.oracle.svm.core.hub.DynamicHub; import com.oracle.svm.core.jdk.UninterruptibleUtils.AtomicWord; -import com.oracle.svm.core.jdk.management.SubstrateRuntimeMXBean; import com.oracle.svm.core.locks.VMLockSupport; import com.oracle.svm.core.log.Log; import com.oracle.svm.core.option.RuntimeOptionKey; @@ -92,6 +91,7 @@ import com.oracle.svm.core.threadlocal.FastThreadLocalFactory; import com.oracle.svm.core.threadlocal.VMThreadLocalInfos; import com.oracle.svm.core.util.CounterSupport; +import com.oracle.svm.core.util.TimeUtils; public class SubstrateDiagnostics { private static final int MAX_THREADS_TO_PRINT = 100_000; @@ -813,7 +813,7 @@ public void printDiagnostics(Log log, ErrorContext context, int maxDiagnosticLev log.string(", ").string(platform.getOS()).string("/").string(platform.getArchitecture()).newline(); log.string("Current timestamp: ").unsigned(System.currentTimeMillis()).newline(); - log.string("VM uptime: ").signed(ImageSingletons.lookup(SubstrateRuntimeMXBean.class).getUptime()).string(" ms").newline(); + log.string("VM uptime: ").rational(Isolates.getCurrentUptimeMillis(), TimeUtils.millisPerSecond, 3).string("s").newline(); CodeInfo info = CodeInfoTable.getImageCodeInfo(); Pointer codeStart = (Pointer) CodeInfoAccess.getCodeStart(info); diff --git a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/SubstrateOptions.java b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/SubstrateOptions.java index 990309c15c6a..cf2d899023d6 100644 --- a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/SubstrateOptions.java +++ b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/SubstrateOptions.java @@ -357,6 +357,8 @@ protected void onValueUpdate(EconomicMap, Object> values, Boolean o } } }; + @Option(help = "Physical memory size (in bytes). By default, the value is queried from the OS/container during VM startup.", type = OptionType.Expert)// + public static final RuntimeOptionKey MaxRAM = new RuntimeOptionKey<>(0L, Immutable); @Option(help = "The size of each thread stack at run-time, in bytes.", type = OptionType.User)// public static final RuntimeOptionKey StackSize = new RuntimeOptionKey<>(0L); diff --git a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/code/RuntimeCodeInfoHistory.java b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/code/RuntimeCodeInfoHistory.java index 7cebedc593ba..7e3809e4d286 100644 --- a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/code/RuntimeCodeInfoHistory.java +++ b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/code/RuntimeCodeInfoHistory.java @@ -31,6 +31,7 @@ import org.graalvm.nativeimage.c.function.CodePointer; import org.graalvm.word.UnsignedWord; +import com.oracle.svm.core.Isolates; import com.oracle.svm.core.SubstrateOptions; import com.oracle.svm.core.Uninterruptible; import com.oracle.svm.core.code.CodeInfoAccess.HasInstalledCode; @@ -41,6 +42,7 @@ import com.oracle.svm.core.thread.Safepoint; import com.oracle.svm.core.thread.VMOperation; import com.oracle.svm.core.thread.VMThreads; +import com.oracle.svm.core.util.TimeUtils; public class RuntimeCodeInfoHistory { private static final RingBuffer.Consumer PRINT_WITH_JAVA_HEAP_DATA = RuntimeCodeInfoHistory::printEntryWithJavaHeapData; @@ -99,7 +101,7 @@ private static void traceCodeCache(String kind, CodeInfo info, boolean allowJava } public void printRecentOperations(Log log, boolean allowJavaHeapAccess) { - log.string("The ").signed(recentOperations.size()).string(" most recent RuntimeCodeInfo operations (oldest first): ").indent(true); + log.string("The ").signed(recentOperations.size()).string(" most recent RuntimeCodeInfo operations:").indent(true); recentOperations.foreach(log, allowJavaHeapAccess ? PRINT_WITH_JAVA_HEAP_DATA : PRINT_WITHOUT_JAVA_HEAP_DATA); log.indent(false); } @@ -160,7 +162,8 @@ public void setValues(String kind, CodeInfo codeInfo, int codeInfoState, String public void print(Log log, boolean allowJavaHeapAccess) { if (kind != null) { - log.unsigned(timestamp).string(" - ").string(kind).spaces(1); + long uptime = timestamp - Isolates.getCurrentStartTimeMillis(); + log.rational(uptime, TimeUtils.millisPerSecond, 3).string("s - ").string(kind).spaces(1); String name = allowJavaHeapAccess ? codeName : null; CodeInfoAccess.printCodeInfo(log, codeInfo, codeInfoState, name, codeStart, codeEnd, hasInstalledCode, installedCodeAddress, installedCodeEntryPoint); log.string(", safepointId: ").unsigned(safepointId).newline(); diff --git a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/graal/snippets/CEntryPointSnippets.java b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/graal/snippets/CEntryPointSnippets.java index fb551a1a5ce4..63e8ee0ff17e 100644 --- a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/graal/snippets/CEntryPointSnippets.java +++ b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/graal/snippets/CEntryPointSnippets.java @@ -90,6 +90,7 @@ import com.oracle.svm.core.graal.nodes.CEntryPointLeaveNode; import com.oracle.svm.core.graal.nodes.CEntryPointUtilityNode; import com.oracle.svm.core.heap.Heap; +import com.oracle.svm.core.heap.PhysicalMemory; import com.oracle.svm.core.heap.ReferenceHandler; import com.oracle.svm.core.heap.ReferenceHandlerThread; import com.oracle.svm.core.heap.RestrictHeapAccess; @@ -306,6 +307,7 @@ private static int initializeIsolate(CEntryPointCreateIsolateParameters paramete } } Isolates.setCurrentIsFirstIsolate(firstIsolate); + Isolates.setCurrentStartTime(); /* * The VM operation thread must be started early as no VM operations can be scheduled before @@ -369,6 +371,9 @@ private static int initializeIsolate(CEntryPointCreateIsolateParameters paramete /* Adjust stack overflow boundary of main thread. */ StackOverflowCheck.singleton().updateStackOverflowBoundary(); + /* Initialize the physical memory size. */ + PhysicalMemory.size(); + assert !isolateInitialized; isolateInitialized = true; diff --git a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/heap/PhysicalMemory.java b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/heap/PhysicalMemory.java index ec613423bf85..d9516fe2b2d3 100644 --- a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/heap/PhysicalMemory.java +++ b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/heap/PhysicalMemory.java @@ -29,7 +29,7 @@ import org.graalvm.word.WordFactory; import com.oracle.svm.core.Containers; -import com.oracle.svm.core.graal.snippets.CEntryPointSnippets; +import com.oracle.svm.core.SubstrateOptions; import com.oracle.svm.core.jdk.UninterruptibleUtils.AtomicInteger; import com.oracle.svm.core.stack.StackOverflowCheck; import com.oracle.svm.core.thread.PlatformThreads; @@ -45,6 +45,7 @@ public class PhysicalMemory { /** Implemented by operating-system specific code. */ public interface PhysicalMemorySupport { + /* Will be removed in GR-48001. */ default boolean hasSize() { throw VMError.shouldNotReachHere("Unused, will be removed"); } @@ -53,15 +54,14 @@ default boolean hasSize() { UnsignedWord size(); } - /** A sentinel unset value. */ + private static final AtomicInteger INITIALIZING = new AtomicInteger(0); private static final UnsignedWord UNSET_SENTINEL = UnsignedUtils.MAX_VALUE; - - /** Prevent recursive initialization in {@link #tryInitialize}. */ - static AtomicInteger initializing = new AtomicInteger(0); - - /** The cached size of physical memory, or an unset value. */ private static UnsignedWord cachedSize = UNSET_SENTINEL; + public static boolean isInitialized() { + return cachedSize != UNSET_SENTINEL; + } + /** * Returns the size of physical memory in bytes, querying it from the OS if it has not been * initialized yet. @@ -75,57 +75,33 @@ public static UnsignedWord size() { * Note that we want to have this safety check even when the cache is already * initialized, so that we always detect wrong usages that could lead to problems. */ - throw VMError.shouldNotReachHere("Accessing the physical memory size requires allocation and synchronization"); + throw VMError.shouldNotReachHere("Accessing the physical memory size may require allocation and synchronization"); } if (!isInitialized()) { - initializing.incrementAndGet(); + /* + * Multiple threads can race to initialize the cache. This is OK because all of them + * will (most-likely) compute the same value. + */ + INITIALIZING.incrementAndGet(); try { - /* - * Multiple threads can race to initialize the cache. This is OK because all of them - * will compute the same value. - */ - doInitialize(); + long memoryLimit = SubstrateOptions.MaxRAM.getValue(); + if (memoryLimit > 0) { + cachedSize = WordFactory.unsigned(memoryLimit); + } else { + memoryLimit = Containers.memoryLimitInBytes(); + cachedSize = memoryLimit == Containers.UNKNOWN + ? ImageSingletons.lookup(PhysicalMemorySupport.class).size() + : WordFactory.unsigned(memoryLimit); + } } finally { - initializing.decrementAndGet(); + INITIALIZING.decrementAndGet(); } } return cachedSize; } - /** - * Tries to initialize the cached memory size. If the initialization is not possible, e.g., - * because the call is from within a VMOperation, the method does nothing. - */ - public static void tryInitialize() { - if (isInitialized() || isInitializationDisallowed()) { - return; - } - - /* - * We need to prevent recursive calls of the initialization. We also want only one thread to - * try the initialization. Since this is an optional initialization, we also do not need to - * wait until the other thread has finished the initialization. Initialization can be quite - * heavyweight and involve reading configuration files. - */ - if (initializing.compareAndSet(0, 1)) { - try { - doInitialize(); - } finally { - initializing.decrementAndGet(); - } - } - } - - /** - * Returns true if the memory size has been queried from the OS, i.e., if - * {@link #getCachedSize()} can be called. - */ - public static boolean isInitialized() { - return cachedSize != UNSET_SENTINEL; - } - /** * Returns the size of physical memory in bytes that has been previously cached. This method * must not be called if {@link #isInitialized()} is still false. @@ -136,15 +112,6 @@ public static UnsignedWord getCachedSize() { } private static boolean isInitializationDisallowed() { - return Heap.getHeap().isAllocationDisallowed() || VMOperation.isInProgress() || !PlatformThreads.isCurrentAssigned() || - !CEntryPointSnippets.isIsolateInitialized() || StackOverflowCheck.singleton().isYellowZoneAvailable(); - } - - @RestrictHeapAccess(access = RestrictHeapAccess.Access.UNRESTRICTED, reason = "Only called if allocation is allowed.") - private static void doInitialize() { - long memoryLimit = Containers.memoryLimitInBytes(); - cachedSize = memoryLimit == Containers.UNKNOWN - ? ImageSingletons.lookup(PhysicalMemorySupport.class).size() - : WordFactory.unsigned(memoryLimit); + return Heap.getHeap().isAllocationDisallowed() || VMOperation.isInProgress() || !PlatformThreads.isCurrentAssigned() || StackOverflowCheck.singleton().isYellowZoneAvailable(); } } diff --git a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/jdk/management/SubstrateRuntimeMXBean.java b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/jdk/management/SubstrateRuntimeMXBean.java index 72e97fdb6ee8..15ab9437ee4b 100644 --- a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/jdk/management/SubstrateRuntimeMXBean.java +++ b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/jdk/management/SubstrateRuntimeMXBean.java @@ -42,24 +42,19 @@ import org.graalvm.nativeimage.Platforms; import org.graalvm.nativeimage.ProcessProperties; +import com.oracle.svm.core.Isolates; import com.oracle.svm.core.JavaMainWrapper; -import com.oracle.svm.core.jdk.RuntimeSupport; +import com.oracle.svm.core.Uninterruptible; import sun.management.Util; public final class SubstrateRuntimeMXBean implements RuntimeMXBean { private final String managementSpecVersion; - private long startMillis; @Platforms(Platform.HOSTED_ONLY.class) SubstrateRuntimeMXBean() { managementSpecVersion = ManagementFactory.getRuntimeMXBean().getManagementSpecVersion(); - RuntimeSupport.getRuntimeSupport().addInitializationHook(isFirstIsolate -> initialize()); - } - - void initialize() { - startMillis = System.currentTimeMillis(); } @Override @@ -83,7 +78,7 @@ public String getName() { try { id = ProcessProperties.getProcessID(); } catch (Throwable t) { - id = startMillis; + id = Isolates.getCurrentStartTimeMillis(); } try { hostName = InetAddress.getLocalHost().getHostName(); @@ -152,13 +147,13 @@ public String getBootClassPath() { @Override public long getUptime() { - return Math.max(0, System.currentTimeMillis() - startMillis); + return Isolates.getCurrentUptimeMillis(); } @Override + @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true) public long getStartTime() { - assert startMillis > 0 : "SubstrateRuntimeMXBean.getStartTime: Should have set SubstrateRuntimeMXBean.startMillis."; - return startMillis; + return Isolates.getCurrentStartTimeMillis(); } /** Copied from {@code sun.management.RuntimeImpl#getSystemProperties()}. */ diff --git a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/log/Log.java b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/log/Log.java index 820c9d9b6668..29590c743b25 100644 --- a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/log/Log.java +++ b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/log/Log.java @@ -36,6 +36,7 @@ import org.graalvm.nativeimage.c.function.CodePointer; import org.graalvm.nativeimage.c.type.CCharPointer; import org.graalvm.word.PointerBase; +import org.graalvm.word.UnsignedWord; import org.graalvm.word.WordBase; /** @@ -234,6 +235,8 @@ protected Log() { public abstract Log rational(long numerator, long denominator, long decimals); + public abstract Log rational(UnsignedWord numerator, long denominator, long decimals); + /** * Prints the value, treated as an unsigned value, in hexadecimal format. */ @@ -493,6 +496,11 @@ public Log rational(long numerator, long denominator, long decimals) { return this; } + @Override + public Log rational(UnsignedWord numerator, long denominator, long decimals) { + return this; + } + @Override public Log hex(WordBase value) { return this; diff --git a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/log/RealLog.java b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/log/RealLog.java index 66a876bd0acf..6445c1d9ad93 100644 --- a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/log/RealLog.java +++ b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/log/RealLog.java @@ -384,6 +384,12 @@ public Log rational(long numerator, long denominator, long decimals) { return this; } + @Override + @RestrictHeapAccess(access = RestrictHeapAccess.Access.NO_ALLOCATION, reason = "Must not allocate when logging.") + public Log rational(UnsignedWord numerator, long denominator, long decimals) { + return rational(numerator.rawValue(), denominator, decimals); + } + @Override @RestrictHeapAccess(access = RestrictHeapAccess.Access.NO_ALLOCATION, reason = "Must not allocate when logging.") public Log hex(WordBase value) { diff --git a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/thread/VMOperationControl.java b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/thread/VMOperationControl.java index 7ba4fd2278f1..32f9f3d3bd15 100644 --- a/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/thread/VMOperationControl.java +++ b/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/thread/VMOperationControl.java @@ -39,6 +39,7 @@ import org.graalvm.word.UnsignedWord; import org.graalvm.word.WordFactory; +import com.oracle.svm.core.Isolates; import com.oracle.svm.core.NeverInline; import com.oracle.svm.core.SubstrateOptions; import com.oracle.svm.core.SubstrateOptions.ConcealedOptions; @@ -57,6 +58,7 @@ import com.oracle.svm.core.stack.StackOverflowCheck; import com.oracle.svm.core.thread.VMThreads.SafepointBehavior; import com.oracle.svm.core.thread.VMThreads.StatusSupport; +import com.oracle.svm.core.util.TimeUtils; import com.oracle.svm.core.util.VMError; /** @@ -920,7 +922,7 @@ public void add(VMOpStatus status, VMOperation operation, IsolateThread queueing } public void print(Log log, boolean allowJavaHeapAccess) { - log.string("The ").signed(history.size()).string(" most recent VM operation status changes (oldest first):").indent(true); + log.string("The ").signed(history.size()).string(" most recent VM operation status changes:").indent(true); history.foreach(log, allowJavaHeapAccess ? PRINT_WITH_JAVA_HEAP_DATA : PRINT_WITHOUT_JAVA_HEAP_DATA); log.indent(false); } @@ -967,7 +969,8 @@ private static class VMOpStatusChange { void print(Log log, boolean allowJavaHeapAccess) { VMOpStatus localStatus = status; if (localStatus != null) { - log.unsigned(timestamp).string(" - ").spaces(nestingLevel * 2).string(localStatus.name()); + long uptime = timestamp - Isolates.getCurrentStartTimeMillis(); + log.rational(uptime, TimeUtils.millisPerSecond, 3).string("s - ").spaces(nestingLevel * 2).string(localStatus.name()); if (allowJavaHeapAccess) { log.string(" ").string(name); }