Revision: 15832
Author:   [email protected]
Date:     Tue Jul 23 08:01:38 2013
Log: Fix call stack sampling for the case when native callback invokes JS function

The SafeStackFrameIterator used by CPU profiler checked if Isolate::c_entry_fp is null and if it is not it would think that the control flow currently is in some native code. This assumption is wrong because the native code could have called a JS function but JSEntryStub would not reset c_entry_fp to NULL in that case. This CL adds a check in SafeStackFrameIterator::IsValidTop for the case when there is a JAVA_SCRIPT frame on top of EXIT frame.

Also this CL changes ExternalCallbackScope behavior to provide access to the whole stack of the scope objects instead of only top one. This allowed to provide exact callback names for those EXIT frames where external callbacks are called. Without this change it was possible only for the top most native call.

BUG=None
[email protected], [email protected]

Review URL: https://codereview.chromium.org/19775017
http://code.google.com/p/v8/source/detail?r=15832

Modified:
 /branches/bleeding_edge/src/frames-inl.h
 /branches/bleeding_edge/src/frames.cc
 /branches/bleeding_edge/src/frames.h
 /branches/bleeding_edge/src/isolate.cc
 /branches/bleeding_edge/src/isolate.h
 /branches/bleeding_edge/src/profile-generator.cc
 /branches/bleeding_edge/src/sampler.cc
 /branches/bleeding_edge/src/vm-state-inl.h
 /branches/bleeding_edge/src/vm-state.h
 /branches/bleeding_edge/test/cctest/test-api.cc
 /branches/bleeding_edge/test/cctest/test-cpu-profiler.cc

=======================================
--- /branches/bleeding_edge/src/frames-inl.h    Thu Jul 11 09:45:58 2013
+++ /branches/bleeding_edge/src/frames-inl.h    Tue Jul 23 08:01:38 2013
@@ -334,10 +334,10 @@
 }


-inline JavaScriptFrame* SafeStackFrameIterator::frame() const {
+inline StackFrame* SafeStackFrameIterator::frame() const {
   ASSERT(!done());
-  ASSERT(frame_->is_java_script());
-  return static_cast<JavaScriptFrame*>(frame_);
+  ASSERT(frame_->is_java_script() || frame_->is_exit());
+  return frame_;
 }


=======================================
--- /branches/bleeding_edge/src/frames.cc       Tue Jul 23 06:46:10 2013
+++ /branches/bleeding_edge/src/frames.cc       Tue Jul 23 08:01:38 2013
@@ -36,6 +36,7 @@
 #include "safepoint-table.h"
 #include "scopeinfo.h"
 #include "string-stream.h"
+#include "vm-state-inl.h"

 #include "allocation-inl.h"

@@ -221,7 +222,8 @@
     : StackFrameIteratorBase(isolate, false),
       low_bound_(sp),
       high_bound_(js_entry_sp),
-      top_frame_type_(StackFrame::NONE) {
+      top_frame_type_(StackFrame::NONE),
+      external_callback_scope_(isolate->external_callback_scope()) {
   StackFrame::State state;
   StackFrame::Type type;
   ThreadLocalTop* top = isolate->thread_local_top();
@@ -256,16 +258,28 @@
   }
   if (SingletonFor(type) == NULL) return;
   frame_ = SingletonFor(type, &state);
+  if (frame_ == NULL) return;

-  if (!done()) Advance();
+  Advance();
+
+  if (frame_ != NULL && !frame_->is_exit() &&
+      external_callback_scope_ != NULL &&
+      external_callback_scope_->scope_address() < frame_->fp()) {
+    // Skip top ExternalCallbackScope if we already advanced to a JS frame
+    // under it. Sampler will anyways take this top external callback.
+    external_callback_scope_ = external_callback_scope_->previous();
+  }
 }


 bool SafeStackFrameIterator::IsValidTop(ThreadLocalTop* top) const {
-  Address fp = Isolate::c_entry_fp(top);
-  if (!IsValidExitFrame(fp)) return false;
+  Address c_entry_fp = Isolate::c_entry_fp(top);
+  if (!IsValidExitFrame(c_entry_fp)) return false;
   // There should be at least one JS_ENTRY stack handler.
-  return Isolate::handler(top) != NULL;
+  Address handler = Isolate::handler(top);
+  if (handler == NULL) return false;
+  // Check that there are no js frames on top of the native frames.
+  return c_entry_fp < handler;
 }


@@ -340,6 +354,24 @@
     AdvanceOneFrame();
     if (done()) return;
     if (frame_->is_java_script()) return;
+    if (frame_->is_exit() && external_callback_scope_) {
+ // Some of the EXIT frames may have ExternalCallbackScope allocated on
+      // top of them. In that case the scope corresponds to the first EXIT
+      // frame beneath it. There may be other EXIT frames on top of the
+ // ExternalCallbackScope, just skip them as we cannot collect any useful
+      // information about them.
+      if (external_callback_scope_->scope_address() < frame_->fp()) {
+        Address* callback_address =
+            external_callback_scope_->callback_address();
+        if (*callback_address != NULL) {
+          frame_->state_.pc_address = callback_address;
+        }
+        external_callback_scope_ = external_callback_scope_->previous();
+        ASSERT(external_callback_scope_ == NULL ||
+               external_callback_scope_->scope_address() > frame_->fp());
+        return;
+      }
+    }
   }
 }

