diff --git a/kotlin-native/runtime/src/gc/cms/cpp/ConcurrentMarkAndSweep.cpp b/kotlin-native/runtime/src/gc/cms/cpp/ConcurrentMarkAndSweep.cpp index dbf43f9a76e..a51b4b2c68c 100644 --- a/kotlin-native/runtime/src/gc/cms/cpp/ConcurrentMarkAndSweep.cpp +++ b/kotlin-native/runtime/src/gc/cms/cpp/ConcurrentMarkAndSweep.cpp @@ -65,17 +65,20 @@ void gc::ConcurrentMarkAndSweep::ThreadData::SafePointAllocation(size_t size) no } void gc::ConcurrentMarkAndSweep::ThreadData::Schedule() noexcept { + RuntimeLogInfo({kTagGC}, "Scheduling GC manually"); ThreadStateGuard guard(ThreadState::kNative); gc_.state_.schedule(); } void gc::ConcurrentMarkAndSweep::ThreadData::ScheduleAndWaitFullGC() noexcept { + RuntimeLogInfo({kTagGC}, "Scheduling GC manually"); ThreadStateGuard guard(ThreadState::kNative); auto scheduled_epoch = gc_.state_.schedule(); gc_.state_.waitEpochFinished(scheduled_epoch); } void gc::ConcurrentMarkAndSweep::ThreadData::ScheduleAndWaitFullGCWithFinalizers() noexcept { + RuntimeLogInfo({kTagGC}, "Scheduling GC manually"); ThreadStateGuard guard(ThreadState::kNative); auto scheduled_epoch = gc_.state_.schedule(); gc_.state_.waitEpochFinalized(scheduled_epoch); @@ -115,7 +118,6 @@ gc::ConcurrentMarkAndSweep::ConcurrentMarkAndSweep( state_.finalized(epoch); })) { gcScheduler_.SetScheduleGC([this]() NO_INLINE { - RuntimeLogDebug({kTagGC}, "Scheduling GC by thread %d", konan::currentThreadId()); // This call acquires a lock, so we need to ensure that we're in the safe state. NativeOrUnregisteredThreadGuard guard(/* reentrant = */ true); state_.schedule(); diff --git a/kotlin-native/runtime/src/gc/common/cpp/GCSchedulerImpl.hpp b/kotlin-native/runtime/src/gc/common/cpp/GCSchedulerImpl.hpp index 2c66aef2a03..c08ca065eb2 100644 --- a/kotlin-native/runtime/src/gc/common/cpp/GCSchedulerImpl.hpp +++ b/kotlin-native/runtime/src/gc/common/cpp/GCSchedulerImpl.hpp @@ -140,6 +140,7 @@ public: return; } if (regularIntervalPacer_.NeedsGC()) { + RuntimeLogInfo({kTagGC}, "Scheduling GC by timer"); scheduleGC_(); } }) {} @@ -147,6 +148,7 @@ public: void UpdateFromThreadData(gc::GCSchedulerThreadData& threadData) noexcept override { heapGrowthController_.OnAllocated(threadData.allocatedBytes()); if (heapGrowthController_.NeedsGC()) { + RuntimeLogInfo({kTagGC}, "Scheduling GC by allocation"); scheduleGC_(); } } diff --git a/kotlin-native/runtime/src/gc/common/cpp/GCStatistics.cpp b/kotlin-native/runtime/src/gc/common/cpp/GCStatistics.cpp index 651a446fbe9..6c20295f8c1 100644 --- a/kotlin-native/runtime/src/gc/common/cpp/GCStatistics.cpp +++ b/kotlin-native/runtime/src/gc/common/cpp/GCStatistics.cpp @@ -123,7 +123,7 @@ GCHandle GCHandle::create(uint64_t epoch) { if (current.epoch) { last = current; current = {}; - RuntimeLogWarning({kTagGC}, "Starting new GC epoch, while previous is not finished\n"); + GCLogWarning(epoch, "Starting new GC epoch, while previous is not finished"); } current.epoch = static_cast(epoch); current.startTime = static_cast(konan::getTimeNanos()); @@ -159,11 +159,43 @@ void GCHandle::finished() { stat->rootSet->threadLocalReferences, stat->rootSet->stackReferences, stat->rootSet->globalReferences, stat->rootSet->stableReferences, stat->rootSet->total()); } + if (stat->markStats) { + GCLogInfo(epoch_, "Mark: %" PRIu64 " objects.", stat->markStats->objectsCount); + } + if (stat->memoryUsageAfter.extra && stat->memoryUsageBefore.extra) { + GCLogInfo( + epoch_, "Sweep extra objects: swept %" PRIu64 " objects, kept %" PRIu64 " objects", + stat->memoryUsageBefore.extra->objectsCount - stat->memoryUsageAfter.extra->objectsCount, stat->memoryUsageAfter.extra->objectsCount); + } + if (stat->memoryUsageBefore.heap && stat->memoryUsageAfter.heap) { + GCLogInfo( + epoch_, "Sweep: swept %" PRIu64 " objects, kept %" PRIu64 " objects", + stat->memoryUsageBefore.heap->objectsCount - stat->memoryUsageAfter.heap->objectsCount, stat->memoryUsageAfter.heap->objectsCount); + GCLogInfo( + epoch_, "Heap memory usage: before %" PRIu64 " bytes, after %" PRIu64 " bytes", stat->memoryUsageBefore.heap->totalObjectsSize, + stat->memoryUsageAfter.heap->totalObjectsSize); + } + if (stat->pauseStartTime && stat->pauseEndTime) { + auto time = (*stat->pauseEndTime - *stat->pauseStartTime) / 1000; + GCLogInfo(epoch_, "Mutators pause time: %" PRIu64 " microseconds.", time); + } if (stat->startTime) { auto time = (*current.endTime - *current.startTime) / 1000; GCLogInfo(epoch_, "Finished. Total GC epoch time is %" PRId64" microseconds.", time); } + + if (auto usage = stat->memoryUsageAfter.heap; usage && stat->markStats) { + RuntimeAssert( + stat->markStats->objectsCount == usage->objectsCount, + "Mismatch in statistics: marked %" PRId64 " objects, while %" PRId64 " is alive after sweep", + stat->markStats->objectsCount, usage->objectsCount); + RuntimeAssert( + stat->markStats->totalObjectsSize == usage->totalObjectsSize, + "Mismatch in statistics: total marked size is %" PRId64 " bytes, while %" PRId64 " bytes is alive after sweep", + stat->markStats->totalObjectsSize, usage->totalObjectsSize); + } + if (stat == ¤t) { last = current; current = {}; @@ -172,7 +204,7 @@ void GCHandle::finished() { } void GCHandle::suspensionRequested() { std::lock_guard guard(lock); - GCLogDebug(epoch_, "Requested thread suspension by thread %d", konan::currentThreadId()); + GCLogDebug(epoch_, "Requested thread suspension"); if (auto* stat = statByEpoch(epoch_)) { stat->pauseStartTime = static_cast(konan::getTimeNanos()); } @@ -182,7 +214,7 @@ void GCHandle::threadsAreSuspended() { if (auto* stat = statByEpoch(epoch_)) { if (stat->pauseStartTime) { auto time = (konan::getTimeNanos() - *stat->pauseStartTime) / 1000; - GCLogInfo(epoch_, "Suspended all threads in %" PRIu64 " microseconds", time); + GCLogDebug(epoch_, "Suspended all threads in %" PRIu64 " microseconds", time); return; } } @@ -193,7 +225,7 @@ void GCHandle::threadsAreResumed() { stat->pauseEndTime = static_cast(konan::getTimeNanos()); if (stat->pauseStartTime) { auto time = (*stat->pauseEndTime - *stat->pauseStartTime) / 1000; - GCLogInfo(epoch_, "Resume all threads. Total pause time is %" PRId64 " microseconds.", time); + GCLogDebug(epoch_, "Resume all threads. Total pause time is %" PRId64 " microseconds.", time); return; } } @@ -206,12 +238,13 @@ void GCHandle::finalizersDone() { auto time = (*stat->finalizersDoneTime - *stat->endTime) / 1000; GCLogInfo(epoch_, "Finalization is done in %" PRId64 " microseconds after epoch end.", time); return; + } else { + GCLogInfo(epoch_, "Finalization is done."); } } - GCLogInfo(epoch_, "Finalization is done."); } void GCHandle::finalizersScheduled(uint64_t finalizersCount) { - GCLogInfo(epoch_, "Finalization is scheduled for %" PRIu64 " objects.", finalizersCount); + GCLogDebug(epoch_, "Finalization is scheduled for %" PRIu64 " objects.", finalizersCount); } void GCHandle::threadRootSetCollected(mm::ThreadData &threadData, uint64_t threadLocalReferences, uint64_t stackReferences) { std::lock_guard guard(lock); @@ -267,25 +300,6 @@ void GCHandle::heapUsageAfter(MemoryUsage usage) { std::lock_guard guard(lock); if (auto* stat = statByEpoch(epoch_)) { stat->memoryUsageAfter.heap = usage; - if (stat->memoryUsageBefore.heap) { - GCLogInfo( - epoch_, - "Collected %" PRId64 " heap objects of total size %" PRId64 " bytes. " - "%" PRId64 " heap objects of total size %" PRId64 " bytes are still alive.", - stat->memoryUsageBefore.heap->objectsCount - stat->memoryUsageAfter.heap->objectsCount, - stat->memoryUsageBefore.heap->totalObjectsSize - stat->memoryUsageAfter.heap->totalObjectsSize, - stat->memoryUsageAfter.heap->objectsCount, stat->memoryUsageAfter.heap->totalObjectsSize); - } - if (stat->markStats) { - RuntimeAssert( - stat->markStats->objectsCount == usage.objectsCount, - "Mismatch in statistics: marked %" PRId64 " objects, while %" PRId64 " is alive after sweep", - stat->markStats->objectsCount, usage.objectsCount); - RuntimeAssert( - stat->markStats->totalObjectsSize == usage.totalObjectsSize, - "Mismatch in statistics: total marked size is %" PRId64 " bytes, while %" PRId64 " bytes is alive after sweep", - stat->markStats->totalObjectsSize, usage.totalObjectsSize); - } } } @@ -299,15 +313,6 @@ void GCHandle::extraObjectsUsageAfter(MemoryUsage usage) { std::lock_guard guard(lock); if (auto* stat = statByEpoch(epoch_)) { stat->memoryUsageAfter.extra = usage; - if (stat->memoryUsageBefore.extra) { - GCLogInfo( - epoch_, - "Collected %" PRId64 " extra objects of total size %" PRId64 ". " - "%" PRId64 " extra objects of total size %" PRId64 " are still alive.", - stat->memoryUsageBefore.extra->objectsCount - stat->memoryUsageAfter.extra->objectsCount, - stat->memoryUsageBefore.extra->totalObjectsSize - stat->memoryUsageAfter.extra->totalObjectsSize, - stat->memoryUsageAfter.extra->objectsCount, stat->memoryUsageAfter.extra->totalObjectsSize); - } } } @@ -367,8 +372,8 @@ GCHandle::GCMarkScope::GCMarkScope(kotlin::gc::GCHandle& handle) : handle_(handl GCHandle::GCMarkScope::~GCMarkScope() { handle_.marked(MemoryUsage{objectsCount, totalObjectSizeBytes}); GCLogDebug(handle_.getEpoch(), - "Marked %" PRIu64 " objects in %" PRIu64 " microseconds in thread %d", - objectsCount, getStageTime(), konan::currentThreadId()); + "Marked %" PRIu64 " objects in %" PRIu64 " microseconds", + objectsCount, getStageTime()); } gc::GCHandle::GCProcessWeaksScope::GCProcessWeaksScope(gc::GCHandle& handle) noexcept : handle_(handle) {} diff --git a/kotlin-native/runtime/src/gc/common/cpp/GCStatistics.hpp b/kotlin-native/runtime/src/gc/common/cpp/GCStatistics.hpp index a0f80d250cc..9d335986302 100644 --- a/kotlin-native/runtime/src/gc/common/cpp/GCStatistics.hpp +++ b/kotlin-native/runtime/src/gc/common/cpp/GCStatistics.hpp @@ -14,6 +14,7 @@ #define GCLogInfo(epoch, format, ...) RuntimeLogInfo({kTagGC}, "Epoch #%" PRIu64 ": " format, epoch, ##__VA_ARGS__) #define GCLogDebug(epoch, format, ...) RuntimeLogDebug({kTagGC}, "Epoch #%" PRIu64 ": " format, epoch, ##__VA_ARGS__) +#define GCLogWarning(epoch, format, ...) RuntimeLogWarning({kTagGC}, "Epoch #%" PRIu64 ": " format, epoch, ##__VA_ARGS__) namespace kotlin::mm { class ThreadData; diff --git a/kotlin-native/runtime/src/gc/stms/cpp/SameThreadMarkAndSweep.cpp b/kotlin-native/runtime/src/gc/stms/cpp/SameThreadMarkAndSweep.cpp index 163c22d7875..916e4302b0b 100644 --- a/kotlin-native/runtime/src/gc/stms/cpp/SameThreadMarkAndSweep.cpp +++ b/kotlin-native/runtime/src/gc/stms/cpp/SameThreadMarkAndSweep.cpp @@ -65,6 +65,7 @@ void gc::SameThreadMarkAndSweep::ThreadData::SafePointAllocation(size_t size) no } void gc::SameThreadMarkAndSweep::ThreadData::ScheduleAndWaitFullGC() noexcept { + RuntimeLogInfo({kTagGC}, "Scheduling GC manually"); auto didGC = gc_.PerformFullGC(); if (!didGC) {