Tick processor: Print C++ entry points

R=loislo@chromium.org, yangguo@chromium.org, yurys@chromium.org

Review URL: https://codereview.chromium.org/638633002

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

src/api.cc

@@ -6657,8 +6657,8 @@ void Isolate::GetHeapStatistics(HeapStatistics* heap_statistics) {
 void Isolate::GetStackSample(const RegisterState& state, void** frames,
                              size_t frames_limit, SampleInfo* sample_info) {
   i::Isolate* isolate = reinterpret_cast<i::Isolate*>(this);
-  i::TickSample::GetStackSample(isolate, state, frames, frames_limit,
-                                sample_info);
+  i::TickSample::GetStackSample(isolate, state, i::TickSample::kSkipCEntryFrame,
+                                frames, frames_limit, sample_info);
 }
 
 

src/cpu-profiler.cc

@@ -48,7 +48,7 @@ void ProfilerEventsProcessor::AddCurrentStack(Isolate* isolate) {
     regs.fp = frame->fp();
     regs.pc = frame->pc();
   }
-  record.sample.Init(isolate, regs);
+  record.sample.Init(isolate, regs, TickSample::kSkipCEntryFrame);
   ticks_from_vm_buffer_.Enqueue(record);
 }
 

src/ia32/macro-assembler-ia32.cc

@@ -942,8 +942,10 @@ void MacroAssembler::EnterExitFramePrologue() {
   // Save the frame pointer and the context in top.
   ExternalReference c_entry_fp_address(Isolate::kCEntryFPAddress, isolate());
   ExternalReference context_address(Isolate::kContextAddress, isolate());
+  ExternalReference c_function_address(Isolate::kCFunctionAddress, isolate());
   mov(Operand::StaticVariable(c_entry_fp_address), ebp);
   mov(Operand::StaticVariable(context_address), esi);
+  mov(Operand::StaticVariable(c_function_address), ebx);
 }
 
 

src/isolate.h

@@ -169,6 +169,7 @@ typedef ZoneList<Handle<Object> > ZoneObjectList;
 #define FOR_EACH_ISOLATE_ADDRESS_NAME(C)                \
   C(Handler, handler)                                   \
   C(CEntryFP, c_entry_fp)                               \
+  C(CFunction, c_function)                              \
   C(Context, context)                                   \
   C(PendingException, pending_exception)                \
   C(ExternalCaughtException, external_caught_exception) \
