Add sanity test for CPU profiler
authoryurys@chromium.org <yurys@chromium.org@ce2b1a6d-e550-0410-aec6-3dcde31c8c00>
Wed, 10 Apr 2013 09:47:44 +0000 (09:47 +0000)
committeryurys@chromium.org <yurys@chromium.org@ce2b1a6d-e550-0410-aec6-3dcde31c8c00>
Wed, 10 Apr 2013 09:47:44 +0000 (09:47 +0000)
The new test checks full CPU profiling cycle: using public
V8 API it starts profiling, executes a script, stops profiling
and analyzes collected profile to check that its top-down
tree has expected strutcture. The script that is being profiled
is guaranteed to run > 200ms to make sure enough samples
are collected.

To avoid possible flakiness due to non-deterministic time required
to start new thread on varios OSs when Sampler and ProfilerEventsProcessor
threads are being started the main thread is blocked until the threads
are running.

Also I removed the heuristic in profile-generator.cc where we try
to figure out if the value on top of the sampled stack is return address
of some frameless stub invocation. The code periodically gives false positive
with the new test ending up in an extra node in the collected cpu profile.
After discussion with jkummerow@ we concluded that the logic is too fragile
and that we can address frameless stub invocations in a more reliable way
later should they have a noticeable effect on cpu profiling.

BUG=None

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

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

12 files changed:
src/cpu-profiler.cc
src/platform-cygwin.cc
src/platform-freebsd.cc
src/platform-linux.cc
src/platform-macos.cc
src/platform-nullos.cc
src/platform-openbsd.cc
src/platform-solaris.cc
src/platform-win32.cc
src/platform.h
src/profile-generator.cc
test/cctest/test-cpu-profiler.cc

