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,
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;
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;
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_();
}
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();
}
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();
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"));
node->set_size(object_size);
*p = target;
+ tracer()->increment_promoted_objects_size(object_size);
return;
}
} else {
(*p)->Iterate(&v);
#endif
}
+ tracer()->increment_promoted_objects_size(object_size);
return;
}
}
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();
#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();
static void ClearJSFunctionResultCaches();
+ static GCTracer* tracer() { return tracer_; }
+
private:
static int reserved_semispace_size_;
static int max_semispace_size_;
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.
SharedFunctionInfo* shared,
Object* prototype);
+ static GCTracer* tracer_;
+
// Initializes the number to string cache based on the max semispace size.
static Object* InitializeNumberStringCache();
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_;
};
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();
}
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_;
// 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_;
};
SweepLargeObjectSpace();
if (IsCompacting()) {
+ GCTracer::Scope gc_scope(tracer_, GCTracer::Scope::MC_COMPACT);
EncodeForwardingAddresses();
UpdatePointers();
void MarkCompactCollector::MarkLiveObjects() {
+ GCTracer::Scope gc_scope(tracer_, GCTracer::Scope::MC_MARK);
#ifdef DEBUG
ASSERT(state_ == PREPARE_GC);
state_ = MARK_LIVE_OBJECTS;
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 {
if (target_space == Heap::old_pointer_space()) {
Heap::UpdateRSet(target);
}
+ MarkCompactCollector::tracer()->
+ increment_promoted_objects_size(object_size);
return true;
}
}
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
--- /dev/null
+#!/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])