=======================================
--- /branches/bleeding_edge/src/frames.h        Tue Jul 23 06:46:10 2013
+++ /branches/bleeding_edge/src/frames.h        Tue Jul 23 08:01:38 2013
@@ -47,6 +47,7 @@


 // Forward declarations.
+class ExternalCallbackScope;
 class StackFrameIteratorBase;
 class ThreadLocalTop;
 class Isolate;
@@ -884,7 +885,7 @@
                          Address fp, Address sp,
                          Address js_entry_sp);

-  inline JavaScriptFrame* frame() const;
+  inline StackFrame* frame() const;
   void Advance();

   StackFrame::Type top_frame_type() const { return top_frame_type_; }
@@ -903,6 +904,7 @@
   const Address low_bound_;
   const Address high_bound_;
   StackFrame::Type top_frame_type_;
+  ExternalCallbackScope* external_callback_scope_;
 };


=======================================
--- /branches/bleeding_edge/src/isolate.cc      Fri Jul 19 02:39:01 2013
+++ /branches/bleeding_edge/src/isolate.cc      Tue Jul 23 08:01:38 2013
@@ -95,7 +95,7 @@
   simulator_ = NULL;
 #endif
   js_entry_sp_ = NULL;
-  external_callback_ = NULL;
+  external_callback_scope_ = NULL;
   current_vm_state_ = EXTERNAL;
   try_catch_handler_address_ = NULL;
   context_ = NULL;
=======================================
--- /branches/bleeding_edge/src/isolate.h       Fri Jul 19 02:39:01 2013
+++ /branches/bleeding_edge/src/isolate.h       Tue Jul 23 08:01:38 2013
@@ -65,6 +65,7 @@
 class DeoptimizerData;
 class Deserializer;
 class EmptyStatement;
+class ExternalCallbackScope;
 class ExternalReferenceTable;
 class Factory;
 class FunctionInfoListener;
@@ -279,7 +280,8 @@
 #endif  // USE_SIMULATOR

   Address js_entry_sp_;  // the stack pointer of the bottom JS entry frame
-  Address external_callback_;  // the external callback we're currently in
+  // the external callback we're currently in
+  ExternalCallbackScope* external_callback_scope_;
   StateTag current_vm_state_;

   // Generated code scratch locations.
@@ -1032,11 +1034,11 @@

   static const int kJSRegexpStaticOffsetsVectorSize = 128;

