Revision: 14205
Author: [email protected]
Date: Wed Apr 10 02:47:44 2013
Log: Add sanity test for CPU profiler
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
http://code.google.com/p/v8/source/detail?r=14205
Modified:
/branches/bleeding_edge/src/cpu-profiler.cc
/branches/bleeding_edge/src/platform-cygwin.cc
/branches/bleeding_edge/src/platform-freebsd.cc
/branches/bleeding_edge/src/platform-linux.cc
/branches/bleeding_edge/src/platform-macos.cc
/branches/bleeding_edge/src/platform-nullos.cc
/branches/bleeding_edge/src/platform-openbsd.cc
/branches/bleeding_edge/src/platform-solaris.cc
/branches/bleeding_edge/src/platform-win32.cc
/branches/bleeding_edge/src/platform.h
/branches/bleeding_edge/src/profile-generator.cc
/branches/bleeding_edge/test/cctest/test-cpu-profiler.cc
=======================================
--- /branches/bleeding_edge/src/cpu-profiler.cc Tue Apr 2 00:53:50 2013
+++ /branches/bleeding_edge/src/cpu-profiler.cc Wed Apr 10 02:47:44 2013
@@ -445,7 +445,7 @@
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 @@
}
// 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();
}
}
=======================================
--- /branches/bleeding_edge/src/platform-cygwin.cc Tue Apr 2 00:53:50 2013
+++ /branches/bleeding_edge/src/platform-cygwin.cc Wed Apr 10 02:47:44 2013
@@ -381,7 +381,8 @@
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 @@
// 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 @@
SamplerRegistry::AddActiveSampler(sampler);
if (instance_ == NULL) {
instance_ = new SamplerThread(sampler->interval());
- instance_->Start();
+ instance_->StartSynchronously();
} else {
ASSERT(instance_->interval_ == sampler->interval());
}
=======================================
--- /branches/bleeding_edge/src/platform-freebsd.cc Tue Apr 2 00:53:50 2013
+++ /branches/bleeding_edge/src/platform-freebsd.cc Wed Apr 10 02:47:44 2013
@@ -500,7 +500,8 @@
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 @@
// 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 @@
// 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());
}
=======================================
--- /branches/bleeding_edge/src/platform-linux.cc Tue Apr 9 08:11:45 2013
+++ /branches/bleeding_edge/src/platform-linux.cc Wed Apr 10 02:47:44 2013
@@ -785,7 +785,8 @@
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 @@
#endif
thread->data()->thread_ = pthread_self();
ASSERT(thread->data()->thread_ != kNoThread);
- thread->Run();
+ thread->NotifyStartedAndRun();
return NULL;
}
@@ -1183,7 +1184,7 @@
// 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());
}
=======================================
--- /branches/bleeding_edge/src/platform-macos.cc Tue Apr 2 00:53:50 2013
+++ /branches/bleeding_edge/src/platform-macos.cc Wed Apr 10 02:47:44 2013
@@ -495,7 +495,8 @@
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 @@
thread->data()->thread_ = pthread_self();
SetThreadName(thread->name());
ASSERT(thread->data()->thread_ != kNoThread);
- thread->Run();
+ thread->NotifyStartedAndRun();
return NULL;
}
@@ -776,7 +777,7 @@
SamplerRegistry::AddActiveSampler(sampler);
if (instance_ == NULL) {
instance_ = new SamplerThread(sampler->interval());
- instance_->Start();
+ instance_->StartSynchronously();
} else {
ASSERT(instance_->interval_ == sampler->interval());
}
=======================================
--- /branches/bleeding_edge/src/platform-nullos.cc Thu Mar 7 01:12:48 2013
+++ /branches/bleeding_edge/src/platform-nullos.cc Wed Apr 10 02:47:44 2013
@@ -369,7 +369,8 @@
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();
}
=======================================
--- /branches/bleeding_edge/src/platform-openbsd.cc Tue Apr 2 00:53:50 2013
+++ /branches/bleeding_edge/src/platform-openbsd.cc Wed Apr 10 02:47:44 2013
@@ -529,7 +529,8 @@
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 @@
#endif
thread->data()->thread_ = pthread_self();
ASSERT(thread->data()->thread_ != kNoThread);
- thread->Run();
+ thread->NotifyStartedAndRun();
return NULL;
}
@@ -827,7 +828,7 @@
// 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());
}
=======================================
--- /branches/bleeding_edge/src/platform-solaris.cc Tue Apr 2 00:53:50 2013
+++ /branches/bleeding_edge/src/platform-solaris.cc Wed Apr 10 02:47:44 2013
@@ -470,7 +470,8 @@
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 @@
// 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 @@
// 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());
}
=======================================
--- /branches/bleeding_edge/src/platform-win32.cc Tue Apr 2 00:53:50 2013
+++ /branches/bleeding_edge/src/platform-win32.cc Wed Apr 10 02:47:44 2013
@@ -1605,7 +1605,7 @@
// convention.
static unsigned int __stdcall ThreadEntry(void* arg) {
Thread* thread = reinterpret_cast<Thread*>(arg);
- thread->Run();
+ thread->NotifyStartedAndRun();
return 0;
}
@@ -1622,7 +1622,8 @@
// 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 @@
SamplerRegistry::AddActiveSampler(sampler);
if (instance_ == NULL) {
instance_ = new SamplerThread(sampler->interval());
- instance_->Start();
+ instance_->StartSynchronously();
} else {
ASSERT(instance_->interval_ == sampler->interval());
}
=======================================
--- /branches/bleeding_edge/src/platform.h Thu Mar 21 05:05:50 2013
+++ /branches/bleeding_edge/src/platform.h Wed Apr 10 02:47:44 2013
@@ -452,6 +452,59 @@
};
+//
----------------------------------------------------------------------------
+// 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,8 +542,17 @@
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();
@@ -540,6 +602,11 @@
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 @@
char name_[kMaxThreadNameLength];
int stack_size_;
+ Semaphore* start_semaphore_;
DISALLOW_COPY_AND_ASSIGN(Thread);
};
@@ -617,59 +685,6 @@
Mutex* mutex_;
DISALLOW_COPY_AND_ASSIGN(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
//
----------------------------------------------------------------------------
=======================================
--- /branches/bleeding_edge/src/profile-generator.cc Tue Apr 2 00:48:25
2013
+++ /branches/bleeding_edge/src/profile-generator.cc Wed Apr 10 02:47:44
2013
@@ -900,14 +900,6 @@
// 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,
=======================================
--- /branches/bleeding_edge/test/cctest/test-cpu-profiler.cc Wed Apr 10
01:29:39 2013
+++ /branches/bleeding_edge/test/cctest/test-cpu-profiler.cc Wed Apr 10
02:47:44 2013
@@ -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::ProfileGenerator;
using i::ProfileNode;
using i::ProfilerEventsProcessor;
+using i::ScopedVector;
using i::TokenEnumerator;
+using i::Vector;
TEST(StartStop) {
@@ -391,3 +394,145 @@
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));
+}
--
--
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.
