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
R=loislo@chromium.org, yangguo@chromium.org

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

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

src/frames-inl.h

@@ -334,10 +334,10 @@ inline JavaScriptFrame* JavaScriptFrameIterator::frame() const {
 }
 
 
-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_;
 }
 
 

src/frames.cc

@@ -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 @@ SafeStackFrameIterator::SafeStackFrameIterator(
     : 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 @@ SafeStackFrameIterator::SafeStackFrameIterator(
   }
   if (SingletonFor(type) == NULL) return;
   frame_ = SingletonFor(type, &state);
+  if (frame_ == NULL) return;
+
+  Advance();
 
-  if (!done()) 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 @@ void SafeStackFrameIterator::Advance() {
     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;
+      }
+    }
   }
 }
 

src/frames.h

@@ -47,6 +47,7 @@ int JSCallerSavedCode(int n);
 
 
 // Forward declarations.
+class ExternalCallbackScope;
 class StackFrameIteratorBase;
 class ThreadLocalTop;
 class Isolate;
@@ -884,7 +885,7 @@ class SafeStackFrameIterator: public StackFrameIteratorBase {
                          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 @@ class SafeStackFrameIterator: public StackFrameIteratorBase {
   const Address low_bound_;
   const Address high_bound_;
   StackFrame::Type top_frame_type_;
+  ExternalCallbackScope* external_callback_scope_;
 };
 
 

src/isolate.cc

@@ -95,7 +95,7 @@ void ThreadLocalTop::InitializeInternal() {
   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;

src/isolate.h

@@ -65,6 +65,7 @@ class CpuProfiler;
 class DeoptimizerData;
 class Deserializer;
 class EmptyStatement;
+class ExternalCallbackScope;
 class ExternalReferenceTable;
 class Factory;
 class FunctionInfoListener;
@@ -279,7 +280,8 @@ class ThreadLocalTop BASE_EMBEDDED {
 #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 @@ class Isolate {
 
   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() {

src/profile-generator.cc

@@ -655,7 +655,8 @@ void ProfileGenerator::RecordTickSample(const TickSample& sample) {
   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.

src/sampler.cc

@@ -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 @@ DISABLE_ASAN void TickSample::Init(Isolate* isolate,
     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

src/vm-state-inl.h

@@ -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 @@ VMState<Tag>::~VMState() {
 
 
 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
 }
 
 

src/vm-state.h

@@ -50,9 +50,18 @@ class ExternalCallbackScope BASE_EMBEDDED {
  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

test/cctest/test-api.cc

@@ -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 @@ static void CheckReturnValue(const T& t, i::Address callback) {
   // 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());
   }
 }
 

test/cctest/test-cpu-profiler.cc

@@ -1081,3 +1081,231 @@ TEST(FunctionApplySample) {
   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();
+}