AuroraMiddleware/v8
1
0
Fork 0
Code Issues 2 Pull Requests Releases Wiki Activity

[heap] GCTracer: Record details for incremental marking

Browse Source 
Record details, such as cumulative duration, number of steps, and longest steps
in IncrementalMarkingDetails which get populated at a single callsite
(AddScopeSample). Remove member fields that thus become obsolete (unfortunately
not all of them).

Additional remove some dead code and refactor printing. Printing in a single
statement allows for using logcat on Android.

This should also address the regression in chromium:640524.

BUG=chromium:639818,chromium:640524
R=jochen@chromium.org

Review-Url: https://codereview.chromium.org/2269093002
Cr-Commit-Position: refs/heads/master@{#38912}
This commit is contained in:
mlippautz 2016-08-25 07:21:59 -07:00 committed by Commit bot
parent 5e8acf6301
commit 3866975f1b
4 changed files with 259 additions and 303 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

358
src/heap/gc-tracer.cc
View File

@ -40,16 +40,6 @@ GCTracer::Scope::~Scope() {
}
}
void GCTracer::AddScopeSample(Scope::ScopeId scope, double duration) {
DCHECK(scope < Scope::NUMBER_OF_SCOPES);
if (scope >= Scope::FIRST_INCREMENTAL_SCOPE &&
scope <= Scope::LAST_INCREMENTAL_SCOPE) {
cumulative_incremental_scopes_[scope] += duration;
} else {
current_.scopes[scope] += duration;
}
}
const char* GCTracer::Scope::Name(ScopeId id) {
#define CASE(scope) \
case Scope::scope: \
@ -79,23 +69,10 @@ GCTracer::Event::Event(Type type, const char* gc_reason,
end_holes_size(0),
new_space_object_size(0),
survived_new_space_object_size(0),
cumulative_incremental_marking_steps(0),
incremental_marking_steps(0),
cumulative_incremental_marking_bytes(0),
incremental_marking_bytes(0),
cumulative_incremental_marking_duration(0.0),
incremental_marking_duration(0.0),
cumulative_pure_incremental_marking_duration(0.0),
pure_incremental_marking_duration(0.0),
longest_incremental_marking_step(0.0),
cumulative_incremental_marking_finalization_steps(0),
cumulative_incremental_marking_finalizaton_duration(0),
longest_incremental_marking_finalization_step(0),
incremental_marking_finalizaton_steps(0),
incremental_marking_finalization_duration(0) {
for (int i = 0; i < Scope::NUMBER_OF_INCREMENTAL_SCOPES; i++) {
cumulative_incremental_scopes[i] = 0;
}
pure_incremental_marking_duration(0.0) {
for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
scopes[i] = 0;
}
@ -127,17 +104,14 @@ const char* GCTracer::Event::TypeName(bool short_name) const {
return "Unknown Event Type";
}
GCTracer::GCTracer(Heap* heap)
: heap_(heap),
cumulative_incremental_marking_steps_(0),
current_(Event::START, nullptr, nullptr),
previous_(current_),
previous_incremental_mark_compactor_event_(current_),
cumulative_incremental_marking_bytes_(0),
cumulative_incremental_marking_duration_(0.0),
cumulative_pure_incremental_marking_duration_(0.0),
longest_incremental_marking_step_(0.0),
cumulative_incremental_marking_finalization_steps_(0),
cumulative_incremental_marking_finalization_duration_(0.0),
longest_incremental_marking_finalization_step_(0.0),
cumulative_marking_duration_(0.0),
cumulative_sweeping_duration_(0.0),
allocation_time_ms_(0.0),
@ -148,20 +122,13 @@ GCTracer::GCTracer(Heap* heap)
old_generation_allocation_in_bytes_since_gc_(0),
combined_mark_compact_speed_cache_(0.0),
start_counter_(0) {
current_ = Event(Event::START, NULL, NULL);
current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
previous_ = previous_incremental_mark_compactor_event_ = current_;
}
void GCTracer::ResetForTesting() {
cumulative_incremental_marking_steps_ = 0.0;
cumulative_incremental_marking_bytes_ = 0.0;
cumulative_incremental_marking_duration_ = 0.0;
cumulative_pure_incremental_marking_duration_ = 0.0;
longest_incremental_marking_step_ = 0.0;
cumulative_incremental_marking_finalization_steps_ = 0.0;
cumulative_incremental_marking_finalization_duration_ = 0.0;
longest_incremental_marking_finalization_step_ = 0.0;
cumulative_marking_duration_ = 0.0;
cumulative_sweeping_duration_ = 0.0;
allocation_time_ms_ = 0.0;
@ -173,7 +140,9 @@ void GCTracer::ResetForTesting() {
combined_mark_compact_speed_cache_ = 0.0;
start_counter_ = 0;
for (int i = 0; i < Scope::NUMBER_OF_INCREMENTAL_SCOPES; i++) {
cumulative_incremental_scopes_[i] = 0;
incremental_marking_scopes_[i].cumulative_duration = 0.0;
incremental_marking_scopes_[i].steps = 0;
incremental_marking_scopes_[i].longest_step = 0.0;
}
current_ = Event(Event::START, NULL, NULL);
current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
@ -211,21 +180,10 @@ void GCTracer::Start(GarbageCollector collector, const char* gc_reason,
current_.new_space_object_size =
heap_->new_space()->top() - heap_->new_space()->bottom();
current_.cumulative_incremental_marking_steps =
cumulative_incremental_marking_steps_;
current_.cumulative_incremental_marking_bytes =
cumulative_incremental_marking_bytes_;
current_.cumulative_incremental_marking_duration =
cumulative_incremental_marking_duration_;
current_.cumulative_pure_incremental_marking_duration =
cumulative_pure_incremental_marking_duration_;
current_.longest_incremental_marking_step = longest_incremental_marking_step_;
current_.cumulative_incremental_marking_finalization_steps =
cumulative_incremental_marking_finalization_steps_;
current_.cumulative_incremental_marking_finalizaton_duration =
cumulative_incremental_marking_finalization_duration_;
current_.longest_incremental_marking_finalization_step =
longest_incremental_marking_finalization_step_;
for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
current_.scopes[i] = 0;
@ -243,12 +201,27 @@ void GCTracer::Start(GarbageCollector collector, const char* gc_reason,
}
}
void GCTracer::MergeBaseline(const Event& baseline) {
current_.incremental_marking_bytes =
current_.cumulative_incremental_marking_bytes -
baseline.cumulative_incremental_marking_bytes;
current_.pure_incremental_marking_duration =
current_.cumulative_pure_incremental_marking_duration -
baseline.cumulative_pure_incremental_marking_duration;
for (int i = Scope::FIRST_INCREMENTAL_SCOPE;
i <= Scope::LAST_INCREMENTAL_SCOPE; i++) {
current_.scopes[i] =
current_.incremental_marking_scopes[i].cumulative_duration -
baseline.incremental_marking_scopes[i].cumulative_duration;
}
}
void GCTracer::Stop(GarbageCollector collector) {
start_counter_--;
if (start_counter_ != 0) {
Output("[Finished reentrant %s during %s.]\n",
collector == SCAVENGER ? "Scavenge" : "Mark-sweep",
current_.TypeName(false));
PrintIsolate(heap_->isolate(), "[Finished reentrant %s during %s.]\n",
collector == SCAVENGER ? "Scavenge" : "Mark-sweep",
current_.TypeName(false));
return;
}
@ -260,8 +233,7 @@ void GCTracer::Stop(GarbageCollector collector) {
for (int i = Scope::FIRST_INCREMENTAL_SCOPE;
i <= Scope::LAST_INCREMENTAL_SCOPE; i++) {
current_.cumulative_incremental_scopes[i] =
cumulative_incremental_scopes_[i];
current_.incremental_marking_scopes[i] = incremental_marking_scopes_[i];
}
current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
@ -281,57 +253,31 @@ void GCTracer::Stop(GarbageCollector collector) {
double duration = current_.end_time - current_.start_time;
const Event* baseline = nullptr;
if (current_.type == Event::SCAVENGER) {
baseline = &previous_;
MergeBaseline(previous_);
recorded_scavenges_total_.Push(
MakeBytesAndDuration(current_.new_space_object_size, duration));
recorded_scavenges_survived_.Push(MakeBytesAndDuration(
current_.survived_new_space_object_size, duration));
} else if (current_.type == Event::INCREMENTAL_MARK_COMPACTOR) {
baseline = &previous_incremental_mark_compactor_event_;
longest_incremental_marking_step_ = 0.0;
longest_incremental_marking_finalization_step_ = 0.0;
MergeBaseline(previous_incremental_mark_compactor_event_);
recorded_incremental_marking_steps_.Push(
MakeBytesAndDuration(current_.incremental_marking_bytes,
current_.pure_incremental_marking_duration));
recorded_incremental_mark_compacts_.Push(
MakeBytesAndDuration(current_.start_object_size, duration));
combined_mark_compact_speed_cache_ = 0.0;
for (int i = 0; i <= Scope::NUMBER_OF_INCREMENTAL_SCOPES; i++) {
incremental_marking_scopes_[i].ResetCurrentCycle();
}
} else {
DCHECK(current_.incremental_marking_bytes == 0);
DCHECK(current_.incremental_marking_duration == 0);
DCHECK(current_.pure_incremental_marking_duration == 0);
longest_incremental_marking_step_ = 0.0;
longest_incremental_marking_finalization_step_ = 0.0;
recorded_mark_compacts_.Push(
MakeBytesAndDuration(current_.start_object_size, duration));
combined_mark_compact_speed_cache_ = 0.0;
}
if (baseline != nullptr) {
current_.incremental_marking_steps =
current_.cumulative_incremental_marking_steps -
baseline->cumulative_incremental_marking_steps;
current_.incremental_marking_bytes =
current_.cumulative_incremental_marking_bytes -
baseline->cumulative_incremental_marking_bytes;
current_.incremental_marking_duration =
current_.cumulative_incremental_marking_duration -
baseline->cumulative_incremental_marking_duration;
current_.pure_incremental_marking_duration =
current_.cumulative_pure_incremental_marking_duration -
baseline->cumulative_pure_incremental_marking_duration;
current_.incremental_marking_finalizaton_steps =
current_.cumulative_incremental_marking_finalization_steps -
baseline->cumulative_incremental_marking_finalization_steps;
current_.incremental_marking_finalization_duration =
current_.cumulative_incremental_marking_finalizaton_duration -
baseline->cumulative_incremental_marking_finalizaton_duration;
for (int i = Scope::FIRST_INCREMENTAL_SCOPE;
i <= Scope::LAST_INCREMENTAL_SCOPE; i++) {
current_.scopes[i] = current_.cumulative_incremental_scopes[i] -
baseline->cumulative_incremental_scopes[i];
for (int i = 0; i <= Scope::NUMBER_OF_INCREMENTAL_SCOPES; i++) {
incremental_marking_scopes_[i].ResetCurrentCycle();
}
}
@ -420,26 +366,14 @@ void GCTracer::AddSurvivalRatio(double promotion_ratio) {
void GCTracer::AddIncrementalMarkingStep(double duration, intptr_t bytes) {
cumulative_incremental_marking_steps_++;
cumulative_incremental_marking_bytes_ += bytes;
cumulative_incremental_marking_duration_ += duration;
longest_incremental_marking_step_ =
Max(longest_incremental_marking_step_, duration);
cumulative_marking_duration_ += duration;
if (bytes > 0) {
cumulative_pure_incremental_marking_duration_ += duration;
}
}
void GCTracer::AddIncrementalMarkingFinalizationStep(double duration) {
cumulative_incremental_marking_finalization_steps_++;
cumulative_incremental_marking_finalization_duration_ += duration;
longest_incremental_marking_finalization_step_ =
Max(longest_incremental_marking_finalization_step_, duration);
}
void GCTracer::Output(const char* format, ...) const {
if (FLAG_trace_gc) {
va_list arguments;
@ -461,46 +395,46 @@ void GCTracer::Output(const char* format, ...) const {
void GCTracer::Print() const {
if (FLAG_trace_gc) {
PrintIsolate(heap_->isolate(), "%s", "");
}
Output("%8.0f ms: ", heap_->isolate()->time_millis_since_init());
Output("%s %.1f (%.1f) -> %.1f (%.1f) MB, ", current_.TypeName(false),
static_cast<double>(current_.start_object_size) / MB,
static_cast<double>(current_.start_memory_size) / MB,
static_cast<double>(current_.end_object_size) / MB,
static_cast<double>(current_.end_memory_size) / MB);
double duration = current_.end_time - current_.start_time;
Output("%.1f / %.1f ms", duration, TotalExternalTime());
const size_t kIncrementalStatsSize = 128;
char incremental_buffer[kIncrementalStatsSize] = {0};
if (current_.type == Event::SCAVENGER) {
if (current_.incremental_marking_steps > 0) {
Output(" (+ %.1f ms in %d steps since last GC)",
current_.incremental_marking_duration,
current_.incremental_marking_steps);
}
} else {
if (current_.incremental_marking_steps > 0) {
Output(
if (current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].steps > 0) {
if (current_.type == Event::SCAVENGER) {
base::OS::SNPrintF(
incremental_buffer, kIncrementalStatsSize,
" (+ %.1f ms in %d steps since last GC)",
current_.scopes[Scope::MC_INCREMENTAL],
current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].steps);
} else {
base::OS::SNPrintF(
incremental_buffer, kIncrementalStatsSize,
" (+ %.1f ms in %d steps since start of marking, "
"biggest step %.1f ms)",
current_.incremental_marking_duration,
current_.incremental_marking_steps,
current_.longest_incremental_marking_step);
current_.scopes[Scope::MC_INCREMENTAL],
current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].steps,
current_.incremental_marking_scopes[Scope::MC_INCREMENTAL]
.longest_step);
}
}
if (current_.gc_reason != NULL) {
Output(" [%s]", current_.gc_reason);
}
if (current_.collector_reason != NULL) {
Output(" [%s]", current_.collector_reason);
}
Output(".\n");
// Avoid PrintF as Output also appends the string to the tracing ring buffer
// that gets printed on OOM failures.
Output(
"[%d:%p] "
"%8.0f ms: "
"%s %.1f (%.1f) -> %.1f (%.1f) MB, "
"%.1f / %.1f ms %s %s %s\n",
base::OS::GetCurrentProcessId(),
reinterpret_cast<void*>(heap_->isolate()),
heap_->isolate()->time_millis_since_init(), current_.TypeName(false),
static_cast<double>(current_.start_object_size) / MB,
static_cast<double>(current_.start_memory_size) / MB,
static_cast<double>(current_.end_object_size) / MB,
static_cast<double>(current_.end_memory_size) / MB, duration,
TotalExternalTime(), incremental_buffer,
current_.gc_reason != nullptr ? current_.gc_reason : "",
current_.collector_reason != nullptr ? current_.collector_reason : "");
}
@ -512,74 +446,75 @@ void GCTracer::PrintNVP() const {
switch (current_.type) {
case Event::SCAVENGER:
PrintIsolate(heap_->isolate(),
"%8.0f ms: "
"pause=%.1f "
"mutator=%.1f "
"gc=%s "
"reduce_memory=%d "
"scavenge=%.2f "
"old_new=%.2f "
"weak=%.2f "
"roots=%.2f "
"code=%.2f "
"semispace=%.2f "
"object_groups=%.2f "
"external_prologue=%.2f "
"external_epilogue=%.2f "
"external_weak_global_handles=%.2f "
"steps_count=%d "
"steps_took=%.1f "
"scavenge_throughput=%.f "
"total_size_before=%" V8PRIdPTR
" "
"total_size_after=%" V8PRIdPTR
" "
"holes_size_before=%" V8PRIdPTR
" "
"holes_size_after=%" V8PRIdPTR
" "
"allocated=%" V8PRIdPTR
" "
"promoted=%" V8PRIdPTR
" "
"semi_space_copied=%" V8PRIdPTR
" "
"nodes_died_in_new=%d "
"nodes_copied_in_new=%d "
"nodes_promoted=%d "
"promotion_ratio=%.1f%% "
"average_survival_ratio=%.1f%% "
"promotion_rate=%.1f%% "
"semi_space_copy_rate=%.1f%% "
"new_space_allocation_throughput=%.1f "
"context_disposal_rate=%.1f\n",
heap_->isolate()->time_millis_since_init(), duration,
spent_in_mutator, current_.TypeName(true),
current_.reduce_memory,
current_.scopes[Scope::SCAVENGER_SCAVENGE],
current_.scopes[Scope::SCAVENGER_OLD_TO_NEW_POINTERS],
current_.scopes[Scope::SCAVENGER_WEAK],
current_.scopes[Scope::SCAVENGER_ROOTS],
current_.scopes[Scope::SCAVENGER_CODE_FLUSH_CANDIDATES],
current_.scopes[Scope::SCAVENGER_SEMISPACE],
current_.scopes[Scope::SCAVENGER_OBJECT_GROUPS],
current_.scopes[Scope::SCAVENGER_EXTERNAL_PROLOGUE],
current_.scopes[Scope::SCAVENGER_EXTERNAL_EPILOGUE],
current_.scopes[Scope::EXTERNAL_WEAK_GLOBAL_HANDLES],
current_.incremental_marking_steps,
current_.incremental_marking_duration,
ScavengeSpeedInBytesPerMillisecond(),
current_.start_object_size, current_.end_object_size,
current_.start_holes_size, current_.end_holes_size,
allocated_since_last_gc, heap_->promoted_objects_size(),
heap_->semi_space_copied_object_size(),
heap_->nodes_died_in_new_space_,
heap_->nodes_copied_in_new_space_, heap_->nodes_promoted_,
heap_->promotion_ratio_, AverageSurvivalRatio(),
heap_->promotion_rate_, heap_->semi_space_copied_rate_,
NewSpaceAllocationThroughputInBytesPerMillisecond(),
ContextDisposalRateInMilliseconds());
PrintIsolate(
heap_->isolate(),
"%8.0f ms: "
"pause=%.1f "
"mutator=%.1f "
"gc=%s "
"reduce_memory=%d "
"scavenge=%.2f "
"old_new=%.2f "
"weak=%.2f "
"roots=%.2f "
"code=%.2f "
"semispace=%.2f "
"object_groups=%.2f "
"external_prologue=%.2f "
"external_epilogue=%.2f "
"external_weak_global_handles=%.2f "
"steps_count=%d "
"steps_took=%.1f "
"scavenge_throughput=%.f "
"total_size_before=%" V8PRIdPTR
" "
"total_size_after=%" V8PRIdPTR
" "
"holes_size_before=%" V8PRIdPTR
" "
"holes_size_after=%" V8PRIdPTR
" "
"allocated=%" V8PRIdPTR
" "
"promoted=%" V8PRIdPTR
" "
"semi_space_copied=%" V8PRIdPTR
" "
"nodes_died_in_new=%d "
"nodes_copied_in_new=%d "
"nodes_promoted=%d "
"promotion_ratio=%.1f%% "
"average_survival_ratio=%.1f%% "
"promotion_rate=%.1f%% "
"semi_space_copy_rate=%.1f%% "
"new_space_allocation_throughput=%.1f "
"context_disposal_rate=%.1f\n",
heap_->isolate()->time_millis_since_init(), duration,
spent_in_mutator, current_.TypeName(true), current_.reduce_memory,
current_.scopes[Scope::SCAVENGER_SCAVENGE],
current_.scopes[Scope::SCAVENGER_OLD_TO_NEW_POINTERS],
current_.scopes[Scope::SCAVENGER_WEAK],
current_.scopes[Scope::SCAVENGER_ROOTS],
current_.scopes[Scope::SCAVENGER_CODE_FLUSH_CANDIDATES],
current_.scopes[Scope::SCAVENGER_SEMISPACE],
current_.scopes[Scope::SCAVENGER_OBJECT_GROUPS],
current_.scopes[Scope::SCAVENGER_EXTERNAL_PROLOGUE],
current_.scopes[Scope::SCAVENGER_EXTERNAL_EPILOGUE],
current_.scopes[Scope::EXTERNAL_WEAK_GLOBAL_HANDLES],
current_.incremental_marking_scopes[GCTracer::Scope::MC_INCREMENTAL]
.steps,
current_.scopes[Scope::MC_INCREMENTAL],
ScavengeSpeedInBytesPerMillisecond(), current_.start_object_size,
current_.end_object_size, current_.start_holes_size,
current_.end_holes_size, allocated_since_last_gc,
heap_->promoted_objects_size(),
heap_->semi_space_copied_object_size(),
heap_->nodes_died_in_new_space_, heap_->nodes_copied_in_new_space_,
heap_->nodes_promoted_, heap_->promotion_ratio_,
AverageSurvivalRatio(), heap_->promotion_rate_,
heap_->semi_space_copied_rate_,
NewSpaceAllocationThroughputInBytesPerMillisecond(),
ContextDisposalRateInMilliseconds());
break;
case Event::MARK_COMPACTOR:
case Event::INCREMENTAL_MARK_COMPACTOR:
@ -632,15 +567,17 @@ void GCTracer::PrintNVP() const {
"sweep.old=%.1f "
"incremental=%.1f "
"incremental.finalize=%.1f "
"incremental.finalize.body=%.1f "
"incremental.finalize.external.prologue=%.1f "
"incremental.finalize.external.epilogue=%.1f "
"incremental.finalize.object_grouping=%.1f "
"incremental.wrapper_prologue=%.1f "
"incremental.wrapper_tracing=%.1f "
"incremental_wrapper_tracing_longest_step=%.1f "
"incremental_finalize_longest_step=%.1f "
"incremental_finalize_steps_count=%d "
"incremental_steps_count=%d "
"incremental_longest_step=%.1f "
"incremental_steps_count=%d "
"incremental_marking_throughput=%.f "
"total_size_before=%" V8PRIdPTR
" "
@ -707,17 +644,26 @@ void GCTracer::PrintNVP() const {
current_.scopes[Scope::MC_SWEEP_CODE],
current_.scopes[Scope::MC_SWEEP_MAP],
current_.scopes[Scope::MC_SWEEP_OLD],
current_.incremental_marking_duration,
current_.scopes[Scope::MC_INCREMENTAL],
current_.scopes[Scope::MC_INCREMENTAL_FINALIZE],
current_.scopes[Scope::MC_INCREMENTAL_FINALIZE_BODY],
current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_PROLOGUE],
current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_EPILOGUE],
current_.scopes[Scope::MC_INCREMENTAL_FINALIZE_OBJECT_GROUPING],
current_.scopes[Scope::MC_INCREMENTAL_WRAPPER_PROLOGUE],
current_.scopes[Scope::MC_INCREMENTAL_WRAPPER_TRACING],
current_.longest_incremental_marking_finalization_step,
current_.incremental_marking_finalizaton_steps,
current_.incremental_marking_steps,
current_.longest_incremental_marking_step,
current_
.incremental_marking_scopes[Scope::MC_INCREMENTAL_WRAPPER_TRACING]
.longest_step,
current_
.incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE_BODY]
.longest_step,
current_
.incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE_BODY]
.steps,
current_.incremental_marking_scopes[Scope::MC_INCREMENTAL]
.longest_step,
current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].steps,
IncrementalMarkingSpeedInBytesPerMillisecond(),
current_.start_object_size, current_.end_object_size,
current_.start_holes_size, current_.end_holes_size,

149
src/heap/gc-tracer.h
View File

@ -60,12 +60,15 @@ inline BytesAndDuration MakeBytesAndDuration(uint64_t bytes, double duration) {
enum ScavengeSpeedMode { kForAllObjects, kForSurvivedObjects };
#define INCREMENTAL_SCOPES(F) \
F(MC_INCREMENTAL_WRAPPER_PROLOGUE) \
F(MC_INCREMENTAL_WRAPPER_TRACING) \
F(MC_INCREMENTAL_FINALIZE) \
F(MC_INCREMENTAL_FINALIZE_OBJECT_GROUPING) \
F(MC_INCREMENTAL_EXTERNAL_EPILOGUE) \
#define INCREMENTAL_SCOPES(F) \
/* MC_INCREMENTAL is the top-level incremental marking scope. */ \
F(MC_INCREMENTAL) \
F(MC_INCREMENTAL_WRAPPER_PROLOGUE) \
F(MC_INCREMENTAL_WRAPPER_TRACING) \
F(MC_INCREMENTAL_FINALIZE) \
F(MC_INCREMENTAL_FINALIZE_BODY) \
F(MC_INCREMENTAL_FINALIZE_OBJECT_GROUPING) \
F(MC_INCREMENTAL_EXTERNAL_EPILOGUE) \
F(MC_INCREMENTAL_EXTERNAL_PROLOGUE)
#define TRACER_SCOPES(F) \
@ -128,9 +131,30 @@ enum ScavengeSpeedMode { kForAllObjects, kForSurvivedObjects };
// GCTracer collects and prints ONE line after each garbage collector
// invocation IFF --trace_gc is used.
// TODO(ernstm): Unit tests.
class GCTracer {
public:
struct IncrementalMarkingInfos {
IncrementalMarkingInfos()
: cumulative_duration(0), longest_step(0), steps(0) {}
void Update(double duration) {
steps++;
cumulative_duration += duration;
if (duration > longest_step) {
longest_step = duration;
}
}
void ResetCurrentCycle() {
longest_step = 0;
steps = 0;
}
double cumulative_duration;
double longest_step;
int steps;
};
class Scope {
public:
enum ScopeId {
@ -139,7 +163,7 @@ class GCTracer {
#undef DEFINE_SCOPE
NUMBER_OF_SCOPES,
FIRST_INCREMENTAL_SCOPE = MC_INCREMENTAL_WRAPPER_PROLOGUE,
FIRST_INCREMENTAL_SCOPE = MC_INCREMENTAL,
LAST_INCREMENTAL_SCOPE = MC_INCREMENTAL_EXTERNAL_PROLOGUE,
NUMBER_OF_INCREMENTAL_SCOPES =
LAST_INCREMENTAL_SCOPE - FIRST_INCREMENTAL_SCOPE + 1
@ -168,9 +192,6 @@ class GCTracer {
START = 3
};
// Default constructor leaves the event uninitialized.
Event() {}
Event(Type type, const char* gc_reason, const char* collector_reason);
// Returns a string describing the event type.
@ -213,19 +234,10 @@ class GCTracer {
// Size of new space objects in constructor.
intptr_t new_space_object_size;
// Size of survived new space objects in destructor.
intptr_t survived_new_space_object_size;
// Number of incremental marking steps since creation of tracer.
// (value at start of event)
int cumulative_incremental_marking_steps;
// Incremental marking steps since
// - last event for SCAVENGER events
// - last INCREMENTAL_MARK_COMPACTOR event for INCREMENTAL_MARK_COMPACTOR
// events
int incremental_marking_steps;
// Bytes marked since creation of tracer (value at start of event).
intptr_t cumulative_incremental_marking_bytes;
@ -235,16 +247,6 @@ class GCTracer {
// events
intptr_t incremental_marking_bytes;
// Cumulative duration of incremental marking steps since creation of
// tracer. (value at start of event)
double cumulative_incremental_marking_duration;
// Duration of incremental marking steps since
// - last event for SCAVENGER events
// - last INCREMENTAL_MARK_COMPACTOR event for INCREMENTAL_MARK_COMPACTOR
// events
double incremental_marking_duration;
// Cumulative pure duration of incremental marking steps since creation of
// tracer. (value at start of event)
double cumulative_pure_incremental_marking_duration;
@ -255,37 +257,12 @@ class GCTracer {
// events
double pure_incremental_marking_duration;
// Longest incremental marking step since start of marking (start of event).
double longest_incremental_marking_step;
// Number of incremental marking finalization steps since creation of
// tracer.
int cumulative_incremental_marking_finalization_steps;
// Cumulative pure duration of incremental marking steps since creation of
// tracer. (value at start of event)
double cumulative_incremental_marking_finalizaton_duration;
// Longest incremental marking finalization step since start of marking
// (start of event).
double longest_incremental_marking_finalization_step;
// Incremental marking finalization steps since
// - last event for SCAVENGER events
// - last INCREMENTAL_MARK_COMPACTOR event for INCREMENTAL_MARK_COMPACTOR
// events
int incremental_marking_finalizaton_steps;
// Duration of incremental marking finalization steps since
// - last event for SCAVENGER events
// - last INCREMENTAL_MARK_COMPACTOR event for INCREMENTAL_MARK_COMPACTOR
// events
double incremental_marking_finalization_duration;
double cumulative_incremental_scopes[Scope::NUMBER_OF_INCREMENTAL_SCOPES];
// Amounts of time spent in different scopes during GC.
double scopes[Scope::NUMBER_OF_SCOPES];
// Holds details for incremental marking scopes.
IncrementalMarkingInfos
incremental_marking_scopes[Scope::NUMBER_OF_INCREMENTAL_SCOPES];
};
static const int kThroughputTimeFrameMs = 5000;
@ -315,8 +292,6 @@ class GCTracer {
// Log an incremental marking step.
void AddIncrementalMarkingStep(double duration, intptr_t bytes);
void AddIncrementalMarkingFinalizationStep(double duration);
// Log time spent in marking.
void AddMarkingTime(double duration) {
cumulative_marking_duration_ += duration;
@ -406,7 +381,15 @@ class GCTracer {
// Discard all recorded survival events.
void ResetSurvivalEvents();
void AddScopeSample(Scope::ScopeId scope, double duration);
V8_INLINE void AddScopeSample(Scope::ScopeId scope, double duration) {
DCHECK(scope < Scope::NUMBER_OF_SCOPES);
if (scope >= Scope::FIRST_INCREMENTAL_SCOPE &&
scope <= Scope::LAST_INCREMENTAL_SCOPE) {
incremental_marking_scopes_[scope].Update(duration);
} else {
current_.scopes[scope] += duration;
}
}
private:
FRIEND_TEST(GCTracer, AverageSpeed);
@ -415,6 +398,7 @@ class GCTracer {
FRIEND_TEST(GCTracerTest, NewSpaceAllocationThroughputWithProvidedTime);
FRIEND_TEST(GCTracerTest, OldGenerationAllocationThroughputWithProvidedTime);
FRIEND_TEST(GCTracerTest, RegularScope);
FRIEND_TEST(GCTracerTest, IncrementalMarkingDetails);
FRIEND_TEST(GCTracerTest, IncrementalScope);
// Returns the average speed of the events in the buffer.
@ -424,6 +408,8 @@ class GCTracer {
static double AverageSpeed(const RingBuffer<BytesAndDuration>& buffer,
const BytesAndDuration& initial, double time_ms);
void MergeBaseline(const Event& baseline);
void ResetForTesting();
// Print one detailed trace line in name=value format.
@ -438,19 +424,6 @@ class GCTracer {
// it can be included in later crash dumps.
void PRINTF_FORMAT(2, 3) Output(const char* format, ...) const;
void ClearMarkCompactStatistics() {
cumulative_incremental_marking_steps_ = 0;
cumulative_incremental_marking_bytes_ = 0;
cumulative_incremental_marking_duration_ = 0;
cumulative_pure_incremental_marking_duration_ = 0;
longest_incremental_marking_step_ = 0;
cumulative_incremental_marking_finalization_steps_ = 0;
cumulative_incremental_marking_finalization_duration_ = 0;
longest_incremental_marking_finalization_step_ = 0;
cumulative_marking_duration_ = 0;
cumulative_sweeping_duration_ = 0;
}
double TotalExternalTime() const {
return current_.scopes[Scope::EXTERNAL_WEAK_GLOBAL_HANDLES] +
current_.scopes[Scope::MC_EXTERNAL_EPILOGUE] +
@ -474,9 +447,6 @@ class GCTracer {
// Previous INCREMENTAL_MARK_COMPACTOR event.
Event previous_incremental_mark_compactor_event_;
// Cumulative number of incremental marking steps since creation of tracer.
int cumulative_incremental_marking_steps_;
// Cumulative size of incremental marking steps (in bytes) since creation of
// tracer.
intptr_t cumulative_incremental_marking_bytes_;
@ -488,27 +458,14 @@ class GCTracer {
// tracer.
double cumulative_pure_incremental_marking_duration_;
// Longest incremental marking step since start of marking.
double longest_incremental_marking_step_;
// Cumulative number of incremental marking finalization steps since creation
// of tracer.
int cumulative_incremental_marking_finalization_steps_;
// Cumulative duration of incremental marking finalization steps since
// creation of tracer.
double cumulative_incremental_marking_finalization_duration_;
// Longest incremental marking finalization step since start of marking.
double longest_incremental_marking_finalization_step_;
// Total marking time.
// This timer is precise when run with --print-cumulative-gc-stat
double cumulative_marking_duration_;
// Cumulative duration of incremental marking scopes since the creation of
// the tracer.
double cumulative_incremental_scopes_[Scope::NUMBER_OF_INCREMENTAL_SCOPES];
// Incremental scopes carry more information than just the duration. The infos
// here are merged back upon starting/stopping the GC tracer.
IncrementalMarkingInfos
incremental_marking_scopes_[Scope::NUMBER_OF_INCREMENTAL_SCOPES];
// Total sweeping time on the main thread.
// This timer is precise when run with --print-cumulative-gc-stat

3
src/heap/incremental-marking.cc
View File

@ -744,6 +744,7 @@ void IncrementalMarking::RetainMaps() {
void IncrementalMarking::FinalizeIncrementally() {
TRACE_GC(heap()->tracer(), GCTracer::Scope::MC_INCREMENTAL_FINALIZE_BODY);
DCHECK(!finalize_marking_completed_);
DCHECK(IsMarking());
@ -777,7 +778,6 @@ void IncrementalMarking::FinalizeIncrementally() {
double end = heap_->MonotonicallyIncreasingTimeInMs();
double delta = end - start;
heap_->tracer()->AddMarkingTime(delta);
heap_->tracer()->AddIncrementalMarkingFinalizationStep(delta);
if (FLAG_trace_incremental_marking) {
PrintF(
"[IncrementalMarking] Finalize incrementally round %d, "
@ -1181,6 +1181,7 @@ intptr_t IncrementalMarking::Step(intptr_t allocated_bytes,
HistogramTimerScope incremental_marking_scope(
heap_->isolate()->counters()->gc_incremental_marking());
TRACE_EVENT0("v8", "V8.GCIncrementalMarking");
TRACE_GC(heap_->tracer(), GCTracer::Scope::MC_INCREMENTAL);
double start = heap_->MonotonicallyIncreasingTimeInMs();
// The marking speed is driven either by the allocation rate or by the rate

52
test/unittests/heap/gc-tracer-unittest.cc
View File

@ -183,5 +183,57 @@ TEST_F(GCTracerTest, IncrementalScope) {
200.0, tracer->current_.scopes[GCTracer::Scope::MC_INCREMENTAL_FINALIZE]);
}
TEST_F(GCTracerTest, IncrementalMarkingDetails) {
GCTracer* tracer = i_isolate()->heap()->tracer();
tracer->ResetForTesting();
// Round 1.
tracer->AddScopeSample(GCTracer::Scope::MC_INCREMENTAL_FINALIZE, 50);
tracer->Start(MARK_COMPACTOR, "gc unittest", "collector unittest");
// Switch to incremental MC to enable writing back incremental scopes.
tracer->current_.type = GCTracer::Event::INCREMENTAL_MARK_COMPACTOR;
tracer->AddScopeSample(GCTracer::Scope::MC_INCREMENTAL_FINALIZE, 100);
tracer->Stop(MARK_COMPACTOR);
EXPECT_DOUBLE_EQ(
100,
tracer->current_
.incremental_marking_scopes[GCTracer::Scope::MC_INCREMENTAL_FINALIZE]
.longest_step);
EXPECT_EQ(
2,
tracer->current_
.incremental_marking_scopes[GCTracer::Scope::MC_INCREMENTAL_FINALIZE]
.steps);
EXPECT_DOUBLE_EQ(
150,
tracer->current_
.incremental_marking_scopes[GCTracer::Scope::MC_INCREMENTAL_FINALIZE]
.cumulative_duration);
// Round 2. Cumulative numbers should add up, others should be reset.
tracer->AddScopeSample(GCTracer::Scope::MC_INCREMENTAL_FINALIZE, 13);
tracer->AddScopeSample(GCTracer::Scope::MC_INCREMENTAL_FINALIZE, 15);
tracer->Start(MARK_COMPACTOR, "gc unittest", "collector unittest");
// Switch to incremental MC to enable writing back incremental scopes.
tracer->current_.type = GCTracer::Event::INCREMENTAL_MARK_COMPACTOR;
tracer->AddScopeSample(GCTracer::Scope::MC_INCREMENTAL_FINALIZE, 122);
tracer->Stop(MARK_COMPACTOR);
EXPECT_DOUBLE_EQ(
122,
tracer->current_
.incremental_marking_scopes[GCTracer::Scope::MC_INCREMENTAL_FINALIZE]
.longest_step);
EXPECT_EQ(
3,
tracer->current_
.incremental_marking_scopes[GCTracer::Scope::MC_INCREMENTAL_FINALIZE]
.steps);
EXPECT_DOUBLE_EQ(
300,
tracer->current_
.incremental_marking_scopes[GCTracer::Scope::MC_INCREMENTAL_FINALIZE]
.cumulative_duration);
}
} // namespace internal
} // namespace v8