-  Address external_callback() {
-    return thread_local_top_.external_callback_;
+  ExternalCallbackScope* external_callback_scope() {
+    return thread_local_top_.external_callback_scope_;
   }
-  void set_external_callback(Address callback) {
-    thread_local_top_.external_callback_ = callback;
+  void set_external_callback_scope(ExternalCallbackScope* scope) {
+    thread_local_top_.external_callback_scope_ = scope;
   }

   StateTag current_vm_state() {
=======================================
--- /branches/bleeding_edge/src/profile-generator.cc Sat Jul 6 02:12:09 2013 +++ /branches/bleeding_edge/src/profile-generator.cc Tue Jul 23 08:01:38 2013
@@ -655,7 +655,8 @@
   CodeEntry** entry = entries.start();
   memset(entry, 0, entries.length() * sizeof(*entry));
   if (sample.pc != NULL) {
-    if (sample.has_external_callback) {
+    if (sample.has_external_callback && sample.state == EXTERNAL &&
+        sample.top_frame_type == StackFrame::EXIT) {
       // Don't use PC when in external callback code, as it can point
       // inside callback's code, and we will erroneously report
       // that a callback calls itself.
=======================================
--- /branches/bleeding_edge/src/sampler.cc      Wed Jul 10 05:56:58 2013
+++ /branches/bleeding_edge/src/sampler.cc      Tue Jul 23 08:01:38 2013
@@ -69,6 +69,7 @@
 #include "platform.h"
 #include "simulator.h"
 #include "v8threads.h"
+#include "vm-state-inl.h"


 #if defined(__ANDROID__) && !defined(__BIONIC_HAVE_UCONTEXT_T)
@@ -621,9 +622,13 @@
     return;
   }

-  const Address callback = isolate->external_callback();
-  if (callback != NULL) {
-    external_callback = callback;
+  ExternalCallbackScope* scope = isolate->external_callback_scope();
+  Address handler = Isolate::handler(isolate->thread_local_top());
+  // If there is a handler on top of the external callback scope then
+  // we have already entrered JavaScript again and the external callback
+  // is not the top function.
+  if (scope && scope->scope_address() < handler) {
+    external_callback = scope->callback();
     has_external_callback = true;
   } else {
     // Sample potential return address value for frameless invocation of
=======================================
--- /branches/bleeding_edge/src/vm-state-inl.h  Wed Apr 24 07:44:08 2013
+++ /branches/bleeding_edge/src/vm-state-inl.h  Tue Jul 23 08:01:38 2013
@@ -29,7 +29,8 @@
 #define V8_VM_STATE_INL_H_

 #include "vm-state.h"
-#include "runtime-profiler.h"
+#include "log.h"
+#include "simulator.h"

 namespace v8 {
 namespace internal {
@@ -80,12 +81,26 @@


ExternalCallbackScope::ExternalCallbackScope(Isolate* isolate, Address callback)
-    : isolate_(isolate), previous_callback_(isolate->external_callback()) {
-  isolate_->set_external_callback(callback);
+    : isolate_(isolate),
+      callback_(callback),
+      previous_scope_(isolate->external_callback_scope()) {
+#ifdef USE_SIMULATOR
+  int32_t sp = Simulator::current(isolate)->get_register(Simulator::sp);
+  scope_address_ = reinterpret_cast<Address>(static_cast<intptr_t>(sp));
+#endif
+  isolate_->set_external_callback_scope(this);
 }

 ExternalCallbackScope::~ExternalCallbackScope() {
-  isolate_->set_external_callback(previous_callback_);
+  isolate_->set_external_callback_scope(previous_scope_);
+}
+
+Address ExternalCallbackScope::scope_address() {
+#ifdef USE_SIMULATOR
+  return scope_address_;
+#else
+  return reinterpret_cast<Address>(this);
+#endif
 }


=======================================
--- /branches/bleeding_edge/src/vm-state.h      Wed Apr 24 07:44:08 2013
+++ /branches/bleeding_edge/src/vm-state.h      Tue Jul 23 08:01:38 2013
@@ -50,9 +50,18 @@
  public:
   inline ExternalCallbackScope(Isolate* isolate, Address callback);
   inline ~ExternalCallbackScope();
+  Address callback() { return callback_; }
+  Address* callback_address() { return &callback_; }
+  ExternalCallbackScope* previous() { return previous_scope_; }
+  inline Address scope_address();
+
  private:
   Isolate* isolate_;
-  Address previous_callback_;
+  Address callback_;
+  ExternalCallbackScope* previous_scope_;
+#ifdef USE_SIMULATOR
+  Address scope_address_;
+#endif
 };

 } }  // namespace v8::internal
=======================================
--- /branches/bleeding_edge/test/cctest/test-api.cc     Mon Jul 15 04:41:41 2013
+++ /branches/bleeding_edge/test/cctest/test-api.cc     Tue Jul 23 08:01:38 2013
@@ -49,6 +49,7 @@
 #include "snapshot.h"
 #include "unicode-inl.h"
 #include "utils.h"
+#include "vm-state.h"

 static const bool kLogThreading = false;

@@ -848,8 +849,8 @@
   // VMState is set to EXTERNAL.
   if (isolate->cpu_profiler()->is_profiling()) {
     CHECK_EQ(i::EXTERNAL, isolate->current_vm_state());
-    CHECK(isolate->external_callback());
-    CHECK_EQ(callback, isolate->external_callback());
+    CHECK(isolate->external_callback_scope());
+    CHECK_EQ(callback, isolate->external_callback_scope()->callback());
   }
 }

=======================================
--- /branches/bleeding_edge/test/cctest/test-cpu-profiler.cc Wed Jul 17 05:16:16 2013 +++ /branches/bleeding_edge/test/cctest/test-cpu-profiler.cc Tue Jul 23 08:01:38 2013
@@ -1081,3 +1081,231 @@
   v8::CpuProfiler* cpu_profiler = env->GetIsolate()->GetCpuProfiler();
   cpu_profiler->DeleteAllCpuProfiles();
 }
+
+
+static const char* js_native_js_test_source = "function foo(iterations) {\n"
+"  var r = 0;\n"
+"  for (var i = 0; i < iterations; i++) { r += i; }\n"
+"  return r;\n"
+"}\n"
+"function bar(iterations) {\n"
+"  try { foo(iterations); } catch(e) {}\n"
+"}\n"
+"function start(duration) {\n"
+"  var start = Date.now();\n"
+"  while (Date.now() - start < duration) {\n"
+"    try {\n"
+"      CallJsFunction(bar, 10 * 1000);\n"
+"    } catch(e) {}\n"
+"  }\n"
+"}";
+
+static void CallJsFunction(const v8::FunctionCallbackInfo<v8::Value>& info) {
+  v8::Handle<v8::Function> function = info[0].As<v8::Function>();
+  v8::Handle<v8::Value> argv[] = { info[1] };
+  function->Call(info.This(), ARRAY_SIZE(argv), argv);
+}
+
+
+// [Top down]:
+//    58     0   (root) #0 1
+//     2     2    (program) #0 2
+//    56     1    start #16 3
+//    55     0      CallJsFunction #0 4
+//    55     1        bar #16 5
+//    54    54          foo #16 6
+TEST(JsNativeJsSample) {
+  LocalContext env;
+  v8::HandleScope scope(env->GetIsolate());
+
+ v8::Local<v8::FunctionTemplate> func_template = v8::FunctionTemplate::New(
+      CallJsFunction);
+  v8::Local<v8::Function> func = func_template->GetFunction();
+  func->SetName(v8::String::New("CallJsFunction"));
+  env->Global()->Set(v8::String::New("CallJsFunction"), func);
+
+  v8::Script::Compile(v8::String::New(js_native_js_test_source))->Run();
+  v8::Local<v8::Function> function = v8::Local<v8::Function>::Cast(
+      env->Global()->Get(v8::String::New("start")));
+
+  int32_t duration_ms = 20;
+  v8::Handle<v8::Value> args[] = { v8::Integer::New(duration_ms) };
+  const v8::CpuProfile* profile =
+      RunProfiler(env, function, args, ARRAY_SIZE(args), 50);
+
+  const v8::CpuProfileNode* root = profile->GetTopDownRoot();
+  {
+    ScopedVector<v8::Handle<v8::String> > names(3);
+ names[0] = v8::String::New(ProfileGenerator::kGarbageCollectorEntryName);
+    names[1] = v8::String::New(ProfileGenerator::kProgramEntryName);
+    names[2] = v8::String::New("start");
+    CheckChildrenNames(root, names);
+  }
+
+  const v8::CpuProfileNode* startNode = GetChild(root, "start");
+  CHECK_EQ(1, startNode->GetChildrenCount());
+  const v8::CpuProfileNode* nativeFunctionNode =
+      GetChild(startNode, "CallJsFunction");
+
+  CHECK_EQ(1, nativeFunctionNode->GetChildrenCount());
+  const v8::CpuProfileNode* barNode = GetChild(nativeFunctionNode, "bar");
+
+  CHECK_EQ(1, barNode->GetChildrenCount());
+  GetChild(barNode, "foo");
+
+  v8::CpuProfiler* cpu_profiler = env->GetIsolate()->GetCpuProfiler();
+  cpu_profiler->DeleteAllCpuProfiles();
+}
+
+
+static const char* js_native_js_runtime_js_test_source =
+"function foo(iterations) {\n"
+"  var r = 0;\n"
+"  for (var i = 0; i < iterations; i++) { r += i; }\n"
+"  return r;\n"
+"}\n"
+"var bound = foo.bind(this);\n"
+"function bar(iterations) {\n"
+"  try { bound(iterations); } catch(e) {}\n"
+"}\n"
+"function start(duration) {\n"
+"  var start = Date.now();\n"
+"  while (Date.now() - start < duration) {\n"
+"    try {\n"
+"      CallJsFunction(bar, 10 * 1000);\n"
+"    } catch(e) {}\n"
+"  }\n"
+"}";
+
+
+// [Top down]:
+//    57     0   (root) #0 1
+//    55     1    start #16 3
+//    54     0      CallJsFunction #0 4
+//    54     3        bar #16 5
+//    51    51          foo #16 6
+//     2     2    (program) #0 2
+TEST(JsNativeJsRuntimeJsSample) {
+  LocalContext env;
+  v8::HandleScope scope(env->GetIsolate());
+
+ v8::Local<v8::FunctionTemplate> func_template = v8::FunctionTemplate::New(
+      CallJsFunction);
+  v8::Local<v8::Function> func = func_template->GetFunction();
+  func->SetName(v8::String::New("CallJsFunction"));
+  env->Global()->Set(v8::String::New("CallJsFunction"), func);
+
+ v8::Script::Compile(v8::String::New(js_native_js_runtime_js_test_source))->
+      Run();
+  v8::Local<v8::Function> function = v8::Local<v8::Function>::Cast(
+      env->Global()->Get(v8::String::New("start")));
+
+  int32_t duration_ms = 20;
+  v8::Handle<v8::Value> args[] = { v8::Integer::New(duration_ms) };
+  const v8::CpuProfile* profile =
+      RunProfiler(env, function, args, ARRAY_SIZE(args), 50);
+
+  const v8::CpuProfileNode* root = profile->GetTopDownRoot();
+  ScopedVector<v8::Handle<v8::String> > names(3);
+  names[0] = v8::String::New(ProfileGenerator::kGarbageCollectorEntryName);
+  names[1] = v8::String::New(ProfileGenerator::kProgramEntryName);
+  names[2] = v8::String::New("start");
+  CheckChildrenNames(root, names);
+
+  const v8::CpuProfileNode* startNode = GetChild(root, "start");
+  CHECK_EQ(1, startNode->GetChildrenCount());
+  const v8::CpuProfileNode* nativeFunctionNode =
+      GetChild(startNode, "CallJsFunction");
+
+  CHECK_EQ(1, nativeFunctionNode->GetChildrenCount());
+  const v8::CpuProfileNode* barNode = GetChild(nativeFunctionNode, "bar");
+
+  CHECK_EQ(1, barNode->GetChildrenCount());
+  GetChild(barNode, "foo");
+
+  v8::CpuProfiler* cpu_profiler = env->GetIsolate()->GetCpuProfiler();
+  cpu_profiler->DeleteAllCpuProfiles();
+}
+
+
+static void CallJsFunction2(const v8::FunctionCallbackInfo<v8::Value>& info) {
+  CallJsFunction(info);
+}
+
+
+static const char* js_native1_js_native2_js_test_source =
+"function foo(iterations) {\n"
+"  var r = 0;\n"
+"  for (var i = 0; i < iterations; i++) { r += i; }\n"
+"  return r;\n"
+"}\n"
+"function bar(iterations) {\n"
+"  CallJsFunction2(foo, iterations);\n"
+"}\n"
+"function start(duration) {\n"
+"  var start = Date.now();\n"
+"  while (Date.now() - start < duration) {\n"
+"    try {\n"
+"      CallJsFunction1(bar, 10 * 1000);\n"
+"    } catch(e) {}\n"
+"  }\n"
+"}";
+
+
+// [Top down]:
+//    57     0   (root) #0 1
+//    55     1    start #16 3
+//    54     0      CallJsFunction1 #0 4
+//    54     0        bar #16 5
+//    54     0          CallJsFunction2 #0 6
+//    54    54            foo #16 7
+//     2     2    (program) #0 2
+TEST(JsNative1JsNative2JsSample) {
+  LocalContext env;
+  v8::HandleScope scope(env->GetIsolate());
+
+ v8::Local<v8::FunctionTemplate> func_template = v8::FunctionTemplate::New(
+      CallJsFunction);
+  v8::Local<v8::Function> func1 = func_template->GetFunction();
+  func1->SetName(v8::String::New("CallJsFunction1"));
+  env->Global()->Set(v8::String::New("CallJsFunction1"), func1);
+
+  v8::Local<v8::Function> func2 = v8::FunctionTemplate::New(
+      CallJsFunction2)->GetFunction();
+  func2->SetName(v8::String::New("CallJsFunction2"));
+  env->Global()->Set(v8::String::New("CallJsFunction2"), func2);
+
+ v8::Script::Compile(v8::String::New(js_native1_js_native2_js_test_source))->
+      Run();
+  v8::Local<v8::Function> function = v8::Local<v8::Function>::Cast(
+      env->Global()->Get(v8::String::New("start")));
+
+  int32_t duration_ms = 20;
+  v8::Handle<v8::Value> args[] = { v8::Integer::New(duration_ms) };
+  const v8::CpuProfile* profile =
+      RunProfiler(env, function, args, ARRAY_SIZE(args), 50);
+
+  const v8::CpuProfileNode* root = profile->GetTopDownRoot();
+  ScopedVector<v8::Handle<v8::String> > names(3);
+  names[0] = v8::String::New(ProfileGenerator::kGarbageCollectorEntryName);
+  names[1] = v8::String::New(ProfileGenerator::kProgramEntryName);
+  names[2] = v8::String::New("start");
+  CheckChildrenNames(root, names);
+
+  const v8::CpuProfileNode* startNode = GetChild(root, "start");
+  CHECK_EQ(1, startNode->GetChildrenCount());
+  const v8::CpuProfileNode* nativeNode1 =
+      GetChild(startNode, "CallJsFunction1");
+
+  CHECK_EQ(1, nativeNode1->GetChildrenCount());
+  const v8::CpuProfileNode* barNode = GetChild(nativeNode1, "bar");
+
+  CHECK_EQ(1, barNode->GetChildrenCount());
+ const v8::CpuProfileNode* nativeNode2 = GetChild(barNode, "CallJsFunction2");
+
+  CHECK_EQ(1, nativeNode2->GetChildrenCount());
+  GetChild(nativeNode2, "foo");
+
+  v8::CpuProfiler* cpu_profiler = env->GetIsolate()->GetCpuProfiler();
+  cpu_profiler->DeleteAllCpuProfiles();
+}

--
--
v8-dev mailing list
[email protected]
http://groups.google.com/group/v8-dev
--- You received this message because you are subscribed to the Google Groups "v8-dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to [email protected].
For more options, visit https://groups.google.com/groups/opt_out.


Reply via email to