From eba1ca2d1ce6c3050a643836f85dd67a93fab0ec Mon Sep 17 00:00:00 2001 From: baf9884bc6e6 Date: Fri, 9 Dec 2022 13:26:59 +0300 Subject: [PATCH] [GC] Log G1 detailed evacuation info Change-Id: Ie38cbb72cda729ddd8e40f85b0925f1849a81c47 Signed-off-by: baf9884bc6e6 --- libpandabase/options.yaml | 1 + libpandabase/templates/logger.yaml | 1 + runtime/include/time_utils.h | 1 + runtime/mem/gc/g1/g1-gc.cpp | 132 +++++++++++++++++++++++++---- runtime/mem/gc/gc_stats.cpp | 11 +++ runtime/mem/gc/gc_stats.h | 55 ++++++++++++ runtime/mem/rem_set.h | 5 ++ runtime/options.yaml | 1 + runtime/time_utils.cpp | 5 ++ 9 files changed, 196 insertions(+), 16 deletions(-) diff --git a/libpandabase/options.yaml b/libpandabase/options.yaml index ce3c634ba..d9f6bbb0d 100644 --- a/libpandabase/options.yaml +++ b/libpandabase/options.yaml @@ -59,6 +59,7 @@ options: - core - gc - gc_trigger + - gc_detailed - reference_processor - interpreter - compiler diff --git a/libpandabase/templates/logger.yaml b/libpandabase/templates/logger.yaml index 3e5da5751..053fe3569 100644 --- a/libpandabase/templates/logger.yaml +++ b/libpandabase/templates/logger.yaml @@ -34,6 +34,7 @@ components: - name: core - name: gc - name: gc_trigger + - name: gc_detailed - name: reference_processor enum: REF_PROC - name: interpreter diff --git a/runtime/include/time_utils.h b/runtime/include/time_utils.h index 5e3879ae1..50c036097 100644 --- a/runtime/include/time_utils.h +++ b/runtime/include/time_utils.h @@ -35,6 +35,7 @@ public: NO_MOVE_SEMANTIC(Timer); ~Timer(); + uint64_t TimeSinceStart() const; private: uint64_t *duration_; uint64_t start_time_; diff --git a/runtime/mem/gc/g1/g1-gc.cpp b/runtime/mem/gc/g1/g1-gc.cpp index 162109a15..ce153f4a7 100644 --- a/runtime/mem/gc/g1/g1-gc.cpp +++ b/runtime/mem/gc/g1/g1-gc.cpp @@ -235,6 +235,8 @@ void G1GC::RegionPromotionImpl(PandaVector *move { size_t move_size = 0; size_t move_count = 0; + uint64_t duration; + time::Timer promotion_duration(&duration, true); auto object_allocator = this->GetG1ObjectAllocator(); auto promotion_move_checker = [&moved_objects](ObjectHeader *src) { LOG_DEBUG_OBJECT_EVENTS << "PROMOTE YOUNG object " << src; @@ -254,6 +256,8 @@ void G1GC::RegionPromotionImpl(PandaVector *move region->RmvFlag(RegionFlag::IS_COLLECTION_SET); this->mem_stats_.template RecordSizeMovedYoung(move_size); this->mem_stats_.template RecordCountMovedYoung(move_count); + LOG(INFO, GC_DETAILED) << '[' << this->gc_counter_ << "] Region promoted: " << region << " M " << move_size << " D " + << promotion_duration.TimeSinceStart(); } template @@ -405,9 +409,11 @@ void G1GC::RegionCompactingImpl(PandaVector *mov } return ObjectStatus::DEAD_OBJECT; }; + uint64_t duration; // NOLINTNEXTLINE(readability-braces-around-statements) if constexpr (REGION_TYPE == RegionFlag::IS_EDEN) { if (!this->NeedToPromote(region)) { + time::Timer compaction_duration(&duration, true); if (g1_track_freed_objects_) { // We want to track all freed objects, therefore, iterate over all objects in region. object_allocator->template CompactRegion(region, death_checker, @@ -427,6 +433,8 @@ void G1GC::RegionCompactingImpl(PandaVector *mov this->mem_stats_.template RecordCountMovedYoung(move_count); this->mem_stats_.template RecordSizeFreedYoung(delete_size); this->mem_stats_.template RecordCountFreedYoung(delete_count); + LOG(INFO, GC_DETAILED) << '[' << this->gc_counter_ << "] Region compacted: " << region << " M " << move_size + << " D " << compaction_duration.TimeSinceStart(); } else { RegionPromotionImpl(moved_objects, region); } @@ -434,6 +442,7 @@ void G1GC::RegionCompactingImpl(PandaVector *mov } else { ASSERT(region->HasFlag(RegionFlag::IS_OLD)); ASSERT(!region->HasFlag(RegionFlag::IS_NONMOVABLE) && !region->HasFlag(RegionFlag::IS_LARGE_OBJECT)); + time::Timer compaction_duration(&duration, true); if (g1_track_freed_objects_) { // We want to track all freed objects, therefore, iterate over all objects in region. object_allocator->template CompactRegion(region, death_checker, move_checker); @@ -452,6 +461,8 @@ void G1GC::RegionCompactingImpl(PandaVector *mov this->mem_stats_.template RecordCountMovedTenured(move_count); this->mem_stats_.template RecordSizeFreedTenured(delete_size); this->mem_stats_.template RecordCountFreedTenured(delete_count); + LOG(INFO, GC_DETAILED) << '[' << this->gc_counter_ << "] Region compacted: " << region << " M " << move_size + << " D " << compaction_duration.TimeSinceStart(); } } @@ -548,6 +559,54 @@ bool G1GC::NeedFullGC(const panda::GCTask &task) return this->IsExplicitFull(task) || (task.reason == GCTaskCause::OOM_CAUSE); } +void PrintDetailedPauseInfo(GCInstanceStats *stats, uint64_t gc_id) +{ + if (!Logger::IsLoggingOn(Logger::Level::INFO, Logger::Component::GC_DETAILED)) { + return; + } + + Logger::Message msg(Logger::Level::INFO, Logger::Component::GC_DETAILED, false); + auto &stream = msg.GetStream(); + +#define __PHASE_TIME(id) panda::helpers::TimeConverter(stats->GetTimeValue(DetailedTimeTypeStats::id)) + + stream << '[' << gc_id << "] Detailed pause info:" + << "\nWait for RemSet update completion: " << __PHASE_TIME(G1_WAIT_REMSET_UPDATE_COMPLETION_TIME) + << "\nCache references from RemSet: " << __PHASE_TIME(G1_CACHE_REFS_FOR_REMSET_TIME) + << "\nMixed mark: " << __PHASE_TIME(G1_STW_MARK_TIME) + << "\nCollect and move: " << __PHASE_TIME(G1_COLLECT_AND_MOVE_TIME) + << "\n\tCompaction/promotion: " << __PHASE_TIME(G1_COLLECT_AND_MOVE___COMPACTION_TIME) + << "\n\tUpdate references: " << __PHASE_TIME(G1_COLLECT_AND_MOVE___UPDATE_REFS_TIME) + << "\n\tSweep VM references: " << __PHASE_TIME(G1_COLLECT_AND_MOVE___SWEEP_VM_REFS_TIME) + << "\n\tActualize RemSet: " << __PHASE_TIME(G1_COLLECT_AND_MOVE___ACTUALIZE_REMSET_TIME) + << "\nClear dirty cards: " << __PHASE_TIME(G1_CLEAR_CARDS_TIME) + << "\nClear references from RemSet cache: " << __PHASE_TIME(G1_CLEAR_REFS_FROM_REMSET_CACHE_TIME); + +#undef __PHASE_TIME +} + +static void PrintCollectionSetDetails(size_t gc_count, const CollectionSet &collection_set) +{ + if (!Logger::IsLoggingOn(Logger::Level::INFO, Logger::Component::GC_DETAILED)) { + return; + } + + Logger::Message msg {Logger::Level::INFO, Logger::Component::GC_DETAILED, false}; + auto &log = msg.GetStream(); + + log << '[' << gc_count << "] Collection set info:"; + for (auto region : collection_set) { + log << "\nR " << region << ' ' << (region->IsYoung() ? 'Y' : 'T') << ' ' << "A " << region->GetAllocatedBytes() + << " L "; + if (region->IsYoung()) { + log << '-'; + } else { + log << region->GetLiveBytes(); + } + log << " RS " << region->GetRemSet()->RegionsCount(); + } +} + template void G1GC::RunPhasesImpl(panda::GCTask &task) { @@ -555,6 +614,7 @@ void G1GC::RunPhasesImpl(panda::GCTask &task) LOG_DEBUG_GC << "G1GC start, reason: " << task.reason; LOG_DEBUG_GC << "Footprint before GC: " << this->GetPandaVm()->GetMemStats()->GetFootprintHeap(); task.UpdateGCCollectionType(GCCollectionType::YOUNG); + this->GetStats()->ResetDetailedStats(); size_t bytes_in_heap_before_move = this->GetPandaVm()->GetMemStats()->GetFootprintHeap(); { @@ -567,9 +627,13 @@ void G1GC::RunPhasesImpl(panda::GCTask &task) // Check there is no concurrent mark running by another thread. // Atomic with relaxed order reason: concurrent access with another thread which can running GC now ASSERT(pre_wrb_entrypoint_.load(std::memory_order_relaxed) == nullptr); - - WaitForUpdateRemsetThread(); - if (NeedFullGC(task)) { + { + GCScopedDetailedPauseStats detailed_stats( + this->GetStats(), DetailedTimeTypeStats::G1_WAIT_REMSET_UPDATE_COMPLETION_TIME); + WaitForUpdateRemsetThread(); + } + bool is_full = NeedFullGC(task); + if (is_full) { task.collection_type = GCCollectionType::FULL; RunFullGC(task); } else { @@ -599,6 +663,9 @@ void G1GC::RunPhasesImpl(panda::GCTask &task) } } this->GetPandaVm()->GetMemStats()->RecordGCPauseEnd(); + if (!is_full) { + PrintDetailedPauseInfo(this->GetStats(), this->gc_counter_); + } } } if (task.reason == GCTaskCause::MIXED) { @@ -696,6 +763,7 @@ void G1GC::RunMixedGC(panda::GCTask &task, const CollectionSet & time::Timer timer(&young_total_time, true); LOG_DEBUG_GC << "Collect regions size:" << collection_set.size(); UpdateCollectionSet(collection_set); + PrintCollectionSetDetails(this->gc_counter_, collection_set); RunPhasesForRegions(task, collection_set); } if (young_total_time > 0) { @@ -878,11 +946,29 @@ void G1GC::RunGC(GCTask &task, const CollectionSet &collectible_ { // TODO(bwx983476) Measure only those that are on pause time::Timer timer(&young_pause_time, true); - MemRange dirty_cards_range = CacheRefsFromRemsets(); - MixedMark(task, collectible_regions); - CollectAndMove(collectible_regions); - ClearDirtyAndYoungCards(dirty_cards_range); - ClearRefsFromRemsetsCache(); + MemRange dirty_cards_range = [&]() { + GCScopedDetailedPauseStats detailed_stats(this->GetStats(), + DetailedTimeTypeStats::G1_CACHE_REFS_FOR_REMSET_TIME); + return CacheRefsFromRemsets(); + }(); + { + GCScopedDetailedPauseStats detailed_stats(this->GetStats(), DetailedTimeTypeStats::G1_STW_MARK_TIME); + MixedMark(task, collectible_regions); + } + { + GCScopedDetailedPauseStats detailed_stats(this->GetStats(), + DetailedTimeTypeStats::G1_COLLECT_AND_MOVE_TIME); + CollectAndMove(collectible_regions); + } + { + GCScopedDetailedPauseStats detailed_stats(this->GetStats(), DetailedTimeTypeStats::G1_CLEAR_CARDS_TIME); + ClearDirtyAndYoungCards(dirty_cards_range); + } + { + GCScopedDetailedPauseStats detailed_stats(this->GetStats(), + DetailedTimeTypeStats::G1_CLEAR_REFS_FROM_REMSET_CACHE_TIME); + ClearRefsFromRemsetsCache(); + } this->GetObjectGenAllocator()->InvalidateSpaceData(); } if (young_pause_time > 0) { @@ -1029,6 +1115,8 @@ bool G1GC::CollectAndMove(const CollectionSet &collection_set) HeapVerifierIntoGC collect_verifier = this->CollectVerificationInfo(collection_set); { ScopedTiming compact_regions("CompactRegions", *this->GetTiming()); + GCScopedDetailedPauseStats detailed_stats(this->GetStats(), + DetailedTimeTypeStats::G1_COLLECT_AND_MOVE___COMPACTION_TIME); if (!use_gc_workers) { auto vector = internal_allocator->template New>(); moved_objects_vector.push_back(vector); @@ -1045,16 +1133,28 @@ bool G1GC::CollectAndMove(const CollectionSet &collection_set) } } - UpdateRefsToMovedObjects(&moved_objects_vector); + { + GCScopedDetailedPauseStats detailed_stats(this->GetStats(), + DetailedTimeTypeStats::G1_COLLECT_AND_MOVE___UPDATE_REFS_TIME); + UpdateRefsToMovedObjects(&moved_objects_vector); + } this->VerifyCollectAndMove(std::move(collect_verifier), collection_set); - this->GetPandaVm()->SweepVmRefs([this](ObjectHeader *obj) { - if (this->InGCSweepRange(obj)) { - return ObjectStatus::DEAD_OBJECT; - } - return ObjectStatus::ALIVE_OBJECT; - }); + { + GCScopedDetailedPauseStats detailed_stats(this->GetStats(), + DetailedTimeTypeStats::G1_COLLECT_AND_MOVE___SWEEP_VM_REFS_TIME); + this->GetPandaVm()->SweepVmRefs([this](ObjectHeader *obj) { + if (this->InGCSweepRange(obj)) { + return ObjectStatus::DEAD_OBJECT; + } + return ObjectStatus::ALIVE_OBJECT; + }); + } - ActualizeRemSets(); + { + GCScopedDetailedPauseStats detailed_stats(this->GetStats(), + DetailedTimeTypeStats::G1_COLLECT_AND_MOVE___ACTUALIZE_REMSET_TIME); + ActualizeRemSets(); + } auto object_allocator = this->GetG1ObjectAllocator(); if (!collection_set.Young().empty()) { diff --git a/runtime/mem/gc/gc_stats.cpp b/runtime/mem/gc/gc_stats.cpp index 6306ee9b1..40ad23f12 100644 --- a/runtime/mem/gc/gc_stats.cpp +++ b/runtime/mem/gc/gc_stats.cpp @@ -242,6 +242,17 @@ GCScopedPauseStats::~GCScopedPauseStats() stats_->RecordPause(time::GetCurrentTimeInNanos() - start_time_, instance_stats_); } +GCScopedDetailedPauseStats::GCScopedDetailedPauseStats(GCInstanceStats *stats, DetailedTimeTypeStats statistic) + : start_time_(time::GetCurrentTimeInNanos()), stats_(stats), statistic_(statistic) +{ + +} + +GCScopedDetailedPauseStats::~GCScopedDetailedPauseStats() +{ + stats_->SetTimeValue(time::GetCurrentTimeInNanos() - start_time_, statistic_); +} + PandaString GCInstanceStats::GetDump(GCType gc_type) { PandaStringStream statistic; diff --git a/runtime/mem/gc/gc_stats.h b/runtime/mem/gc/gc_stats.h index 5e6e04499..1c0c5dece 100644 --- a/runtime/mem/gc/gc_stats.h +++ b/runtime/mem/gc/gc_stats.h @@ -81,6 +81,28 @@ constexpr size_t ToIndex(TimeTypeStats type) constexpr size_t TIME_TYPE_STATS_SIZE = static_cast(TimeTypeStats::TIME_TYPE_STATS_LAST); +enum class DetailedTimeTypeStats : size_t { + G1_WAIT_REMSET_UPDATE_COMPLETION_TIME = 0, + G1_CACHE_REFS_FOR_REMSET_TIME, + G1_STW_MARK_TIME, + G1_COLLECT_AND_MOVE_TIME, + G1_COLLECT_AND_MOVE___COMPACTION_TIME, + G1_COLLECT_AND_MOVE___UPDATE_REFS_TIME, + G1_COLLECT_AND_MOVE___SWEEP_VM_REFS_TIME, + G1_COLLECT_AND_MOVE___ACTUALIZE_REMSET_TIME, + G1_CLEAR_CARDS_TIME, + G1_CLEAR_REFS_FROM_REMSET_CACHE_TIME, + + DETAILED_TIME_TYPE_STATS_LAST +}; + +constexpr size_t ToIndex(DetailedTimeTypeStats type) +{ + return static_cast(type); +} + +constexpr size_t DETAILED_TIME_TYPE_STATS_SIZE = static_cast(DetailedTimeTypeStats::DETAILED_TIME_TYPE_STATS_LAST); + // scoped specific for GC Stats class GCInstanceStats { public: @@ -111,6 +133,18 @@ public: time_stats_[index].AddValue(value); } + void SetTimeValue(uint64_t value, DetailedTimeTypeStats time_type) + { + auto index = static_cast(time_type); + detailed_time_stats_[index] = value; + } + + uint64_t GetTimeValue(DetailedTimeTypeStats time_type) + { + auto index = static_cast(time_type); + return detailed_time_stats_[index]; + } + void AddReclaimRatioValue(double value) { reclaim_bytes_.AddValue(value); @@ -121,6 +155,11 @@ public: copied_bytes_.AddValue(value); } + void ResetDetailedStats() + { + detailed_time_stats_.fill(0); + } + PandaString GetDump(GCType gc_type); virtual ~GCInstanceStats() = default; @@ -134,6 +173,7 @@ private: std::array, OBJECT_TYPE_STATS_SIZE> objects_stats_; std::array, MEMORY_TYPE_STATS_SIZE> memory_stats_; std::array, TIME_TYPE_STATS_SIZE> time_stats_; + std::array detailed_time_stats_; SimpleHistogram reclaim_bytes_; SimpleHistogram copied_bytes_; }; @@ -170,6 +210,21 @@ private: GCStats *stats_; }; +class GCScopedDetailedPauseStats { +public: + GCScopedDetailedPauseStats(GCInstanceStats *stats, DetailedTimeTypeStats statistic); + + NO_COPY_SEMANTIC(GCScopedDetailedPauseStats); + NO_MOVE_SEMANTIC(GCScopedDetailedPauseStats); + + ~GCScopedDetailedPauseStats(); + +private: + uint64_t start_time_; + GCInstanceStats *stats_; + DetailedTimeTypeStats statistic_; +}; + class GCStats { public: explicit GCStats(MemStatsType *mem_stats, GCType gc_type_from_runtime, InternalAllocatorPtr allocator); diff --git a/runtime/mem/rem_set.h b/runtime/mem/rem_set.h index e5e8f76ff..96820ce42 100644 --- a/runtime/mem/rem_set.h +++ b/runtime/mem/rem_set.h @@ -60,6 +60,11 @@ public: template static void InvalidateRefsFromRegion(Region *invalid_region); + size_t RegionsCount() const + { + return regions_.size(); + } + /** * Used in the barrier. Record the reference from the region of obj_addr to the region of value_addr. * @param obj_addr - address of the object diff --git a/runtime/options.yaml b/runtime/options.yaml index 936fedaa2..a81edb22a 100644 --- a/runtime/options.yaml +++ b/runtime/options.yaml @@ -151,6 +151,7 @@ options: - core - gc - gc_trigger + - gc_detailed - reference_processor - interpreter - compiler diff --git a/runtime/time_utils.cpp b/runtime/time_utils.cpp index 0e9132d26..7fa5cf07d 100644 --- a/runtime/time_utils.cpp +++ b/runtime/time_utils.cpp @@ -35,6 +35,11 @@ Timer::~Timer() *duration_ += GetCurrentTimeInNanos() - start_time_; } +uint64_t Timer::TimeSinceStart() const +{ + return GetCurrentTimeInNanos() - start_time_; +} + PandaString GetCurrentTimeString() { PandaOStringStream result_stream; -- Gitee