azalea/kotlin-fork
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

[K/N] Tweak GC logs ^KT-55364

Browse Source 
In info log one big chunk at the end of the GC iteration.
This commit is contained in:
Alexander Shabalin
2023-04-11 13:01:57 +02:00
committed by Space Cloud
parent f4c89148b8
commit 18b6351d5d
5 changed files with 48 additions and 37 deletions
Download Patch File Download Diff File Expand all files Collapse all files
kotlin-native/runtime/src/gc/cms/cpp/ConcurrentMarkAndSweep.cpp
+3 -1
View File
@@ -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();
kotlin-native/runtime/src/gc/common/cpp/GCSchedulerImpl.hpp
+2
View File
@@ -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_();
}
}
kotlin-native/runtime/src/gc/common/cpp/GCStatistics.cpp
+41 -36
View File
@@ -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<KLong>(epoch);
current.startTime = static_cast<KLong>(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 == &current) {
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<KLong>(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<KLong>(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) {}
kotlin-native/runtime/src/gc/common/cpp/GCStatistics.hpp
+1
View File
@@ -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;
kotlin-native/runtime/src/gc/stms/cpp/SameThreadMarkAndSweep.cpp
+1
View File
@@ -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) {