v8/test/cctest/test-cpu-profiler.cc
yurys@chromium.org c7ce87f865 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

git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@14205 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
2013-04-10 09:47:44 +00:00

539 lines
19 KiB
C++

// Copyright 2010 the V8 project authors. All rights reserved.
// Redistribution and use in source and binary forms, with or without
// modification, are permitted provided that the following conditions are
// met:
//
// * Redistributions of source code must retain the above copyright
// notice, this list of conditions and the following disclaimer.
// * Redistributions in binary form must reproduce the above
// copyright notice, this list of conditions and the following
// disclaimer in the documentation and/or other materials provided
// with the distribution.
// * Neither the name of Google Inc. nor the names of its
// contributors may be used to endorse or promote products derived
// from this software without specific prior written permission.
//
// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
//
// Tests of profiles generator and utilities.
#include "v8.h"
#include "cpu-profiler-inl.h"
#include "cctest.h"
#include "utils.h"
#include "../include/v8-profiler.h"
using i::CodeEntry;
using i::CpuProfile;
using i::CpuProfiler;
using i::CpuProfilesCollection;
using i::ProfileGenerator;
using i::ProfileNode;
using i::ProfilerEventsProcessor;
using i::ScopedVector;
using i::TokenEnumerator;
using i::Vector;
TEST(StartStop) {
CpuProfilesCollection profiles;
ProfileGenerator generator(&profiles);
ProfilerEventsProcessor processor(&generator);
processor.Start();
processor.Stop();
processor.Join();
}
static inline i::Address ToAddress(int n) {
return reinterpret_cast<i::Address>(n);
}
static void EnqueueTickSampleEvent(ProfilerEventsProcessor* proc,
i::Address frame1,
i::Address frame2 = NULL,
i::Address frame3 = NULL) {
i::TickSample* sample = proc->TickSampleEvent();
sample->pc = frame1;
sample->tos = frame1;
sample->frames_count = 0;
if (frame2 != NULL) {
sample->stack[0] = frame2;
sample->frames_count = 1;
}
if (frame3 != NULL) {
sample->stack[1] = frame3;
sample->frames_count = 2;
}
}
namespace {
class TestSetup {
public:
TestSetup()
: old_flag_prof_browser_mode_(i::FLAG_prof_browser_mode) {
i::FLAG_prof_browser_mode = false;
}
~TestSetup() {
i::FLAG_prof_browser_mode = old_flag_prof_browser_mode_;
}
private:
bool old_flag_prof_browser_mode_;
};
} // namespace
TEST(CodeEvents) {
CcTest::InitializeVM();
i::Isolate* isolate = i::Isolate::Current();
i::Heap* heap = isolate->heap();
i::Factory* factory = isolate->factory();
TestSetup test_setup;
CpuProfilesCollection profiles;
profiles.StartProfiling("", 1, false);
ProfileGenerator generator(&profiles);
ProfilerEventsProcessor processor(&generator);
processor.Start();
// Enqueue code creation events.
i::HandleScope scope(isolate);
const char* aaa_str = "aaa";
i::Handle<i::String> aaa_name = factory->NewStringFromAscii(
i::Vector<const char>(aaa_str, i::StrLength(aaa_str)));
processor.CodeCreateEvent(i::Logger::FUNCTION_TAG,
*aaa_name,
heap->empty_string(),
0,
ToAddress(0x1000),
0x100,
ToAddress(0x10000));
processor.CodeCreateEvent(i::Logger::BUILTIN_TAG,
"bbb",
ToAddress(0x1200),
0x80);
processor.CodeCreateEvent(i::Logger::STUB_TAG, 5, ToAddress(0x1300), 0x10);
processor.CodeCreateEvent(i::Logger::BUILTIN_TAG,
"ddd",
ToAddress(0x1400),
0x80);
processor.CodeMoveEvent(ToAddress(0x1400), ToAddress(0x1500));
processor.CodeCreateEvent(i::Logger::STUB_TAG, 3, ToAddress(0x1600), 0x10);
processor.CodeCreateEvent(i::Logger::STUB_TAG, 4, ToAddress(0x1605), 0x10);
// Enqueue a tick event to enable code events processing.
EnqueueTickSampleEvent(&processor, ToAddress(0x1000));
processor.Stop();
processor.Join();
// Check the state of profile generator.
CodeEntry* entry1 = generator.code_map()->FindEntry(ToAddress(0x1000));
CHECK_NE(NULL, entry1);
CHECK_EQ(aaa_str, entry1->name());
CodeEntry* entry2 = generator.code_map()->FindEntry(ToAddress(0x1200));
CHECK_NE(NULL, entry2);
CHECK_EQ("bbb", entry2->name());
CodeEntry* entry3 = generator.code_map()->FindEntry(ToAddress(0x1300));
CHECK_NE(NULL, entry3);
CHECK_EQ("5", entry3->name());
CHECK_EQ(NULL, generator.code_map()->FindEntry(ToAddress(0x1400)));
CodeEntry* entry4 = generator.code_map()->FindEntry(ToAddress(0x1500));
CHECK_NE(NULL, entry4);
CHECK_EQ("ddd", entry4->name());
CHECK_EQ(NULL, generator.code_map()->FindEntry(ToAddress(0x1600)));
}
template<typename T>
static int CompareProfileNodes(const T* p1, const T* p2) {
return strcmp((*p1)->entry()->name(), (*p2)->entry()->name());
}
TEST(TickEvents) {
TestSetup test_setup;
CpuProfilesCollection profiles;
profiles.StartProfiling("", 1, false);
ProfileGenerator generator(&profiles);
ProfilerEventsProcessor processor(&generator);
processor.Start();
processor.CodeCreateEvent(i::Logger::BUILTIN_TAG,
"bbb",
ToAddress(0x1200),
0x80);
processor.CodeCreateEvent(i::Logger::STUB_TAG, 5, ToAddress(0x1300), 0x10);
processor.CodeCreateEvent(i::Logger::BUILTIN_TAG,
"ddd",
ToAddress(0x1400),
0x80);
EnqueueTickSampleEvent(&processor, ToAddress(0x1210));
EnqueueTickSampleEvent(&processor, ToAddress(0x1305), ToAddress(0x1220));
EnqueueTickSampleEvent(&processor,
ToAddress(0x1404),
ToAddress(0x1305),
ToAddress(0x1230));
processor.Stop();
processor.Join();
CpuProfile* profile =
profiles.StopProfiling(TokenEnumerator::kNoSecurityToken, "", 1);
CHECK_NE(NULL, profile);
// Check call trees.
const i::List<ProfileNode*>* top_down_root_children =
profile->top_down()->root()->children();
CHECK_EQ(1, top_down_root_children->length());
CHECK_EQ("bbb", top_down_root_children->last()->entry()->name());
const i::List<ProfileNode*>* top_down_bbb_children =
top_down_root_children->last()->children();
CHECK_EQ(1, top_down_bbb_children->length());
CHECK_EQ("5", top_down_bbb_children->last()->entry()->name());
const i::List<ProfileNode*>* top_down_stub_children =
top_down_bbb_children->last()->children();
CHECK_EQ(1, top_down_stub_children->length());
CHECK_EQ("ddd", top_down_stub_children->last()->entry()->name());
const i::List<ProfileNode*>* top_down_ddd_children =
top_down_stub_children->last()->children();
CHECK_EQ(0, top_down_ddd_children->length());
}
// http://crbug/51594
// This test must not crash.
TEST(CrashIfStoppingLastNonExistentProfile) {
CcTest::InitializeVM();
TestSetup test_setup;
CpuProfiler* profiler = i::Isolate::Current()->cpu_profiler();
profiler->StartProfiling("1");
profiler->StopProfiling("2");
profiler->StartProfiling("1");
profiler->StopProfiling("");
}
// http://code.google.com/p/v8/issues/detail?id=1398
// Long stacks (exceeding max frames limit) must not be erased.
TEST(Issue1398) {
TestSetup test_setup;
CpuProfilesCollection profiles;
profiles.StartProfiling("", 1, false);
ProfileGenerator generator(&profiles);
ProfilerEventsProcessor processor(&generator);
processor.Start();
processor.CodeCreateEvent(i::Logger::BUILTIN_TAG,
"bbb",
ToAddress(0x1200),
0x80);
i::TickSample* sample = processor.TickSampleEvent();
sample->pc = ToAddress(0x1200);
sample->tos = 0;
sample->frames_count = i::TickSample::kMaxFramesCount;
for (int i = 0; i < sample->frames_count; ++i) {
sample->stack[i] = ToAddress(0x1200);
}
processor.Stop();
processor.Join();
CpuProfile* profile =
profiles.StopProfiling(TokenEnumerator::kNoSecurityToken, "", 1);
CHECK_NE(NULL, profile);
int actual_depth = 0;
const ProfileNode* node = profile->top_down()->root();
while (node->children()->length() > 0) {
node = node->children()->last();
++actual_depth;
}
CHECK_EQ(1 + i::TickSample::kMaxFramesCount, actual_depth); // +1 for PC.
}
TEST(DeleteAllCpuProfiles) {
CcTest::InitializeVM();
TestSetup test_setup;
CpuProfiler* profiler = i::Isolate::Current()->cpu_profiler();
CHECK_EQ(0, profiler->GetProfilesCount());
profiler->DeleteAllProfiles();
CHECK_EQ(0, profiler->GetProfilesCount());
profiler->StartProfiling("1");
profiler->StopProfiling("1");
CHECK_EQ(1, profiler->GetProfilesCount());
profiler->DeleteAllProfiles();
CHECK_EQ(0, profiler->GetProfilesCount());
profiler->StartProfiling("1");
profiler->StartProfiling("2");
profiler->StopProfiling("2");
profiler->StopProfiling("1");
CHECK_EQ(2, profiler->GetProfilesCount());
profiler->DeleteAllProfiles();
CHECK_EQ(0, profiler->GetProfilesCount());
// Test profiling cancellation by the 'delete' command.
profiler->StartProfiling("1");
profiler->StartProfiling("2");
CHECK_EQ(0, profiler->GetProfilesCount());
profiler->DeleteAllProfiles();
CHECK_EQ(0, profiler->GetProfilesCount());
}
TEST(DeleteCpuProfile) {
LocalContext env;
v8::HandleScope scope(env->GetIsolate());
v8::CpuProfiler* cpu_profiler = env->GetIsolate()->GetCpuProfiler();
CHECK_EQ(0, cpu_profiler->GetProfileCount());
v8::Local<v8::String> name1 = v8::String::New("1");
cpu_profiler->StartCpuProfiling(name1);
const v8::CpuProfile* p1 = cpu_profiler->StopCpuProfiling(name1);
CHECK_NE(NULL, p1);
CHECK_EQ(1, cpu_profiler->GetProfileCount());
unsigned uid1 = p1->GetUid();
CHECK_EQ(p1, cpu_profiler->FindCpuProfile(uid1));
const_cast<v8::CpuProfile*>(p1)->Delete();
CHECK_EQ(0, cpu_profiler->GetProfileCount());
CHECK_EQ(NULL, cpu_profiler->FindCpuProfile(uid1));
v8::Local<v8::String> name2 = v8::String::New("2");
cpu_profiler->StartCpuProfiling(name2);
const v8::CpuProfile* p2 = cpu_profiler->StopCpuProfiling(name2);
CHECK_NE(NULL, p2);
CHECK_EQ(1, cpu_profiler->GetProfileCount());
unsigned uid2 = p2->GetUid();
CHECK_NE(static_cast<int>(uid1), static_cast<int>(uid2));
CHECK_EQ(p2, cpu_profiler->FindCpuProfile(uid2));
CHECK_EQ(NULL, cpu_profiler->FindCpuProfile(uid1));
v8::Local<v8::String> name3 = v8::String::New("3");
cpu_profiler->StartCpuProfiling(name3);
const v8::CpuProfile* p3 = cpu_profiler->StopCpuProfiling(name3);
CHECK_NE(NULL, p3);
CHECK_EQ(2, cpu_profiler->GetProfileCount());
unsigned uid3 = p3->GetUid();
CHECK_NE(static_cast<int>(uid1), static_cast<int>(uid3));
CHECK_EQ(p3, cpu_profiler->FindCpuProfile(uid3));
CHECK_EQ(NULL, cpu_profiler->FindCpuProfile(uid1));
const_cast<v8::CpuProfile*>(p2)->Delete();
CHECK_EQ(1, cpu_profiler->GetProfileCount());
CHECK_EQ(NULL, cpu_profiler->FindCpuProfile(uid2));
CHECK_EQ(p3, cpu_profiler->FindCpuProfile(uid3));
const_cast<v8::CpuProfile*>(p3)->Delete();
CHECK_EQ(0, cpu_profiler->GetProfileCount());
CHECK_EQ(NULL, cpu_profiler->FindCpuProfile(uid3));
CHECK_EQ(NULL, cpu_profiler->FindCpuProfile(uid2));
CHECK_EQ(NULL, cpu_profiler->FindCpuProfile(uid1));
}
TEST(DeleteCpuProfileDifferentTokens) {
LocalContext env;
v8::HandleScope scope(env->GetIsolate());
v8::CpuProfiler* cpu_profiler = env->GetIsolate()->GetCpuProfiler();
CHECK_EQ(0, cpu_profiler->GetProfileCount());
v8::Local<v8::String> name1 = v8::String::New("1");
cpu_profiler->StartCpuProfiling(name1);
const v8::CpuProfile* p1 = cpu_profiler->StopCpuProfiling(name1);
CHECK_NE(NULL, p1);
CHECK_EQ(1, cpu_profiler->GetProfileCount());
unsigned uid1 = p1->GetUid();
CHECK_EQ(p1, cpu_profiler->FindCpuProfile(uid1));
v8::Local<v8::String> token1 = v8::String::New("token1");
const v8::CpuProfile* p1_t1 = cpu_profiler->FindCpuProfile(uid1, token1);
CHECK_NE(NULL, p1_t1);
CHECK_NE(p1, p1_t1);
CHECK_EQ(1, cpu_profiler->GetProfileCount());
const_cast<v8::CpuProfile*>(p1)->Delete();
CHECK_EQ(0, cpu_profiler->GetProfileCount());
CHECK_EQ(NULL, cpu_profiler->FindCpuProfile(uid1));
CHECK_EQ(NULL, cpu_profiler->FindCpuProfile(uid1, token1));
const_cast<v8::CpuProfile*>(p1_t1)->Delete();
CHECK_EQ(0, cpu_profiler->GetProfileCount());
v8::Local<v8::String> name2 = v8::String::New("2");
cpu_profiler->StartCpuProfiling(name2);
v8::Local<v8::String> token2 = v8::String::New("token2");
const v8::CpuProfile* p2_t2 = cpu_profiler->StopCpuProfiling(name2, token2);
CHECK_NE(NULL, p2_t2);
CHECK_EQ(1, cpu_profiler->GetProfileCount());
unsigned uid2 = p2_t2->GetUid();
CHECK_NE(static_cast<int>(uid1), static_cast<int>(uid2));
const v8::CpuProfile* p2 = cpu_profiler->FindCpuProfile(uid2);
CHECK_NE(p2_t2, p2);
v8::Local<v8::String> name3 = v8::String::New("3");
cpu_profiler->StartCpuProfiling(name3);
const v8::CpuProfile* p3 = cpu_profiler->StopCpuProfiling(name3);
CHECK_NE(NULL, p3);
CHECK_EQ(2, cpu_profiler->GetProfileCount());
unsigned uid3 = p3->GetUid();
CHECK_NE(static_cast<int>(uid1), static_cast<int>(uid3));
CHECK_EQ(p3, cpu_profiler->FindCpuProfile(uid3));
const_cast<v8::CpuProfile*>(p2_t2)->Delete();
CHECK_EQ(1, cpu_profiler->GetProfileCount());
CHECK_EQ(NULL, cpu_profiler->FindCpuProfile(uid2));
CHECK_EQ(p3, cpu_profiler->FindCpuProfile(uid3));
const_cast<v8::CpuProfile*>(p2)->Delete();
CHECK_EQ(1, cpu_profiler->GetProfileCount());
CHECK_EQ(NULL, cpu_profiler->FindCpuProfile(uid2));
CHECK_EQ(p3, cpu_profiler->FindCpuProfile(uid3));
const_cast<v8::CpuProfile*>(p3)->Delete();
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));
}