Revision: 3069 Author: [email protected] Date: Thu Oct 15 00:50:23 2009 Log: Add initial semi-working producers profile.
Turned on with '--log-producers' flag, also needs '--noinline-new' (this is temporarily), '--log-code', '--log-gc'. Not all allocations are traced (I'm investigating.) Stacks are stored using weak handles. Thus, when an object is collected, its allocation stack is deleted. Review URL: http://codereview.chromium.org/267077 http://code.google.com/p/v8/source/detail?r=3069 Modified: /branches/bleeding_edge/src/flag-definitions.h /branches/bleeding_edge/src/global-handles.cc /branches/bleeding_edge/src/global-handles.h /branches/bleeding_edge/src/heap-profiler.cc /branches/bleeding_edge/src/heap-profiler.h /branches/bleeding_edge/src/heap.cc /branches/bleeding_edge/src/log.cc /branches/bleeding_edge/src/log.h /branches/bleeding_edge/tools/tickprocessor.js ======================================= --- /branches/bleeding_edge/src/flag-definitions.h Wed Oct 14 12:30:50 2009 +++ /branches/bleeding_edge/src/flag-definitions.h Thu Oct 15 00:50:23 2009 @@ -350,6 +350,7 @@ DEFINE_bool(log_handles, false, "Log global handle events.") DEFINE_bool(log_state_changes, false, "Log state changes.") DEFINE_bool(log_suspect, false, "Log suspect operations.") +DEFINE_bool(log_producers, false, "Log stack traces of JS objects allocations.") DEFINE_bool(compress_log, false, "Compress log to save space (makes log less human-readable).") DEFINE_bool(prof, false, ======================================= --- /branches/bleeding_edge/src/global-handles.cc Fri Aug 21 01:52:24 2009 +++ /branches/bleeding_edge/src/global-handles.cc Thu Oct 15 00:50:23 2009 @@ -262,6 +262,16 @@ } } } + + +void GlobalHandles::IterateWeakRoots(WeakReferenceGuest f, + WeakReferenceCallback callback) { + for (Node* current = head_; current != NULL; current = current->next()) { + if (current->IsWeak() && current->callback() == callback) { + f(current->object_, current->parameter()); + } + } +} void GlobalHandles::IdentifyWeakHandles(WeakSlotCallback f) { ======================================= --- /branches/bleeding_edge/src/global-handles.h Mon May 25 03:05:56 2009 +++ /branches/bleeding_edge/src/global-handles.h Thu Oct 15 00:50:23 2009 @@ -54,6 +54,8 @@ }; +typedef void (*WeakReferenceGuest)(Object* object, void* parameter); + class GlobalHandles : public AllStatic { public: // Creates a new global handle that is alive until Destroy is called. @@ -99,6 +101,10 @@ // Iterates over all weak roots in heap. static void IterateWeakRoots(ObjectVisitor* v); + // Iterates over weak roots that are bound to a given callback. + static void IterateWeakRoots(WeakReferenceGuest f, + WeakReferenceCallback callback); + // Find all weak handles satisfying the callback predicate, mark // them as pending. static void IdentifyWeakHandles(WeakSlotCallback f); ======================================= --- /branches/bleeding_edge/src/heap-profiler.cc Mon Sep 28 02:05:06 2009 +++ /branches/bleeding_edge/src/heap-profiler.cc Thu Oct 15 00:50:23 2009 @@ -28,6 +28,8 @@ #include "v8.h" #include "heap-profiler.h" +#include "frames-inl.h" +#include "global-handles.h" #include "string-stream.h" namespace v8 { @@ -325,6 +327,11 @@ void ConstructorHeapProfile::PrintStats() { js_objects_info_tree_.ForEach(this); } + + +static const char* GetConstructorName(const char* name) { + return name[0] != '\0' ? name : "(anonymous)"; +} void JSObjectsCluster::Print(StringStream* accumulator) const { @@ -338,7 +345,7 @@ } else { SmartPointer<char> s_name( constructor_->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL)); - accumulator->Add("%s", (*s_name)[0] != '\0' ? *s_name : "(anonymous)"); + accumulator->Add("%s", GetConstructorName(*s_name)); if (instance_ != NULL) { accumulator->Add(":%p", static_cast<void*>(instance_)); } @@ -572,6 +579,23 @@ info[type].increment_number(1); info[type].increment_bytes(obj->Size()); } + + +static void StackWeakReferenceCallback(Persistent<Value> object, + void* trace) { + DeleteArray(static_cast<Address*>(trace)); + object.Dispose(); +} + + +static void PrintProducerStackTrace(Object* obj, void* trace) { + if (!obj->IsJSObject()) return; + String* constructor = JSObject::cast(obj)->constructor_name(); + SmartPointer<char> s_name( + constructor->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL)); + LOG(HeapSampleJSProducerEvent(GetConstructorName(*s_name), + reinterpret_cast<Address*>(trace))); +} void HeapProfiler::WriteSample() { @@ -616,8 +640,38 @@ js_cons_profile.PrintStats(); js_retainer_profile.PrintStats(); + GlobalHandles::IterateWeakRoots(PrintProducerStackTrace, + StackWeakReferenceCallback); + LOG(HeapSampleEndEvent("Heap", "allocated")); } + + +bool ProducerHeapProfile::can_log_ = false; + +void ProducerHeapProfile::Setup() { + can_log_ = true; +} + +void ProducerHeapProfile::RecordJSObjectAllocation(Object* obj) { + if (!can_log_ || !FLAG_log_producers) return; + int framesCount = 0; + for (JavaScriptFrameIterator it; !it.done(); it.Advance()) { + ++framesCount; + } + if (framesCount == 0) return; + ++framesCount; // Reserve place for the terminator item. + Vector<Address> stack(NewArray<Address>(framesCount), framesCount); + int i = 0; + for (JavaScriptFrameIterator it; !it.done(); it.Advance()) { + stack[i++] = it.frame()->pc(); + } + stack[i] = NULL; + Handle<Object> handle = GlobalHandles::Create(obj); + GlobalHandles::MakeWeak(handle.location(), + static_cast<void*>(stack.start()), + StackWeakReferenceCallback); +} #endif // ENABLE_LOGGING_AND_PROFILING ======================================= --- /branches/bleeding_edge/src/heap-profiler.h Mon Sep 28 02:05:06 2009 +++ /branches/bleeding_edge/src/heap-profiler.h Thu Oct 15 00:50:23 2009 @@ -256,6 +256,14 @@ }; +class ProducerHeapProfile : public AllStatic { + public: + static void Setup(); + static void RecordJSObjectAllocation(Object* obj); + private: + static bool can_log_; +}; + #endif // ENABLE_LOGGING_AND_PROFILING } } // namespace v8::internal ======================================= --- /branches/bleeding_edge/src/heap.cc Thu Oct 8 05:36:12 2009 +++ /branches/bleeding_edge/src/heap.cc Thu Oct 15 00:50:23 2009 @@ -2021,6 +2021,7 @@ TargetSpaceId(map->instance_type())); if (result->IsFailure()) return result; HeapObject::cast(result)->set_map(map); + ProducerHeapProfile::RecordJSObjectAllocation(result); return result; } @@ -2342,6 +2343,7 @@ JSObject::cast(clone)->set_properties(FixedArray::cast(prop)); } // Return the new clone. + ProducerHeapProfile::RecordJSObjectAllocation(clone); return clone; } @@ -3308,6 +3310,9 @@ LOG(IntEvent("heap-capacity", Capacity())); LOG(IntEvent("heap-available", Available())); + // This should be called only after initial objects have been created. + ProducerHeapProfile::Setup(); + return true; } ======================================= --- /branches/bleeding_edge/src/log.cc Wed Oct 7 05:20:02 2009 +++ /branches/bleeding_edge/src/log.cc Thu Oct 15 00:50:23 2009 @@ -932,6 +932,21 @@ } while (pos < event_len); #endif } + + +void Logger::HeapSampleJSProducerEvent(const char* constructor, + Address* stack) { +#ifdef ENABLE_LOGGING_AND_PROFILING + if (!Log::IsEnabled() || !FLAG_log_gc) return; + LogMessageBuilder msg; + msg.Append("heap-js-prod-item,%s", constructor); + while (*stack != NULL) { + msg.Append(",0x%" V8PRIxPTR, *stack++); + } + msg.Append("\n"); + msg.WriteToLogFile(); +#endif +} void Logger::DebugTag(const char* call_site_tag) { ======================================= --- /branches/bleeding_edge/src/log.h Fri Sep 18 05:05:18 2009 +++ /branches/bleeding_edge/src/log.h Thu Oct 15 00:50:23 2009 @@ -223,6 +223,8 @@ int number, int bytes); static void HeapSampleJSRetainersEvent(const char* constructor, const char* event); + static void HeapSampleJSProducerEvent(const char* constructor, + Address* stack); static void HeapSampleStats(const char* space, const char* kind, int capacity, int used); ======================================= --- /branches/bleeding_edge/tools/tickprocessor.js Wed Sep 2 01:18:27 2009 +++ /branches/bleeding_edge/tools/tickprocessor.js Thu Oct 15 00:50:23 2009 @@ -75,7 +75,18 @@ 'tick': { parsers: [this.createAddressParser('code'), this.createAddressParser('stack'), parseInt, 'var-args'], processor: this.processTick, backrefs: true }, + 'heap-sample-begin': { parsers: [null, null, parseInt], + processor: this.processHeapSampleBegin }, + 'heap-sample-end': { parsers: [null, null], + processor: this.processHeapSampleEnd }, + 'heap-js-prod-item': { parsers: [null, 'var-args'], + processor: this.processJSProducer, backrefs: true }, + // Ignored events. 'profiler': null, + 'heap-sample-stats': null, + 'heap-sample-item': null, + 'heap-js-cons-item': null, + 'heap-js-ret-item': null, // Obsolete row types. 'code-allocate': null, 'begin-code-region': null, @@ -113,6 +124,9 @@ // Count each tick as a time unit. this.viewBuilder_ = new devtools.profiler.ViewBuilder(1); this.lastLogFileName_ = null; + + this.generation_ = 1; + this.currentProducerProfile_ = null; }; inherits(TickProcessor, devtools.profiler.LogReader); @@ -220,6 +234,41 @@ }; +TickProcessor.prototype.processHeapSampleBegin = function(space, state, ticks) { + if (space != 'Heap') return; + this.currentProducerProfile_ = new devtools.profiler.CallTree(); +}; + + +TickProcessor.prototype.processHeapSampleEnd = function(space, state) { + if (space != 'Heap' || !this.currentProducerProfile_) return; + + print('Generation ' + this.generation_ + ':'); + var tree = this.currentProducerProfile_; + tree.computeTotalWeights(); + var producersView = this.viewBuilder_.buildView(tree); + // Sort by total time, desc, then by name, desc. + producersView.sort(function(rec1, rec2) { + return rec2.totalTime - rec1.totalTime || + (rec2.internalFuncName < rec1.internalFuncName ? -1 : 1); }); + this.printHeavyProfile(producersView.head.children); + + this.currentProducerProfile_ = null; + this.generation_++; +}; + + +TickProcessor.prototype.processJSProducer = function(constructor, stack) { + if (!this.currentProducerProfile_) return; + if (stack.length == 0) return; + var first = stack.shift(); + var processedStack = + this.profile_.resolveAndFilterFuncs_(this.processStack(first, stack)); + processedStack.unshift(constructor); + this.currentProducerProfile_.addPath(processedStack); +}; + + TickProcessor.prototype.printStatistics = function() { print('Statistical profiling result from ' + this.lastLogFileName_ + ', (' + this.ticks_.total + --~--~---------~--~----~------------~-------~--~----~ v8-dev mailing list [email protected] http://groups.google.com/group/v8-dev -~----------~----~----~----~------~----~------~--~---
