Commit 8fbac01b authored by vegorov@chromium.org's avatar vegorov@chromium.org

Improved GC statistics.

Collect cumulative (--print-cumulative-gc-stat) and per collection (--trace-gc-nvp) GC statistics and output it in a machine-readable name=value format.

Review URL: http://codereview.chromium.org/2132005

git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@4675 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
parent eb131775
......@@ -182,6 +182,11 @@ DEFINE_bool(gc_global, false, "always perform global GCs")
DEFINE_int(gc_interval, -1, "garbage collect after <n> allocations")
DEFINE_bool(trace_gc, false,
"print one trace line following each garbage collection")
DEFINE_bool(trace_gc_nvp, false,
"print one detailed trace line in name=value format "
"after each garbage collection")
DEFINE_bool(print_cumulative_gc_stat, false,
"print cumulative GC statistics in name=value format on exit")
DEFINE_bool(trace_gc_verbose, false,
"print more details following each garbage collection")
DEFINE_bool(collect_maps, true,
......
......@@ -115,8 +115,11 @@ int Heap::external_allocation_limit_ = 0;
Heap::HeapState Heap::gc_state_ = NOT_IN_GC;
int Heap::mc_count_ = 0;
int Heap::ms_count_ = 0;
int Heap::gc_count_ = 0;
GCTracer* Heap::tracer_ = NULL;
int Heap::unflattened_strings_length_ = 0;
int Heap::always_allocate_scope_depth_ = 0;
......@@ -130,6 +133,11 @@ int Heap::allocation_timeout_ = 0;
bool Heap::disallow_allocation_failure_ = false;
#endif // DEBUG
int GCTracer::alive_after_last_gc_ = 0;
double GCTracer::last_gc_end_timestamp_ = 0.0;
int GCTracer::max_gc_pause_ = 0;
int GCTracer::max_alive_after_gc_ = 0;
int GCTracer::min_in_mutator_ = kMaxInt;
int Heap::Capacity() {
if (!HasBeenSetup()) return 0;
......@@ -570,7 +578,7 @@ void Heap::PerformGarbageCollection(AllocationSpace space,
VerifySymbolTable();
if (collector == MARK_COMPACTOR && global_gc_prologue_callback_) {
ASSERT(!allocation_allowed_);
GCTracer::ExternalScope scope(tracer);
GCTracer::Scope scope(tracer, GCTracer::Scope::EXTERNAL);
global_gc_prologue_callback_();
}
......@@ -596,14 +604,16 @@ void Heap::PerformGarbageCollection(AllocationSpace space,
old_gen_size + Max(kMinimumAllocationLimit, old_gen_size / 2);
old_gen_exhausted_ = false;
} else {
tracer_ = tracer;
Scavenge();
tracer_ = NULL;
}
Counters::objs_since_last_young.Set(0);
if (collector == MARK_COMPACTOR) {
DisableAssertNoAllocation allow_allocation;
GCTracer::ExternalScope scope(tracer);
GCTracer::Scope scope(tracer, GCTracer::Scope::EXTERNAL);
GlobalHandles::PostGarbageCollectionProcessing();
}
......@@ -627,7 +637,7 @@ void Heap::PerformGarbageCollection(AllocationSpace space,
if (collector == MARK_COMPACTOR && global_gc_epilogue_callback_) {
ASSERT(!allocation_allowed_);
GCTracer::ExternalScope scope(tracer);
GCTracer::Scope scope(tracer, GCTracer::Scope::EXTERNAL);
global_gc_epilogue_callback_();
}
VerifySymbolTable();
......@@ -636,7 +646,11 @@ void Heap::PerformGarbageCollection(AllocationSpace space,
void Heap::MarkCompact(GCTracer* tracer) {
gc_state_ = MARK_COMPACT;
mc_count_++;
if (MarkCompactCollector::IsCompacting()) {
mc_count_++;
} else {
ms_count_++;
}
tracer->set_full_gc_count(mc_count_);
LOG(ResourceEvent("markcompact", "begin"));
......@@ -1179,6 +1193,7 @@ void Heap::ScavengeObjectSlow(HeapObject** p, HeapObject* object) {
node->set_size(object_size);
*p = target;
tracer()->increment_promoted_objects_size(object_size);
return;
}
} else {
......@@ -1214,6 +1229,7 @@ void Heap::ScavengeObjectSlow(HeapObject** p, HeapObject* object) {
(*p)->Iterate(&v);
#endif
}
tracer()->increment_promoted_objects_size(object_size);
return;
}
}
......@@ -3760,6 +3776,17 @@ void Heap::SetStackLimits() {
void Heap::TearDown() {
if (FLAG_print_cumulative_gc_stat) {
PrintF("\n\n");
PrintF("gc_count=%d ", gc_count_);
PrintF("mark_sweep_count=%d ", ms_count_);
PrintF("mark_compact_count=%d ", mc_count_);
PrintF("max_gc_pause=%d ", GCTracer::get_max_gc_pause());
PrintF("min_in_mutator=%d ", GCTracer::get_min_in_mutator());
PrintF("max_alive_after_gc=%d ", GCTracer::get_max_alive_after_gc());
PrintF("\n\n");
}
GlobalHandles::TearDown();
ExternalStringTable::TearDown();
......@@ -4235,33 +4262,114 @@ void Heap::TracePathToGlobal() {
#endif
static int CountTotalHolesSize() {
int holes_size = 0;
OldSpaces spaces;
for (OldSpace* space = spaces.next();
space != NULL;
space = spaces.next()) {
holes_size += space->Waste() + space->AvailableFree();
}
return holes_size;
}
GCTracer::GCTracer()
: start_time_(0.0),
start_size_(0.0),
external_time_(0.0),
start_size_(0),
gc_count_(0),
full_gc_count_(0),
is_compacting_(false),
marked_count_(0) {
marked_count_(0),
allocated_since_last_gc_(0),
spent_in_mutator_(0),
promoted_objects_size_(0) {
// These two fields reflect the state of the previous full collection.
// Set them before they are changed by the collector.
previous_has_compacted_ = MarkCompactCollector::HasCompacted();
previous_marked_count_ = MarkCompactCollector::previous_marked_count();
if (!FLAG_trace_gc) return;
if (!FLAG_trace_gc && !FLAG_print_cumulative_gc_stat) return;
start_time_ = OS::TimeCurrentMillis();
start_size_ = SizeOfHeapObjects();
start_size_ = Heap::SizeOfObjects();
for (int i = 0; i < Scope::kNumberOfScopes; i++) {
scopes_[i] = 0;
}
in_free_list_or_wasted_before_gc_ = CountTotalHolesSize();
allocated_since_last_gc_ = Heap::SizeOfObjects() - alive_after_last_gc_;
if (last_gc_end_timestamp_ > 0) {
spent_in_mutator_ = Max(start_time_ - last_gc_end_timestamp_, 0.0);
}
}
GCTracer::~GCTracer() {
if (!FLAG_trace_gc) return;
// Printf ONE line iff flag is set.
int time = static_cast<int>(OS::TimeCurrentMillis() - start_time_);
int external_time = static_cast<int>(external_time_);
PrintF("%s %.1f -> %.1f MB, ",
CollectorString(), start_size_, SizeOfHeapObjects());
if (external_time > 0) PrintF("%d / ", external_time);
PrintF("%d ms.\n", time);
if (!FLAG_trace_gc && !FLAG_print_cumulative_gc_stat) return;
bool first_gc = (last_gc_end_timestamp_ == 0);
alive_after_last_gc_ = Heap::SizeOfObjects();
last_gc_end_timestamp_ = OS::TimeCurrentMillis();
int time = static_cast<int>(last_gc_end_timestamp_ - start_time_);
// Update cumulative GC statistics if required.
if (FLAG_print_cumulative_gc_stat) {
max_gc_pause_ = Max(max_gc_pause_, time);
max_alive_after_gc_ = Max(max_alive_after_gc_, alive_after_last_gc_);
if (!first_gc) {
min_in_mutator_ = Min(min_in_mutator_,
static_cast<int>(spent_in_mutator_));
}
}
if (!FLAG_trace_gc_nvp) {
int external_time = static_cast<int>(scopes_[Scope::EXTERNAL]);
PrintF("%s %.1f -> %.1f MB, ",
CollectorString(),
static_cast<double>(start_size_) / MB,
SizeOfHeapObjects());
if (external_time > 0) PrintF("%d / ", external_time);
PrintF("%d ms.\n", time);
} else {
PrintF("pause=%d ", time);
PrintF("mutator=%d ",
static_cast<int>(spent_in_mutator_));
PrintF("gc=");
switch (collector_) {
case SCAVENGER:
PrintF("s");
break;
case MARK_COMPACTOR:
PrintF(MarkCompactCollector::HasCompacted() ? "mc" : "ms");
break;
default:
UNREACHABLE();
}
PrintF(" ");
PrintF("external=%d ", static_cast<int>(scopes_[Scope::EXTERNAL]));
PrintF("mark=%d ", static_cast<int>(scopes_[Scope::MC_MARK]));
PrintF("sweep=%d ", static_cast<int>(scopes_[Scope::MC_SWEEP]));
PrintF("compact=%d ", static_cast<int>(scopes_[Scope::MC_COMPACT]));
PrintF("total_size_before=%d ", start_size_);
PrintF("total_size_after=%d ", Heap::SizeOfObjects());
PrintF("holes_size_before=%d ", in_free_list_or_wasted_before_gc_);
PrintF("holes_size_after=%d ", CountTotalHolesSize());
PrintF("allocated=%d ", allocated_since_last_gc_);
PrintF("promoted=%d ", promoted_objects_size_);
PrintF("\n");
}
#if defined(ENABLE_LOGGING_AND_PROFILING)
Heap::PrintShortHeapStatistics();
......
......@@ -981,6 +981,8 @@ class Heap : public AllStatic {
static void ClearJSFunctionResultCaches();
static GCTracer* tracer() { return tracer_; }
private:
static int reserved_semispace_size_;
static int max_semispace_size_;
......@@ -1020,6 +1022,7 @@ class Heap : public AllStatic {
static int PromotedExternalMemorySize();
static int mc_count_; // how many mark-compact collections happened
static int ms_count_; // how many mark-sweep collections happened
static int gc_count_; // how many gc happened
// Total length of the strings we failed to flatten since the last GC.
......@@ -1223,6 +1226,8 @@ class Heap : public AllStatic {
SharedFunctionInfo* shared,
Object* prototype);
static GCTracer* tracer_;
// Initializes the number to string cache based on the max semispace size.
static Object* InitializeNumberStringCache();
......@@ -1629,19 +1634,30 @@ class DisableAssertNoAllocation {
class GCTracer BASE_EMBEDDED {
public:
// Time spent while in the external scope counts towards the
// external time in the tracer and will be reported separately.
class ExternalScope BASE_EMBEDDED {
class Scope BASE_EMBEDDED {
public:
explicit ExternalScope(GCTracer* tracer) : tracer_(tracer) {
enum ScopeId {
EXTERNAL,
MC_MARK,
MC_SWEEP,
MC_COMPACT,
kNumberOfScopes
};
Scope(GCTracer* tracer, ScopeId scope)
: tracer_(tracer),
scope_(scope) {
start_time_ = OS::TimeCurrentMillis();
}
~ExternalScope() {
tracer_->external_time_ += OS::TimeCurrentMillis() - start_time_;
~Scope() {
ASSERT((0 <= scope_) && (scope_ < kNumberOfScopes));
tracer_->scopes_[scope_] += OS::TimeCurrentMillis() - start_time_;
}
private:
GCTracer* tracer_;
ScopeId scope_;
double start_time_;
};
......@@ -1667,6 +1683,19 @@ class GCTracer BASE_EMBEDDED {
int marked_count() { return marked_count_; }
void increment_promoted_objects_size(int object_size) {
promoted_objects_size_ += object_size;
}
// Returns maximum GC pause.
static int get_max_gc_pause() { return max_gc_pause_; }
// Returns maximum size of objects alive after GC.
static int get_max_alive_after_gc() { return max_alive_after_gc_; }
// Returns minimal interval between two subsequent collections.
static int get_min_in_mutator() { return min_in_mutator_; }
private:
// Returns a string matching the collector.
const char* CollectorString();
......@@ -1677,12 +1706,9 @@ class GCTracer BASE_EMBEDDED {
}
double start_time_; // Timestamp set in the constructor.
double start_size_; // Size of objects in heap set in constructor.
int start_size_; // Size of objects in heap set in constructor.
GarbageCollector collector_; // Type of collector.
// Keep track of the amount of time spent in external callbacks.
double external_time_;
// A count (including this one, eg, the first collection is 1) of the
// number of garbage collections.
int gc_count_;
......@@ -1706,6 +1732,38 @@ class GCTracer BASE_EMBEDDED {
// The count from the end of the previous full GC. Will be zero if there
// was no previous full GC.
int previous_marked_count_;
// Amounts of time spent in different scopes during GC.
double scopes_[Scope::kNumberOfScopes];
// Total amount of space either wasted or contained in one of free lists
// before the current GC.
int in_free_list_or_wasted_before_gc_;
// Difference between space used in the heap at the beginning of the current
// collection and the end of the previous collection.
int allocated_since_last_gc_;
// Amount of time spent in mutator that is time elapsed between end of the
// previous collection and the beginning of the current one.
double spent_in_mutator_;
// Size of objects promoted during the current collection.
int promoted_objects_size_;
// Maximum GC pause.
static int max_gc_pause_;
// Maximum size of objects alive after GC.
static int max_alive_after_gc_;
// Minimal interval between two subsequent collections.
static int min_in_mutator_;
// Size of objects alive after last GC.
static int alive_after_last_gc_;
static double last_gc_end_timestamp_;
};
......
......@@ -78,6 +78,7 @@ void MarkCompactCollector::CollectGarbage() {
SweepLargeObjectSpace();
if (IsCompacting()) {
GCTracer::Scope gc_scope(tracer_, GCTracer::Scope::MC_COMPACT);
EncodeForwardingAddresses();
UpdatePointers();
......@@ -678,6 +679,7 @@ void MarkCompactCollector::ProcessObjectGroups(MarkingVisitor* visitor) {
void MarkCompactCollector::MarkLiveObjects() {
GCTracer::Scope gc_scope(tracer_, GCTracer::Scope::MC_MARK);
#ifdef DEBUG
ASSERT(state_ == PREPARE_GC);
state_ = MARK_LIVE_OBJECTS;
......@@ -1163,6 +1165,8 @@ static bool TryPromoteObject(HeapObject* object, int object_size) {
HeapObject* target = HeapObject::cast(result);
MigrateObject(target->address(), object->address(), object_size);
Heap::UpdateRSet(target);
MarkCompactCollector::tracer()->
increment_promoted_objects_size(object_size);
return true;
}
} else {
......@@ -1177,6 +1181,8 @@ static bool TryPromoteObject(HeapObject* object, int object_size) {
if (target_space == Heap::old_pointer_space()) {
Heap::UpdateRSet(target);
}
MarkCompactCollector::tracer()->
increment_promoted_objects_size(object_size);
return true;
}
}
......@@ -1735,6 +1741,8 @@ MapCompact::MapUpdatingVisitor MapCompact::map_updating_visitor_;
void MarkCompactCollector::SweepSpaces() {
GCTracer::Scope gc_scope(tracer_, GCTracer::Scope::MC_SWEEP);
ASSERT(state_ == SWEEP_SPACES);
ASSERT(!IsCompacting());
// Noncompacting collections simply sweep the spaces to clear the mark
......
#!/usr/bin/env python
#
# Copyright 2010 the V8 project authors. All rights reserved.
# Redistribution and use in source and binary forms, with or without
# modification, are permitted provided that the following conditions are
# met:
#
# * Redistributions of source code must retain the above copyright
# notice, this list of conditions and the following disclaimer.
# * Redistributions in binary form must reproduce the above
# copyright notice, this list of conditions and the following
# disclaimer in the documentation and/or other materials provided
# with the distribution.
# * Neither the name of Google Inc. nor the names of its
# contributors may be used to endorse or promote products derived
# from this software without specific prior written permission.
#
# THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
# "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
# LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
# A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
# OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
# SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
# LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
# DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
# THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
# (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
# OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
#
#
# This is an utility for plotting charts based on GC traces produced by V8 when
# run with flags --trace-gc --trace-gc-nvp. Relies on gnuplot for actual
# plotting.
#
# Usage: gc-nvp-trace-processor.py <GC-trace-filename>
#
from __future__ import with_statement
import sys, types, re, subprocess
def flatten(l):
flat = []
for i in l: flat.extend(i)
return flat
def split_nvp(s):
t = {}
for m in re.finditer(r"(\w+)=(-?\d+)", s):
t[m.group(1)] = int(m.group(2))
return t
def parse_gc_trace(input):
trace = []
with open(input) as f:
for line in f:
info = split_nvp(line)
if info and 'pause' in info and info['pause'] > 0:
info['i'] = len(trace)
trace.append(info)
return trace
def extract_field_names(script):
fields = { 'data': true, 'in': true }
for m in re.finditer(r"$(\w+)", script):
field_name = m.group(1)
if field_name not in fields:
fields[field] = field_count
field_count = field_count + 1
return fields
def gnuplot(script):
gnuplot = subprocess.Popen(["gnuplot"], stdin=subprocess.PIPE)
gnuplot.stdin.write(script)
gnuplot.stdin.close()
gnuplot.wait()
x1y1 = 'x1y1'
x1y2 = 'x1y2'
x2y1 = 'x2y1'
x2y2 = 'x2y2'
class Item(object):
def __init__(self, title, field, axis = x1y1, **keywords):
self.title = title
self.axis = axis
self.props = keywords
if type(field) is types.ListType:
self.field = field
else:
self.field = [field]
def fieldrefs(self):
return self.field
def to_gnuplot(self, context):
args = ['"%s"' % context.datafile,
'using %s' % context.format_fieldref(self.field),
'title "%s"' % self.title,
'axis %s' % self.axis]
if 'style' in self.props:
args.append('with %s' % self.props['style'])
if 'lc' in self.props:
args.append('lc rgb "%s"' % self.props['lc'])
if 'fs' in self.props:
args.append('fs %s' % self.props['fs'])
return ' '.join(args)
class Plot(object):
def __init__(self, *items):
self.items = items
def fieldrefs(self):
return flatten([item.fieldrefs() for item in self.items])
def to_gnuplot(self, ctx):
return 'plot ' + ', '.join([item.to_gnuplot(ctx) for item in self.items])
class Set(object):
def __init__(self, value):
self.value = value
def to_gnuplot(self, ctx):
return 'set ' + self.value
def fieldrefs(self):
return []
class Context(object):
def __init__(self, datafile, field_to_index):
self.datafile = datafile
self.field_to_index = field_to_index
def format_fieldref(self, fieldref):
return ':'.join([str(self.field_to_index[field]) for field in fieldref])
def collect_fields(plot):
field_to_index = {}
fields = []
def add_field(field):
if field not in field_to_index:
fields.append(field)
field_to_index[field] = len(fields)
for field in flatten([item.fieldrefs() for item in plot]):
add_field(field)
return (fields, field_to_index)
def is_y2_used(plot):
for subplot in plot:
if isinstance(subplot, Plot):
for item in subplot.items:
if item.axis == x1y2 or item.axis == x2y2:
return True
return False
def get_field(trace_line, field):
t = type(field)
if t is types.StringType:
return trace_line[field]
elif t is types.FunctionType:
return field(trace_line)
def generate_datafile(datafile_name, trace, fields):
with open(datafile_name, 'w') as datafile:
for line in trace:
data_line = [str(get_field(line, field)) for field in fields]
datafile.write('\t'.join(data_line))
datafile.write('\n')
def generate_script_and_datafile(plot, trace, datafile, output):
(fields, field_to_index) = collect_fields(plot)
generate_datafile(datafile, trace, fields)
script = [
'set terminal png',
'set output "%s"' % output,
'set autoscale',
'set ytics nomirror',
'set xtics nomirror',
'set key below'
]
if is_y2_used(plot):
script.append('set autoscale y2')
script.append('set y2tics')
context = Context(datafile, field_to_index)
for item in plot:
script.append(item.to_gnuplot(context))
return '\n'.join(script)
def plot_all(plots, trace, prefix):
charts = []
for plot in plots:
outfilename = "%s_%d.png" % (prefix, len(charts))
charts.append(outfilename)
script = generate_script_and_datafile(plot, trace, '~datafile', outfilename)
print 'Plotting %s...' % outfilename
gnuplot(script)
return charts
def reclaimed_bytes(row):
return row['total_size_before'] - row['total_size_after']
plots = [
[
Set('style fill solid 0.5 noborder'),
Set('style histogram rowstacked'),
Set('style data histograms'),
Plot(Item('Marking', 'mark', lc = 'purple'),
Item('Sweep', 'sweep', lc = 'blue'),
Item('Compaction', 'compact', lc = 'red'),
Item('Other',
lambda r: r['pause'] - r['mark'] - r['sweep'] - r['compact'],
lc = 'grey'))
],
[
Set('style histogram rowstacked'),
Set('style data histograms'),
Plot(Item('Heap Size (before GC)', 'total_size_before', x1y2,
fs = 'solid 0.4 noborder',
lc = 'green'),
Item('Total holes (after GC)', 'holes_size_before', x1y2,
fs = 'solid 0.4 noborder',
lc = 'red'),
Item('GC Time', ['i', 'pause'], style = 'lines', lc = 'red'))
],
[
Set('style histogram rowstacked'),
Set('style data histograms'),
Plot(Item('Heap Size (after GC)', 'total_size_after', x1y2,
fs = 'solid 0.4 noborder',
lc = 'green'),
Item('Total holes (after GC)', 'holes_size_after', x1y2,
fs = 'solid 0.4 noborder',
lc = 'red'),
Item('GC Time', ['i', 'pause'],
style = 'lines',
lc = 'red'))
],
[
Set('style fill solid 0.5 noborder'),
Set('style data histograms'),
Plot(Item('Allocated', 'allocated'),
Item('Reclaimed', reclaimed_bytes),
Item('Promoted', 'promoted', style = 'lines', lc = 'black'))
],
]
def process_trace(filename):
trace = parse_gc_trace(filename)
total_gc = reduce(lambda t,r: t + r['pause'], trace, 0)
max_gc = reduce(lambda t,r: max(t, r['pause']), trace, 0)
avg_gc = total_gc / len(trace)
charts = plot_all(plots, trace, filename)
with open(filename + '.html', 'w') as out:
out.write('<html><body>')
out.write('Total in GC: <b>%d</b><br/>' % total_gc)
out.write('Max in GC: <b>%d</b><br/>' % max_gc)
out.write('Avg in GC: <b>%d</b><br/>' % avg_gc)
for chart in charts:
out.write('<img src="%s">' % chart)
out.write('</body></html>')
print "%s generated." % (filename + '.html')
if len(sys.argv) != 2:
print "Usage: %s <GC-trace-filename>" % sys.argv[0]
sys.exit(1)
process_trace(sys.argv[1])
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment