More advanced timing loggers.
The new timing loggers have lower overhead since they only push into
a vector. The new format has two types, a start timing and a stop
timing. You can thing of these as brackets associated with a
timestamp. It uses these to construct various statistics when needed,
such as: Total time, exclusive time, and nesting depth.
Changed PrettyDuration to have a default of 3 digits after the decimal
point.
Exaple of a GC dump with exclusive / total times and indenting:
I/art (23546): GC iteration timing logger [Exclusive time] [Total time]
I/art (23546): 0ms InitializePhase
I/art (23546): 0.305ms/167.746ms MarkingPhase
I/art (23546): 0ms BindBitmaps
I/art (23546): 0ms FindDefaultSpaceBitmap
I/art (23546): 0ms/1.709ms ProcessCards
I/art (23546): 0.183ms ImageModUnionClearCards
I/art (23546): 0.916ms ZygoteModUnionClearCards
I/art (23546): 0.610ms AllocSpaceClearCards
I/art (23546): 1.373ms AllocSpaceClearCards
I/art (23546): 0.305ms/6.318ms MarkRoots
I/art (23546): 2.106ms MarkRootsCheckpoint
I/art (23546): 0.153ms MarkNonThreadRoots
I/art (23546): 4.287ms MarkConcurrentRoots
I/art (23546): 43.461ms UpdateAndMarkImageModUnionTable
I/art (23546): 0ms/112.712ms RecursiveMark
I/art (23546): 112.712ms ProcessMarkStack
I/art (23546): 0.610ms/2.777ms PreCleanCards
I/art (23546): 0.305ms/0.855ms ProcessCards
I/art (23546): 0.153ms ImageModUnionClearCards
I/art (23546): 0.610ms ZygoteModUnionClearCards
I/art (23546): 0.610ms AllocSpaceClearCards
I/art (23546): 0.549ms AllocSpaceClearCards
I/art (23546): 0.549ms MarkRootsCheckpoint
I/art (23546): 0.610ms MarkNonThreadRoots
I/art (23546): 0ms MarkConcurrentRoots
I/art (23546): 0.610ms ScanGrayImageSpaceObjects
I/art (23546): 0.305ms ScanGrayZygoteSpaceObjects
I/art (23546): 0.305ms ScanGrayAllocSpaceObjects
I/art (23546): 1.129ms ScanGrayAllocSpaceObjects
I/art (23546): 0ms ProcessMarkStack
I/art (23546): 0ms/0.977ms (Paused)PausePhase
I/art (23546): 0.244ms ReMarkRoots
I/art (23546): 0.672ms (Paused)ScanGrayObjects
I/art (23546): 0ms (Paused)ProcessMarkStack
I/art (23546): 0ms/0.610ms SwapStacks
I/art (23546): 0.610ms RevokeAllThreadLocalAllocationStacks
I/art (23546): 0ms PreSweepingGcVerification
I/art (23546): 0ms/10.621ms ReclaimPhase
I/art (23546): 0.610ms/0.702ms ProcessReferences
I/art (23546): 0.214ms/0.641ms EnqueueFinalizerReferences
I/art (23546): 0.427ms ProcessMarkStack
I/art (23546): 0.488ms SweepSystemWeaks
I/art (23546): 0.824ms/9.400ms Sweep
I/art (23546): 0ms SweepMallocSpace
I/art (23546): 0.214ms SweepZygoteSpace
I/art (23546): 0.122ms SweepMallocSpace
I/art (23546): 6.226ms SweepMallocSpace
I/art (23546): 0ms SweepMallocSpace
I/art (23546): 2.144ms SweepLargeObjects
I/art (23546): 0.305ms SwapBitmaps
I/art (23546): 0ms UnBindBitmaps
I/art (23546): 0.275ms FinishPhase
I/art (23546): GC iteration timing logger: end, 178.971ms
Change-Id: Ia55b65609468f212b3cd65cda66b843da42be645
diff --git a/runtime/gc/heap.cc b/runtime/gc/heap.cc
index 6c63e5f..03ae8c3 100644
--- a/runtime/gc/heap.cc
+++ b/runtime/gc/heap.cc
@@ -1580,6 +1580,7 @@
};
void Heap::UnBindBitmaps() {
+ TimingLogger::ScopedTiming t("UnBindBitmaps", GetCurrentGcIteration()->GetTimings());
for (const auto& space : GetContinuousSpaces()) {
if (space->IsContinuousMemMapAllocSpace()) {
space::ContinuousMemMapAllocSpace* alloc_space = space->AsContinuousMemMapAllocSpace();
@@ -1848,7 +1849,7 @@
const size_t duration = GetCurrentGcIteration()->GetDurationNs();
const std::vector<uint64_t>& pause_times = GetCurrentGcIteration()->GetPauseTimes();
// Print the GC if it is an explicit GC (e.g. Runtime.gc()) or a slow GC
- // (mutator time blocked >= long_pause_log_threshold_).
+ // (mutator time blocked >= long_pause_log_threshold_).
bool log_gc = gc_cause == kGcCauseExplicit;
if (!log_gc && CareAboutPauseTimes()) {
// GC for alloc pauses the allocating thread, so consider it as a pause.
@@ -2314,6 +2315,7 @@
}
void Heap::ProcessCards(TimingLogger* timings, bool use_rem_sets) {
+ TimingLogger::ScopedTiming t(__FUNCTION__, timings);
// Clear cards and keep track of cards cleared in the mod-union table.
for (const auto& space : continuous_spaces_) {
accounting::ModUnionTable* table = FindModUnionTableFromSpace(space);
@@ -2321,15 +2323,15 @@
if (table != nullptr) {
const char* name = space->IsZygoteSpace() ? "ZygoteModUnionClearCards" :
"ImageModUnionClearCards";
- TimingLogger::ScopedSplit split(name, timings);
+ TimingLogger::ScopedTiming t(name, timings);
table->ClearCards();
} else if (use_rem_sets && rem_set != nullptr) {
DCHECK(collector::SemiSpace::kUseRememberedSet && collector_type_ == kCollectorTypeGSS)
<< static_cast<int>(collector_type_);
- TimingLogger::ScopedSplit split("AllocSpaceRemSetClearCards", timings);
+ TimingLogger::ScopedTiming t("AllocSpaceRemSetClearCards", timings);
rem_set->ClearCards();
} else if (space->GetType() != space::kSpaceTypeBumpPointerSpace) {
- TimingLogger::ScopedSplit split("AllocSpaceClearCards", timings);
+ TimingLogger::ScopedTiming t("AllocSpaceClearCards", timings);
// No mod union table for the AllocSpace. Age the cards so that the GC knows that these cards
// were dirty before the GC started.
// TODO: Need to use atomic for the case where aged(cleaning thread) -> dirty(other thread)
@@ -2349,8 +2351,9 @@
void Heap::PreGcVerificationPaused(collector::GarbageCollector* gc) {
Thread* const self = Thread::Current();
TimingLogger* const timings = current_gc_iteration_.GetTimings();
+ TimingLogger::ScopedTiming t(__FUNCTION__, timings);
if (verify_pre_gc_heap_) {
- TimingLogger::ScopedSplit split("PreGcVerifyHeapReferences", timings);
+ TimingLogger::ScopedTiming t("(Paused)PreGcVerifyHeapReferences", timings);
ReaderMutexLock mu(self, *Locks::heap_bitmap_lock_);
size_t failures = VerifyHeapReferences();
if (failures > 0) {
@@ -2360,7 +2363,7 @@
}
// Check that all objects which reference things in the live stack are on dirty cards.
if (verify_missing_card_marks_) {
- TimingLogger::ScopedSplit split("PreGcVerifyMissingCardMarks", timings);
+ TimingLogger::ScopedTiming t("(Paused)PreGcVerifyMissingCardMarks", timings);
ReaderMutexLock mu(self, *Locks::heap_bitmap_lock_);
SwapStacks(self);
// Sort the live stack so that we can quickly binary search it later.
@@ -2370,7 +2373,7 @@
SwapStacks(self);
}
if (verify_mod_union_table_) {
- TimingLogger::ScopedSplit split("PreGcVerifyModUnionTables", timings);
+ TimingLogger::ScopedTiming t("(Paused)PreGcVerifyModUnionTables", timings);
ReaderMutexLock reader_lock(self, *Locks::heap_bitmap_lock_);
for (const auto& table_pair : mod_union_tables_) {
accounting::ModUnionTable* mod_union_table = table_pair.second;
@@ -2397,10 +2400,11 @@
void Heap::PreSweepingGcVerification(collector::GarbageCollector* gc) {
Thread* const self = Thread::Current();
TimingLogger* const timings = current_gc_iteration_.GetTimings();
+ TimingLogger::ScopedTiming t(__FUNCTION__, timings);
// Called before sweeping occurs since we want to make sure we are not going so reclaim any
// reachable objects.
if (verify_pre_sweeping_heap_) {
- TimingLogger::ScopedSplit split("PostSweepingVerifyHeapReferences", timings);
+ TimingLogger::ScopedTiming t("(Paused)PostSweepingVerifyHeapReferences", timings);
CHECK_NE(self->GetState(), kRunnable);
WriterMutexLock mu(self, *Locks::heap_bitmap_lock_);
// Swapping bound bitmaps does nothing.
@@ -2423,16 +2427,17 @@
// Only pause if we have to do some verification.
Thread* const self = Thread::Current();
TimingLogger* const timings = GetCurrentGcIteration()->GetTimings();
+ TimingLogger::ScopedTiming t(__FUNCTION__, timings);
if (verify_system_weaks_) {
ReaderMutexLock mu2(self, *Locks::heap_bitmap_lock_);
collector::MarkSweep* mark_sweep = down_cast<collector::MarkSweep*>(gc);
mark_sweep->VerifySystemWeaks();
}
if (verify_post_gc_rosalloc_) {
- RosAllocVerification(timings, "PostGcRosAllocVerification");
+ RosAllocVerification(timings, "(Paused)PostGcRosAllocVerification");
}
if (verify_post_gc_heap_) {
- TimingLogger::ScopedSplit split("PostGcVerifyHeapReferences", timings);
+ TimingLogger::ScopedTiming t("(Paused)PostGcVerifyHeapReferences", timings);
ReaderMutexLock mu(self, *Locks::heap_bitmap_lock_);
size_t failures = VerifyHeapReferences();
if (failures > 0) {
@@ -2450,7 +2455,7 @@
}
void Heap::RosAllocVerification(TimingLogger* timings, const char* name) {
- TimingLogger::ScopedSplit split(name, timings);
+ TimingLogger::ScopedTiming t(name, timings);
for (const auto& space : continuous_spaces_) {
if (space->IsRosAllocSpace()) {
VLOG(heap) << name << " : " << space->GetName();