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

git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3069 ce2b1a6d-e550-0410-aec6-3dcde31c8c00

diff --git a/src/flag-definitions.h b/src/flag-definitions.h
index 8f2008341445fdf540ca7485a268dc8666913e84..2a964abd074ec642804d59c47bdd8f573627df18 100644 (file)
--- a/src/flag-definitions.h
+++ b/src/flag-definitions.h
@@ -350,6 +350,7 @@ DEFINE_bool(log_gc, false,
 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,

diff --git a/src/global-handles.cc b/src/global-handles.cc
index e51c4aadf13d68bd581064f33628caf8bbf588d6..f4b69fcdd3038b6c1ef322eac24612a1964cb7d3 100644 (file)
--- a/src/global-handles.cc
+++ b/src/global-handles.cc
@@ -264,6 +264,16 @@ void GlobalHandles::IterateWeakRoots(ObjectVisitor* v) {
 }
 
 
+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) {
   for (Node* current = head_; current != NULL; current = current->next()) {
     if (current->state_ == Node::WEAK) {

diff --git a/src/global-handles.h b/src/global-handles.h
index 9e63ba7a9730fa146780b7dc85f2a59b355b8b17..feb95bf2a3dfe7d73ecd4d2e1e401d07c22e3e90 100644 (file)
--- a/src/global-handles.h
+++ b/src/global-handles.h
@@ -54,6 +54,8 @@ class ObjectGroup : public Malloced {
 };
 
 
+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 @@ class GlobalHandles : public AllStatic {
   // 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);

diff --git a/src/heap-profiler.cc b/src/heap-profiler.cc
index ecb6919874a6334cfda3d81c6a13a1252e953713..8f55ce1ce49356b581a6d56731e37e91638e191d 100644 (file)
--- a/src/heap-profiler.cc
+++ b/src/heap-profiler.cc
@@ -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 {
@@ -327,6 +329,11 @@ void ConstructorHeapProfile::PrintStats() {
 }
 
 
+static const char* GetConstructorName(const char* name) {
+  return name[0] != '\0' ? name : "(anonymous)";
+}
+
+
 void JSObjectsCluster::Print(StringStream* accumulator) const {
   ASSERT(!is_null());
   if (constructor_ == FromSpecialCase(ROOTS)) {
@@ -338,7 +345,7 @@ void JSObjectsCluster::Print(StringStream* accumulator) const {
   } 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_));
     }
@@ -574,6 +581,23 @@ void HeapProfiler::CollectStats(HeapObject* obj, HistogramInfo* info) {
 }
 
 
+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() {
   LOG(HeapSampleBeginEvent("Heap", "allocated"));
   LOG(HeapSampleStats(
@@ -616,10 +640,40 @@ void HeapProfiler::WriteSample() {
   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
 
 

diff --git a/src/heap-profiler.h b/src/heap-profiler.h
index 7fda883f87c1c60eca68649b4cac9793b3e06e0d..bd875df236809a1cb6e7ade710960eaa97d9de48 100644 (file)
--- a/src/heap-profiler.h
+++ b/src/heap-profiler.h
@@ -256,6 +256,14 @@ class RetainerHeapProfile BASE_EMBEDDED {
 };
 
 
+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

diff --git a/src/heap.cc b/src/heap.cc
index 648e4869953bca2e38a23e64b694f75c9b52ead0..817a50f16301f443ec0679381d9ec35f54b38bba 100644 (file)
--- a/src/heap.cc
+++ b/src/heap.cc
@@ -2021,6 +2021,7 @@ Object* Heap::Allocate(Map* map, AllocationSpace space) {
                                TargetSpaceId(map->instance_type()));
   if (result->IsFailure()) return result;
   HeapObject::cast(result)->set_map(map);
+  ProducerHeapProfile::RecordJSObjectAllocation(result);
   return result;
 }
 
@@ -2342,6 +2343,7 @@ Object* Heap::CopyJSObject(JSObject* source) {
     JSObject::cast(clone)->set_properties(FixedArray::cast(prop));
   }
   // Return the new clone.
+  ProducerHeapProfile::RecordJSObjectAllocation(clone);
   return clone;
 }
 
@@ -3308,6 +3310,9 @@ bool Heap::Setup(bool create_heap_objects) {
   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;
 }
 

diff --git a/src/log.cc b/src/log.cc
index 1c82f8525c95f954e87091a7d3b964e7c6fe24aa..d1d9a31e49b1b76a8201f9a13d8849a2f9bc299d 100644 (file)
--- a/src/log.cc
+++ b/src/log.cc
@@ -934,6 +934,21 @@ void Logger::HeapSampleJSRetainersEvent(
 }
 
 
+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) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (!Log::IsEnabled() || !FLAG_log) return;

diff --git a/src/log.h b/src/log.h
index 07a0429ace19895a167a9d54f86ab8332720e546..13d45d2e325769f61dd9bb1e263cb3cb9af69e67 100644 (file)
--- a/src/log.h
+++ b/src/log.h
@@ -223,6 +223,8 @@ class Logger {
                                            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);
 

diff --git a/tools/tickprocessor.js b/tools/tickprocessor.js
index 84f0eea580d10fcef2ad01d15da638f782cc1bdc..fd23987d9f399082ad4707ba41151c5d412976fa 100644 (file)
--- a/tools/tickprocessor.js
+++ b/tools/tickprocessor.js
@@ -75,7 +75,18 @@ function TickProcessor(
       '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 @@ function TickProcessor(
   // 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.processTick = function(pc, sp, vmState, stack) {
 };
 
 
+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 +