@@ -288,6 +289,7 @@ class ThreadLocalTop BASE_EMBEDDED {
   // Stack.
   Address c_entry_fp_;  // the frame pointer of the top c entry frame
   Address handler_;   // try-blocks are chained through the stack
+  Address c_function_;  // C function that was called at c entry.
 
   // Throwing an exception may cause a Promise rejection.  For this purpose
   // we keep track of a stack of nested promises and the corresponding
@@ -652,11 +654,15 @@ class Isolate {
     return thread->c_entry_fp_;
   }
   static Address handler(ThreadLocalTop* thread) { return thread->handler_; }
+  Address c_function() { return thread_local_top_.c_function_; }
 
   inline Address* c_entry_fp_address() {
     return &thread_local_top_.c_entry_fp_;
   }
   inline Address* handler_address() { return &thread_local_top_.handler_; }
+  inline Address* c_function_address() {
+    return &thread_local_top_.c_function_;
+  }
 
   // Bottom JS entry.
   Address js_entry_sp() {

src/sampler.cc

@@ -570,7 +570,8 @@ SamplerThread* SamplerThread::instance_ = NULL;
 // StackTracer implementation
 //
 DISABLE_ASAN void TickSample::Init(Isolate* isolate,
-                                   const v8::RegisterState& regs) {
+                                   const v8::RegisterState& regs,
+                                   RecordCEntryFrame record_c_entry_frame) {
   timestamp = base::TimeTicks::HighResolutionNow();
   pc = reinterpret_cast<Address>(regs.pc);
   state = isolate->current_vm_state();
@@ -601,13 +602,14 @@ DISABLE_ASAN void TickSample::Init(Isolate* isolate,
   top_frame_type = it.top_frame_type();
 
   SampleInfo info;
-  GetStackSample(isolate, regs, reinterpret_cast<void**>(&stack[0]),
-                 kMaxFramesCount, &info);
+  GetStackSample(isolate, regs, record_c_entry_frame,
+                 reinterpret_cast<void**>(&stack[0]), kMaxFramesCount, &info);
   frames_count = static_cast<unsigned>(info.frames_count);
 }
 
 
 void TickSample::GetStackSample(Isolate* isolate, const v8::RegisterState& regs,
+                                RecordCEntryFrame record_c_entry_frame,
                                 void** frames, size_t frames_limit,
                                 v8::SampleInfo* sample_info) {
   sample_info->frames_count = 0;
@@ -620,6 +622,10 @@ void TickSample::GetStackSample(Isolate* isolate, const v8::RegisterState& regs,
   SafeStackFrameIterator it(isolate, reinterpret_cast<Address>(regs.fp),
                             reinterpret_cast<Address>(regs.sp), js_entry_sp);
   size_t i = 0;
+  if (record_c_entry_frame == kIncludeCEntryFrame && !it.done() &&
+      it.top_frame_type() == StackFrame::EXIT) {
+    frames[i++] = isolate->c_function();
+  }
   while (!it.done() && i < frames_limit) {
     frames[i++] = it.frame()->pc();
     it.Advance();
@@ -696,7 +702,7 @@ void Sampler::SampleStack(const v8::RegisterState& state) {
   TickSample* sample = isolate_->cpu_profiler()->StartTickSample();
   TickSample sample_obj;
   if (sample == NULL) sample = &sample_obj;
-  sample->Init(isolate_, state);
+  sample->Init(isolate_, state, TickSample::kIncludeCEntryFrame);
   if (is_counting_samples_) {
     if (sample->state == JS || sample->state == EXTERNAL) {
       ++js_and_external_sample_count_;

src/sampler.h

@@ -25,6 +25,11 @@ class Isolate;
 
 // TickSample captures the information collected for each sample.
 struct TickSample {
+  // Internal profiling (with --prof + tools/$OS-tick-processor) wants to
+  // include the runtime function we're calling. Externally exposed tick
+  // samples don't care.
+  enum RecordCEntryFrame { kIncludeCEntryFrame, kSkipCEntryFrame };
+
   TickSample()
       : state(OTHER),
         pc(NULL),
@@ -32,8 +37,10 @@ struct TickSample {
         frames_count(0),
         has_external_callback(false),
         top_frame_type(StackFrame::NONE) {}
-  void Init(Isolate* isolate, const v8::RegisterState& state);
+  void Init(Isolate* isolate, const v8::RegisterState& state,
+            RecordCEntryFrame record_c_entry_frame);
   static void GetStackSample(Isolate* isolate, const v8::RegisterState& state,
+                             RecordCEntryFrame record_c_entry_frame,
                              void** frames, size_t frames_limit,
                              v8::SampleInfo* sample_info);
   StateTag state;  // The state of the VM.

src/x64/macro-assembler-x64.cc

@@ -4093,6 +4093,7 @@ void MacroAssembler::EnterExitFramePrologue(bool save_rax) {
 
   Store(ExternalReference(Isolate::kCEntryFPAddress, isolate()), rbp);
   Store(ExternalReference(Isolate::kContextAddress, isolate()), rsi);
+  Store(ExternalReference(Isolate::kCFunctionAddress, isolate()), rbx);
 }
 
 

test/cctest/trace-extension.cc

@@ -91,7 +91,8 @@ void TraceExtension::DoTrace(Address fp) {
   // sp is only used to define stack high bound
   regs.sp =
       reinterpret_cast<Address>(trace_env.sample) - 10240;
-  trace_env.sample->Init(CcTest::i_isolate(), regs);
+  trace_env.sample->Init(CcTest::i_isolate(), regs,
+                         TickSample::kSkipCEntryFrame);
 }
 
 

test/mjsunit/tools/tickprocessor-test.default

@@ -24,6 +24,13 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
       4   30.8%          Shared libraries
       2   15.4%          Unaccounted
 
+ [C++ entry points]:
+   ticks    cpp   total   name
+      2   40.0%   15.4%  v8::internal::Runtime_Math_exp(v8::internal::Arguments)
+      1   20.0%    7.7%  v8::internal::JSObject::LookupOwnRealNamedProperty(v8::internal::String*, v8::internal::LookupResult*)
+      1   20.0%    7.7%  v8::internal::HashTable<v8::internal::StringDictionaryShape, v8::internal::String*>::FindEntry(v8::internal::String*)
+      1   20.0%    7.7%  exp
+
  [Bottom up (heavy) profile]:
   Note: percentage shows a share of a particular caller in the total
   amount of its parent calls.

test/mjsunit/tools/tickprocessor-test.func-info

@@ -18,6 +18,9 @@ Statistical profiling result from v8.log, (3 ticks, 0 unaccounted, 0 excluded).
       0    0.0%    0.0%  GC
       0    0.0%          Shared libraries
 
+ [C++ entry points]:
+   ticks    cpp   total   name
+
  [Bottom up (heavy) profile]:
   Note: percentage shows a share of a particular caller in the total
   amount of its parent calls.

test/mjsunit/tools/tickprocessor-test.gc-state

@@ -16,6 +16,9 @@ Statistical profiling result from v8.log, (13 ticks, 0 unaccounted, 13 excluded)
       0    0.0%    0.0%  GC
       0    0.0%          Shared libraries
 
+ [C++ entry points]:
+   ticks    cpp   total   name
+
  [Bottom up (heavy) profile]:
   Note: percentage shows a share of a particular caller in the total
   amount of its parent calls.

test/mjsunit/tools/tickprocessor-test.ignore-unknown

@@ -23,6 +23,13 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
       0    0.0%    0.0%  GC
       4   36.4%          Shared libraries
 
+ [C++ entry points]:
+   ticks    cpp   total   name
+      2   40.0%   18.2%  v8::internal::Runtime_Math_exp(v8::internal::Arguments)
+      1   20.0%    9.1%  v8::internal::JSObject::LookupOwnRealNamedProperty(v8::internal::String*, v8::internal::LookupResult*)
+      1   20.0%    9.1%  v8::internal::HashTable<v8::internal::StringDictionaryShape, v8::internal::String*>::FindEntry(v8::internal::String*)
+      1   20.0%    9.1%  exp
+
  [Bottom up (heavy) profile]:
   Note: percentage shows a share of a particular caller in the total
   amount of its parent calls.

test/mjsunit/tools/tickprocessor-test.separate-ic

@@ -26,6 +26,13 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
       4   30.8%          Shared libraries
       2   15.4%          Unaccounted
 
+ [C++ entry points]:
+   ticks    cpp   total   name
+      2   40.0%   15.4%  v8::internal::Runtime_Math_exp(v8::internal::Arguments)
+      1   20.0%    7.7%  v8::internal::JSObject::LookupOwnRealNamedProperty(v8::internal::String*, v8::internal::LookupResult*)
+      1   20.0%    7.7%  v8::internal::HashTable<v8::internal::StringDictionaryShape, v8::internal::String*>::FindEntry(v8::internal::String*)
+      1   20.0%    7.7%  exp
+
  [Bottom up (heavy) profile]:
   Note: percentage shows a share of a particular caller in the total
   amount of its parent calls.

tools/codemap.js

@@ -258,11 +258,13 @@ CodeMap.prototype.getAllLibrariesEntries = function() {
  *
  * @param {number} size Code entry size in bytes.
  * @param {string} opt_name Code entry name.
+ * @param {string} opt_type Code entry type, e.g. SHARED_LIB, CPP.
  * @constructor
  */
-CodeMap.CodeEntry = function(size, opt_name) {
+CodeMap.CodeEntry = function(size, opt_name, opt_type) {
   this.size = size;
   this.name = opt_name || '';
+  this.type = opt_type || '';
   this.nameUpdated_ = false;
 };
 

tools/logreader.js

@@ -108,6 +108,8 @@ LogReader.prototype.processStack = function(pc, func, stack) {
     // Filter out possible 'overflow' string.
     } else if (firstChar != 'o') {
       fullStack.push(parseInt(frame, 16));
+    } else {
+      print("dropping: " + frame);
     }
   }
   return fullStack;

tools/profile.js

@@ -36,6 +36,7 @@ function Profile() {
   this.codeMap_ = new CodeMap();
   this.topDownTree_ = new CallTree();
   this.bottomUpTree_ = new CallTree();
+  this.c_entries_ = {};
 };
 
 
@@ -102,7 +103,7 @@ Profile.prototype.handleUnknownCode = function(
 Profile.prototype.addLibrary = function(
     name, startAddr, endAddr) {
   var entry = new CodeMap.CodeEntry(
-      endAddr - startAddr, name);
+      endAddr - startAddr, name, 'SHARED_LIB');
   this.codeMap_.addLibrary(startAddr, entry);
   return entry;
 };
@@ -118,7 +119,7 @@ Profile.prototype.addLibrary = function(
 Profile.prototype.addStaticCode = function(
     name, startAddr, endAddr) {
   var entry = new CodeMap.CodeEntry(
-      endAddr - startAddr, name);
+      endAddr - startAddr, name, 'CPP');
   this.codeMap_.addStaticCode(startAddr, entry);
   return entry;
 };
@@ -250,10 +251,26 @@ Profile.prototype.recordTick = function(stack) {
  */
 Profile.prototype.resolveAndFilterFuncs_ = function(stack) {
   var result = [];
+  var last_seen_c_function = '';
+  var look_for_first_c_function = false;
   for (var i = 0; i < stack.length; ++i) {
     var entry = this.codeMap_.findEntry(stack[i]);
     if (entry) {
       var name = entry.getName();
+      if (i == 0 && (entry.type == 'CPP' || entry.type == 'SHARED_LIB')) {
+        look_for_first_c_function = true;
+      }
+      if (look_for_first_c_function) {
+        if (entry.type == 'CPP') {
+          last_seen_c_function = name;
+        } else if (i > 0 && last_seen_c_function != '') {
+          if (this.c_entries_[last_seen_c_function] === undefined) {
+            this.c_entries_[last_seen_c_function] = 0;
+          }
+          this.c_entries_[last_seen_c_function]++;
+          look_for_first_c_function = false;  // Found it, we're done.
+        }
+      }
       if (!this.skipThisFunction(name)) {
         result.push(name);
       }
@@ -381,6 +398,28 @@ Profile.prototype.getFlatProfile = function(opt_label) {
 };
 
 
+Profile.CEntryNode = function(name, ticks) {
+  this.name = name;
+  this.ticks = ticks;
+}
+
+
+Profile.prototype.getCEntryProfile = function() {
+  var result = [new Profile.CEntryNode("TOTAL", 0)];
+  var total_ticks = 0;
+  for (var f in this.c_entries_) {
+    var ticks = this.c_entries_[f];
+    total_ticks += ticks;
+    result.push(new Profile.CEntryNode(f, ticks));
+  }
+  result[0].ticks = total_ticks;  // Sorting will keep this at index 0.
+  result.sort(function(n1, n2) {
+    return n2.ticks - n1.ticks || (n2.name < n1.name ? -1 : 1)
+  });
+  return result;
+}
+
+
 /**
  * Cleans up function entries that are not referenced by code entries.
  */
@@ -415,8 +454,7 @@ Profile.prototype.cleanUpFuncEntries = function() {
  * @constructor
  */
 Profile.DynamicCodeEntry = function(size, type, name) {
-  CodeMap.CodeEntry.call(this, size, name);
-  this.type = type;
+  CodeMap.CodeEntry.call(this, size, name, type);
 };
 
 
@@ -456,8 +494,7 @@ Profile.DynamicCodeEntry.prototype.toString = function() {
  * @constructor
  */
 Profile.DynamicFuncCodeEntry = function(size, type, func, state) {
-  CodeMap.CodeEntry.call(this, size);
-  this.type = type;
+  CodeMap.CodeEntry.call(this, size, '', type);
   this.func = func;
   this.state = state;
 };

tools/tickprocessor.js

@@ -485,6 +485,15 @@ TickProcessor.prototype.printStatistics = function() {
                    this.ticks_.total, null);
   }
 
+  print('\n [C++ entry points]:');
+  print('   ticks    cpp   total   name');
+  var c_entry_functions = this.profile_.getCEntryProfile();
+  var total_c_entry = c_entry_functions[0].ticks;
+  for (var i = 1; i < c_entry_functions.length; i++) {
+    c = c_entry_functions[i];
+    this.printLine(c.name, c.ticks, total_c_entry, totalTicks);
+  }
+
   this.printHeavyProfHeader();
   var heavyProfile = this.profile_.getBottomUpProfile();
   var heavyView = this.viewBuilder_.buildView(heavyProfile);