index 7979eb4d21a0c33e1630992244f15cb54bab43df..47c2a94232c1533da2b77cbfbd8189daa03ad903 100644 (file)
@@ -445,7 +445,7 @@ void CpuProfiler::StartProcessorIfNotStarted() {
     generator_ = new ProfileGenerator(profiles_);
     processor_ = new ProfilerEventsProcessor(generator_);
     is_profiling_ = true;
-    processor_->Start();
+    processor_->StartSynchronously();
     // Enumerate stuff we already have in the heap.
     if (isolate_->heap()->HasBeenSetUp()) {
       if (!FLAG_prof_browser_mode) {
@@ -459,11 +459,11 @@ void CpuProfiler::StartProcessorIfNotStarted() {
     }
     // Enable stack sampling.
     Sampler* sampler = reinterpret_cast<Sampler*>(isolate_->logger()->ticker_);
+    sampler->IncreaseProfilingDepth();
     if (!sampler->IsActive()) {
       sampler->Start();
       need_to_stop_sampler_ = true;
     }
-    sampler->IncreaseProfilingDepth();
   }
 }
 
index 67c389e794eca914d0ff9259e10903b5289dff25..23f88c9fe6c883c1615301436f500e87d5f2e465 100644 (file)
@@ -381,7 +381,8 @@ class Thread::PlatformData : public Malloced {
 
 Thread::Thread(const Options& options)
     : data_(new PlatformData()),
-      stack_size_(options.stack_size()) {
+      stack_size_(options.stack_size()),
+      start_semaphore_(NULL) {
   set_name(options.name());
 }
 
@@ -398,7 +399,7 @@ static void* ThreadEntry(void* arg) {
   // one) so we initialize it here too.
   thread->data()->thread_ = pthread_self();
   ASSERT(thread->data()->thread_ != kNoThread);
-  thread->Run();
+  thread->NotifyStartedAndRun();
   return NULL;
 }
 
@@ -639,7 +640,7 @@ class SamplerThread : public Thread {
     SamplerRegistry::AddActiveSampler(sampler);
     if (instance_ == NULL) {
       instance_ = new SamplerThread(sampler->interval());
-      instance_->Start();
+      instance_->StartSynchronously();
     } else {
       ASSERT(instance_->interval_ == sampler->interval());
     }
index 14f7171a3cf7f33fb349bff7a65ad3d978ed117e..8c2e397ebad71ce955ca04a4c2777a9839bd909f 100644 (file)
@@ -500,7 +500,8 @@ class Thread::PlatformData : public Malloced {
 
 Thread::Thread(const Options& options)
     : data_(new PlatformData),
-      stack_size_(options.stack_size()) {
+      stack_size_(options.stack_size()),
+      start_semaphore_(NULL) {
   set_name(options.name());
 }
 
@@ -517,7 +518,7 @@ static void* ThreadEntry(void* arg) {
   // one) so we initialize it here too.
   thread->data()->thread_ = pthread_self();
   ASSERT(thread->data()->thread_ != kNoThread);
-  thread->Run();
+  thread->NotifyStartedAndRun();
   return NULL;
 }
 
@@ -765,7 +766,7 @@ class SignalSender : public Thread {
 
       // Start a thread that sends SIGPROF signal to VM threads.
       instance_ = new SignalSender(sampler->interval());
-      instance_->Start();
+      instance_->StartSynchronously();
     } else {
       ASSERT(instance_->interval_ == sampler->interval());
     }
index dbd496ef060d7a906c0e5c644931a896593714af..36b91449096d805f7e53e272335938dd4aa9f6e0 100644 (file)
@@ -785,7 +785,8 @@ class Thread::PlatformData : public Malloced {
 
 Thread::Thread(const Options& options)
     : data_(new PlatformData()),
-      stack_size_(options.stack_size()) {
+      stack_size_(options.stack_size()),
+      start_semaphore_(NULL) {
   set_name(options.name());
 }
 
@@ -807,7 +808,7 @@ static void* ThreadEntry(void* arg) {
 #endif
   thread->data()->thread_ = pthread_self();
   ASSERT(thread->data()->thread_ != kNoThread);
-  thread->Run();
+  thread->NotifyStartedAndRun();
   return NULL;
 }
 
@@ -1183,7 +1184,7 @@ class SignalSender : public Thread {
       // Start a thread that will send SIGPROF signal to VM threads,
       // when CPU profiling will be enabled.
       instance_ = new SignalSender(sampler->interval());
-      instance_->Start();
+      instance_->StartSynchronously();
     } else {
       ASSERT(instance_->interval_ == sampler->interval());
     }
index 30e2b890bb75faee074808802b2e9ae3eac59ed0..52f6d7ea50638fe380c40a86779f76c8e3e27632 100644 (file)
@@ -495,7 +495,8 @@ class Thread::PlatformData : public Malloced {
 
 Thread::Thread(const Options& options)
     : data_(new PlatformData),
-      stack_size_(options.stack_size()) {
+      stack_size_(options.stack_size()),
+      start_semaphore_(NULL) {
   set_name(options.name());
 }
 
@@ -530,7 +531,7 @@ static void* ThreadEntry(void* arg) {
   thread->data()->thread_ = pthread_self();
   SetThreadName(thread->name());
   ASSERT(thread->data()->thread_ != kNoThread);
-  thread->Run();
+  thread->NotifyStartedAndRun();
   return NULL;
 }
 
@@ -776,7 +777,7 @@ class SamplerThread : public Thread {
     SamplerRegistry::AddActiveSampler(sampler);
     if (instance_ == NULL) {
       instance_ = new SamplerThread(sampler->interval());
-      instance_->Start();
+      instance_->StartSynchronously();
     } else {
       ASSERT(instance_->interval_ == sampler->interval());
     }
index 0fef0633e9b0e5c9f05fc5b16ee126244c9473f9..56d12ac1fe8283ca03b4a3d1d7e6233e5428c9b1 100644 (file)
@@ -369,7 +369,8 @@ class Thread::PlatformData : public Malloced {
 
 Thread::Thread(const Options& options)
     : data_(new PlatformData()),
-      stack_size_(options.stack_size) {
+      stack_size_(options.stack_size),
+      start_semaphore_(NULL) {
   set_name(options.name);
   UNIMPLEMENTED();
 }
index e48d4cb35a477ece3168c76801a6edf4e3e379b5..f4d366bbdf3f942d1c372c6b7f50d1589144118b 100644 (file)
@@ -529,7 +529,8 @@ class Thread::PlatformData : public Malloced {
 
 Thread::Thread(const Options& options)
     : data_(new PlatformData()),
-      stack_size_(options.stack_size()) {
+      stack_size_(options.stack_size()),
+      start_semaphore_(NULL) {
   set_name(options.name());
 }
 
@@ -551,7 +552,7 @@ static void* ThreadEntry(void* arg) {
 #endif
   thread->data()->thread_ = pthread_self();
   ASSERT(thread->data()->thread_ != kNoThread);
-  thread->Run();
+  thread->NotifyStartedAndRun();
   return NULL;
 }
 
@@ -827,7 +828,7 @@ class SignalSender : public Thread {
       // Start a thread that will send SIGPROF signal to VM threads,
       // when CPU profiling will be enabled.
       instance_ = new SignalSender(sampler->interval());
-      instance_->Start();
+      instance_->StartSynchronously();
     } else {
       ASSERT(instance_->interval_ == sampler->interval());
     }
index 0e616d1ab4315131cacdc61f62bc0034353db3f3..90e099a3a4b86847f85a1a9b253fc0bd5c3b3809 100644 (file)
@@ -470,7 +470,8 @@ class Thread::PlatformData : public Malloced {
 
 Thread::Thread(const Options& options)
     : data_(new PlatformData()),
-      stack_size_(options.stack_size()) {
+      stack_size_(options.stack_size()),
+      start_semaphore_(NULL) {
   set_name(options.name());
 }
 
@@ -487,7 +488,7 @@ static void* ThreadEntry(void* arg) {
   // one) so we initialize it here too.
   thread->data()->thread_ = pthread_self();
   ASSERT(thread->data()->thread_ != kNoThread);
-  thread->Run();
+  thread->NotifyStartedAndRun();
   return NULL;
 }
 
@@ -743,7 +744,7 @@ class SignalSender : public Thread {
       // Start a thread that will send SIGPROF signal to VM threads,
       // when CPU profiling will be enabled.
       instance_ = new SignalSender(sampler->interval());
-      instance_->Start();
+      instance_->StartSynchronously();
     } else {
       ASSERT(instance_->interval_ == sampler->interval());
     }
index c1bae9352c82dee92f82426809bb548d916d98df..0fc70c511e0a9706f938322b06cefac4e8d81581 100644 (file)
@@ -1605,7 +1605,7 @@ static const HANDLE kNoThread = INVALID_HANDLE_VALUE;
 // convention.
 static unsigned int __stdcall ThreadEntry(void* arg) {
   Thread* thread = reinterpret_cast<Thread*>(arg);
-  thread->Run();
+  thread->NotifyStartedAndRun();
   return 0;
 }
 
@@ -1622,7 +1622,8 @@ class Thread::PlatformData : public Malloced {
 // handle until it is started.
 
 Thread::Thread(const Options& options)
-    : stack_size_(options.stack_size()) {
+    : stack_size_(options.stack_size()),
+      start_semaphore_(NULL) {
   data_ = new PlatformData(kNoThread);
   set_name(options.name());
 }
@@ -2016,7 +2017,7 @@ class SamplerThread : public Thread {
     SamplerRegistry::AddActiveSampler(sampler);
     if (instance_ == NULL) {
       instance_ = new SamplerThread(sampler->interval());
-      instance_->Start();
+      instance_->StartSynchronously();
     } else {
       ASSERT(instance_->interval_ == sampler->interval());
     }
index f2a228c926c23392103a25ea9aedb52ff4549a2a..1c655da3005c0c0b8ee562d42cced578572be662 100644 (file)
@@ -452,6 +452,59 @@ class VirtualMemory {
 };
 
 
+// ----------------------------------------------------------------------------
+// Semaphore
+//
+// A semaphore object is a synchronization object that maintains a count. The
+// count is decremented each time a thread completes a wait for the semaphore
+// object and incremented each time a thread signals the semaphore. When the
+// count reaches zero,  threads waiting for the semaphore blocks until the
+// count becomes non-zero.
+
+class Semaphore {
+ public:
+  virtual ~Semaphore() {}
+
+  // Suspends the calling thread until the semaphore counter is non zero
+  // and then decrements the semaphore counter.
+  virtual void Wait() = 0;
+
+  // Suspends the calling thread until the counter is non zero or the timeout
+  // time has passed. If timeout happens the return value is false and the
+  // counter is unchanged. Otherwise the semaphore counter is decremented and
+  // true is returned. The timeout value is specified in microseconds.
+  virtual bool Wait(int timeout) = 0;
+
+  // Increments the semaphore counter.
+  virtual void Signal() = 0;
+};
+
+template <int InitialValue>
+struct CreateSemaphoreTrait {
+  static Semaphore* Create() {
+    return OS::CreateSemaphore(InitialValue);
+  }
+};
+
+// POD Semaphore initialized lazily (i.e. the first time Pointer() is called).
+// Usage:
+//   // The following semaphore starts at 0.
+//   static LazySemaphore<0>::type my_semaphore = LAZY_SEMAPHORE_INITIALIZER;
+//
+//   void my_function() {
+//     // Do something with my_semaphore.Pointer().
+//   }
+//
+template <int InitialValue>
+struct LazySemaphore {
+  typedef typename LazyDynamicInstance<
+      Semaphore, CreateSemaphoreTrait<InitialValue>,
+      ThreadSafeInitOnceTrait>::type type;
+};
+
+#define LAZY_SEMAPHORE_INITIALIZER LAZY_DYNAMIC_INSTANCE_INITIALIZER
+
+
 // ----------------------------------------------------------------------------
 // Thread
 //
@@ -489,9 +542,18 @@ class Thread {
   explicit Thread(const Options& options);
   virtual ~Thread();
 
-  // Start new thread by calling the Run() method in the new thread.
+  // Start new thread by calling the Run() method on the new thread.
   void Start();
 
+  // Start new thread and wait until Run() method is called on the new thread.
+  void StartSynchronously() {
+    start_semaphore_ = OS::CreateSemaphore(0);
+    Start();
+    start_semaphore_->Wait();
+    delete start_semaphore_;
+    start_semaphore_ = NULL;
+  }
+
   // Wait until thread terminates.
   void Join();
 
@@ -541,6 +603,11 @@ class Thread {
   class PlatformData;
   PlatformData* data() { return data_; }
 
+  void NotifyStartedAndRun() {
+    if (start_semaphore_) start_semaphore_->Signal();
+    Run();
+  }
+
  private:
   void set_name(const char* name);
 
@@ -548,6 +615,7 @@ class Thread {
 
   char name_[kMaxThreadNameLength];
   int stack_size_;
+  Semaphore* start_semaphore_;
 
   DISALLOW_COPY_AND_ASSIGN(Thread);
 };
@@ -619,59 +687,6 @@ class ScopedLock {
 };
 
 
-// ----------------------------------------------------------------------------
-// Semaphore
-//
-// A semaphore object is a synchronization object that maintains a count. The
-// count is decremented each time a thread completes a wait for the semaphore
-// object and incremented each time a thread signals the semaphore. When the
-// count reaches zero,  threads waiting for the semaphore blocks until the
-// count becomes non-zero.
-
-class Semaphore {
- public:
-  virtual ~Semaphore() {}
-
-  // Suspends the calling thread until the semaphore counter is non zero
-  // and then decrements the semaphore counter.
-  virtual void Wait() = 0;
-
-  // Suspends the calling thread until the counter is non zero or the timeout
-  // time has passed. If timeout happens the return value is false and the
-  // counter is unchanged. Otherwise the semaphore counter is decremented and
-  // true is returned. The timeout value is specified in microseconds.
-  virtual bool Wait(int timeout) = 0;
-
-  // Increments the semaphore counter.
-  virtual void Signal() = 0;
-};
-
-template <int InitialValue>
-struct CreateSemaphoreTrait {
-  static Semaphore* Create() {
-    return OS::CreateSemaphore(InitialValue);
-  }
-};
-
-// POD Semaphore initialized lazily (i.e. the first time Pointer() is called).
-// Usage:
-//   // The following semaphore starts at 0.
-//   static LazySemaphore<0>::type my_semaphore = LAZY_SEMAPHORE_INITIALIZER;
-//
-//   void my_function() {
-//     // Do something with my_semaphore.Pointer().
-//   }
-//
-template <int InitialValue>
-struct LazySemaphore {
-  typedef typename LazyDynamicInstance<
-      Semaphore, CreateSemaphoreTrait<InitialValue>,
-      ThreadSafeInitOnceTrait>::type type;
-};
-
-#define LAZY_SEMAPHORE_INITIALIZER LAZY_DYNAMIC_INSTANCE_INITIALIZER
-
-
 // ----------------------------------------------------------------------------
 // Socket
 //
index ce07213b029403646a4f14d8086fc5269f57c6b3..e4c750cb83c1dbc8b489f2a08779d3b43ccacb0d 100644 (file)
@@ -900,14 +900,6 @@ void ProfileGenerator::RecordTickSample(const TickSample& sample) {
       // that a callback calls itself.
       *(entries.start()) = NULL;
       *entry++ = code_map_.FindEntry(sample.external_callback);
-    } else if (sample.tos != NULL) {
-      // Find out, if top of stack was pointing inside a JS function
-      // meaning that we have encountered a frameless invocation.
-      *entry = code_map_.FindEntry(sample.tos);
-      if (*entry != NULL && !(*entry)->is_js_function()) {
-        *entry = NULL;
-      }
-      entry++;
     }
 
     for (const Address* stack_pos = sample.stack,
index daf7e26724281702a124d573c5903a294ed1eb5d..1643a1fd3ac7de1ffe3d22f9a74028dd3a20c8a9 100644 (file)
@@ -30,6 +30,7 @@
 #include "v8.h"
 #include "cpu-profiler-inl.h"
 #include "cctest.h"
+#include "utils.h"
 #include "../include/v8-profiler.h"
 
 using i::CodeEntry;
@@ -39,7 +40,9 @@ using i::CpuProfilesCollection;
 using i::ProfileGenerator;
 using i::ProfileNode;
 using i::ProfilerEventsProcessor;
+using i::ScopedVector;
 using i::TokenEnumerator;
+using i::Vector;
 
 
 TEST(StartStop) {
@@ -391,3 +394,145 @@ TEST(DeleteCpuProfileDifferentTokens) {
   CHECK_EQ(0, cpu_profiler->GetProfileCount());
   CHECK_EQ(NULL, cpu_profiler->FindCpuProfile(uid3));
 }
+
+
+static bool ContainsString(v8::Handle<v8::String> string,
+                           const Vector<v8::Handle<v8::String> >& vector) {
+  for (int i = 0; i < vector.length(); i++) {
+    if (string->Equals(vector[i]))
+      return true;
+  }
+  return false;
+}
+
+
+static void CheckChildrenNames(const v8::CpuProfileNode* node,
+                               const Vector<v8::Handle<v8::String> >& names) {
+  int count = node->GetChildrenCount();
+  for (int i = 0; i < count; i++) {
+    v8::Handle<v8::String> name = node->GetChild(i)->GetFunctionName();
+    CHECK(ContainsString(name, names));
+    // Check that there are no duplicates.
+    for (int j = 0; j < count; j++) {
+      if (j == i) continue;
+      CHECK_NE(name, node->GetChild(j)->GetFunctionName());
+    }
+  }
+}
+
+
+static const v8::CpuProfileNode* FindChild(const v8::CpuProfileNode* node,
+                                           const char* name) {
+  int count = node->GetChildrenCount();
+  v8::Handle<v8::String> nameHandle = v8::String::New(name);
+  for (int i = 0; i < count; i++) {
+    const v8::CpuProfileNode* child = node->GetChild(i);
+    if (nameHandle->Equals(child->GetFunctionName())) return child;
+  }
+  CHECK(false);
+  return NULL;
+}
+
+
+static void CheckSimpleBranch(const v8::CpuProfileNode* node,
+                              const char* names[], int length) {
+  for (int i = 0; i < length; i++) {
+    const char* name = names[i];
+    node = FindChild(node, name);
+    CHECK(node);
+    int expectedChildrenCount = (i == length - 1) ? 0 : 1;
+    CHECK_EQ(expectedChildrenCount, node->GetChildrenCount());
+  }
+}
+
+
+static const char* cpu_profiler_test_source = "function loop(timeout) {\n"
+"  this.mmm = 0;\n"
+"  var start = Date.now();\n"
+"  while (Date.now() - start < timeout) {\n"
+"    var n = 100*1000;\n"
+"    while(n > 1) {\n"
+"      n--;\n"
+"      this.mmm += n * n * n;\n"
+"    }\n"
+"  }\n"
+"}\n"
+"function delay() { try { loop(10); } catch(e) { } }\n"
+"function bar() { delay(); }\n"
+"function baz() { delay(); }\n"
+"function foo() {\n"
+"    try {\n"
+"       delay();\n"
+"       bar();\n"
+"       delay();\n"
+"       baz();\n"
+"    } catch (e) { }\n"
+"}\n"
+"function start() {\n"
+"  var start = Date.now();\n"
+"  do {\n"
+"    foo();\n"
+"    var duration = Date.now() - start;\n"
+"  } while (duration < 200);\n"
+"  return duration;\n"
+"}\n";
+
+
+// Check that the profile tree for the script above will look like the
+// following:
+//
+// [Top down]:
+//  1062     0   (root) [-1]
+//  1054     0    start [-1]
+//  1054     1      foo [-1]
+//   265     0        baz [-1]
+//   265     1          delay [-1]
+//   264   264            loop [-1]
+//   525     3        delay [-1]
+//   522   522          loop [-1]
+//   263     0        bar [-1]
+//   263     1          delay [-1]
+//   262   262            loop [-1]
+//     2     2    (program) [-1]
+//     6     6    (garbage collector) [-1]
+TEST(CollectCpuProfile) {
+  LocalContext env;
+  v8::HandleScope scope(env->GetIsolate());
+
+  v8::Script::Compile(v8::String::New(cpu_profiler_test_source))->Run();
+  v8::Local<v8::Function> function = v8::Local<v8::Function>::Cast(
+      env->Global()->Get(v8::String::New("start")));
+
+  v8::CpuProfiler* cpu_profiler = env->GetIsolate()->GetCpuProfiler();
+  v8::Local<v8::String> profile_name = v8::String::New("my_profile");
+
+  cpu_profiler->StartCpuProfiling(profile_name);
+  function->Call(env->Global(), 0, 0);
+  const v8::CpuProfile* profile = cpu_profiler->StopCpuProfiling(profile_name);
+
+  CHECK_NE(NULL, profile);
+  // Dump collected profile to have a better diagnostic in case of failure.
+  reinterpret_cast<i::CpuProfile*>(
+      const_cast<v8::CpuProfile*>(profile))->Print();
+
+  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 = FindChild(root, "start");
+  CHECK_EQ(1, startNode->GetChildrenCount());
+
+  const v8::CpuProfileNode* fooNode = FindChild(startNode, "foo");
+  CHECK_EQ(3, fooNode->GetChildrenCount());
+
+  const char* barBranch[] = { "bar", "delay", "loop" };
+  CheckSimpleBranch(fooNode, barBranch, ARRAY_SIZE(barBranch));
+  const char* bazBranch[] = { "baz", "delay", "loop" };
+  CheckSimpleBranch(fooNode, bazBranch, ARRAY_SIZE(bazBranch));
+  const char* delayBranch[] = { "delay", "loop" };
+  CheckSimpleBranch(fooNode, delayBranch, ARRAY_SIZE(delayBranch));
+}