Google Git
Sign in
cobalt / cobalt / c52866be1febb1c09c04df4cb93d87f3595f4dc1 / . / src / third_party / v8 / test / cctest / test-cpu-profiler.cc
blob: 1db0a7b4264ff37ee98ae022436f51861e67f61c [file] [log] [blame]
// 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 the CPU profiler and utilities.
#include <limits>
#include <memory>
#include "include/libplatform/v8-tracing.h"
#include "include/v8-profiler.h"
#include "src/api/api-inl.h"
#include "src/base/platform/platform.h"
#include "src/codegen/source-position-table.h"
#include "src/deoptimizer/deoptimizer.h"
#include "src/heap/spaces.h"
#include "src/init/v8.h"
#include "src/libplatform/default-platform.h"
#include "src/libplatform/tracing/trace-event-listener.h"
#include "src/libsampler/sampler.h"
#include "src/logging/log.h"
#include "src/objects/objects-inl.h"
#include "src/profiler/cpu-profiler-inl.h"
#include "src/profiler/profiler-listener.h"
#include "src/profiler/symbolizer.h"
#include "src/profiler/tracing-cpu-profiler.h"
#include "src/tracing/trace-event.h"
#include "src/utils/utils.h"
#include "test/cctest/cctest.h"
#include "test/cctest/heap/heap-utils.h"
#include "test/cctest/profiler-extension.h"
#ifdef V8_USE_PERFETTO
#include "protos/perfetto/trace/trace.pb.h"
#endif
namespace v8 {
namespace internal {
namespace test_cpu_profiler {
// Helper methods
static v8::Local<v8::Function> GetFunction(v8::Local<v8::Context> env,
const char* name) {
return v8::Local<v8::Function>::Cast(
env->Global()->Get(env, v8_str(name)).ToLocalChecked());
}
static size_t offset(const char* src, const char* substring) {
const char* it = strstr(src, substring);
CHECK(it);
return static_cast<size_t>(it - src);
}
template <typename A, typename B>
static int dist(A a, B b) {
return abs(static_cast<int>(a) - static_cast<int>(b));
}
static const char* reason(const i::DeoptimizeReason reason) {
return i::DeoptimizeReasonToString(reason);
}
TEST(StartStop) {
i::Isolate* isolate = CcTest::i_isolate();
CpuProfilesCollection profiles(isolate);
ProfilerCodeObserver code_observer(isolate);
Symbolizer symbolizer(code_observer.code_map());
std::unique_ptr<ProfilerEventsProcessor> processor(
new SamplingEventsProcessor(
isolate, &symbolizer, &code_observer, &profiles,
v8::base::TimeDelta::FromMicroseconds(100), true));
CHECK(processor->Start());
processor->StopSynchronously();
}
static void EnqueueTickSampleEvent(ProfilerEventsProcessor* proc,
i::Address frame1,
i::Address frame2 = kNullAddress,
i::Address frame3 = kNullAddress) {
v8::internal::TickSample sample;
sample.pc = reinterpret_cast<void*>(frame1);
sample.tos = reinterpret_cast<void*>(frame1);
sample.frames_count = 0;
if (frame2 != kNullAddress) {
sample.stack[0] = reinterpret_cast<void*>(frame2);
sample.frames_count = 1;
}
if (frame3 != kNullAddress) {
sample.stack[1] = reinterpret_cast<void*>(frame3);
sample.frames_count = 2;
}
sample.timestamp = base::TimeTicks::HighResolutionNow();
proc->AddSample(sample);
}
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
i::AbstractCode CreateCode(LocalContext* env) {
static int counter = 0;
i::EmbeddedVector<char, 256> script;
i::EmbeddedVector<char, 32> name;
i::SNPrintF(name, "function_%d", ++counter);
const char* name_start = name.begin();
i::SNPrintF(script,
"function %s() {\n"
"var counter = 0;\n"
"for (var i = 0; i < %d; ++i) counter += i;\n"
"return '%s_' + counter;\n"
"}\n"
"%s();\n",
name_start, counter, name_start, name_start);
CompileRun(script.begin());
i::Handle<i::JSFunction> fun = i::Handle<i::JSFunction>::cast(
v8::Utils::OpenHandle(*GetFunction(env->local(), name_start)));
return fun->abstract_code();
}
TEST(CodeEvents) {
CcTest::InitializeVM();
LocalContext env;
i::Isolate* isolate = CcTest::i_isolate();
i::Factory* factory = isolate->factory();
TestSetup test_setup;
i::HandleScope scope(isolate);
i::Handle<i::AbstractCode> aaa_code(CreateCode(&env), isolate);
i::Handle<i::AbstractCode> comment_code(CreateCode(&env), isolate);
i::Handle<i::AbstractCode> comment2_code(CreateCode(&env), isolate);
i::Handle<i::AbstractCode> moved_code(CreateCode(&env), isolate);
CpuProfilesCollection* profiles = new CpuProfilesCollection(isolate);
ProfilerCodeObserver code_observer(isolate);
Symbolizer* symbolizer = new Symbolizer(code_observer.code_map());
ProfilerEventsProcessor* processor = new SamplingEventsProcessor(
isolate, symbolizer, &code_observer, profiles,
v8::base::TimeDelta::FromMicroseconds(100), true);
CHECK(processor->Start());
ProfilerListener profiler_listener(isolate, processor);
isolate->logger()->AddCodeEventListener(&profiler_listener);
// Enqueue code creation events.
const char* aaa_str = "aaa";
i::Handle<i::String> aaa_name = factory->NewStringFromAsciiChecked(aaa_str);
profiler_listener.CodeCreateEvent(i::Logger::FUNCTION_TAG, aaa_code,
aaa_name);
profiler_listener.CodeCreateEvent(i::Logger::BUILTIN_TAG, comment_code,
"comment");
profiler_listener.CodeCreateEvent(i::Logger::BUILTIN_TAG, comment2_code,
"comment2");
profiler_listener.CodeMoveEvent(*comment2_code, *moved_code);
// Enqueue a tick event to enable code events processing.
EnqueueTickSampleEvent(processor, aaa_code->InstructionStart());
isolate->logger()->RemoveCodeEventListener(&profiler_listener);
processor->StopSynchronously();
// Check the state of the symbolizer.
CodeEntry* aaa =
symbolizer->code_map()->FindEntry(aaa_code->InstructionStart());
CHECK(aaa);
CHECK_EQ(0, strcmp(aaa_str, aaa->name()));
CodeEntry* comment =
symbolizer->code_map()->FindEntry(comment_code->InstructionStart());
CHECK(comment);
CHECK_EQ(0, strcmp("comment", comment->name()));
CHECK(!symbolizer->code_map()->FindEntry(comment2_code->InstructionStart()));
CodeEntry* comment2 =
symbolizer->code_map()->FindEntry(moved_code->InstructionStart());
CHECK(comment2);
CHECK_EQ(0, strcmp("comment2", comment2->name()));
}
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;
LocalContext env;
i::Isolate* isolate = CcTest::i_isolate();
i::HandleScope scope(isolate);
i::Handle<i::AbstractCode> frame1_code(CreateCode(&env), isolate);
i::Handle<i::AbstractCode> frame2_code(CreateCode(&env), isolate);
i::Handle<i::AbstractCode> frame3_code(CreateCode(&env), isolate);
CpuProfilesCollection* profiles = new CpuProfilesCollection(isolate);
ProfilerCodeObserver code_observer(isolate);
Symbolizer* symbolizer = new Symbolizer(code_observer.code_map());
ProfilerEventsProcessor* processor = new SamplingEventsProcessor(
CcTest::i_isolate(), symbolizer, &code_observer, profiles,
v8::base::TimeDelta::FromMicroseconds(100), true);
CpuProfiler profiler(isolate, kDebugNaming, kLazyLogging, profiles,
symbolizer, processor);
profiles->StartProfiling("");
CHECK(processor->Start());
ProfilerListener profiler_listener(isolate, processor);
isolate->logger()->AddCodeEventListener(&profiler_listener);
profiler_listener.CodeCreateEvent(i::Logger::BUILTIN_TAG, frame1_code, "bbb");
profiler_listener.CodeCreateEvent(i::Logger::STUB_TAG, frame2_code, "ccc");
profiler_listener.CodeCreateEvent(i::Logger::BUILTIN_TAG, frame3_code, "ddd");
EnqueueTickSampleEvent(processor, frame1_code->raw_instruction_start());
EnqueueTickSampleEvent(processor,
frame2_code->raw_instruction_start() +
frame2_code->raw_instruction_size() / 2,
frame1_code->raw_instruction_start() +
frame1_code->raw_instruction_size() / 2);
EnqueueTickSampleEvent(processor, frame3_code->raw_instruction_end() - 1,
frame2_code->raw_instruction_end() - 1,
frame1_code->raw_instruction_end() - 1);
isolate->logger()->RemoveCodeEventListener(&profiler_listener);
processor->StopSynchronously();
CpuProfile* profile = profiles->StopProfiling("");
CHECK(profile);
// Check call trees.
const std::vector<ProfileNode*>* top_down_root_children =
profile->top_down()->root()->children();
CHECK_EQ(1, top_down_root_children->size());
CHECK_EQ(0, strcmp("bbb", top_down_root_children->back()->entry()->name()));
const std::vector<ProfileNode*>* top_down_bbb_children =
top_down_root_children->back()->children();
CHECK_EQ(1, top_down_bbb_children->size());
CHECK_EQ(0, strcmp("ccc", top_down_bbb_children->back()->entry()->name()));
const std::vector<ProfileNode*>* top_down_stub_children =
top_down_bbb_children->back()->children();
CHECK_EQ(1, top_down_stub_children->size());
CHECK_EQ(0, strcmp("ddd", top_down_stub_children->back()->entry()->name()));
const std::vector<ProfileNode*>* top_down_ddd_children =
top_down_stub_children->back()->children();
CHECK(top_down_ddd_children->empty());
}
TEST(CodeMapClearedBetweenProfilesWithLazyLogging) {
TestSetup test_setup;
LocalContext env;
i::Isolate* isolate = CcTest::i_isolate();
i::HandleScope scope(isolate);
// This gets logged when the profiler starts up and scans the heap.
i::Handle<i::AbstractCode> code1(CreateCode(&env), isolate);
CpuProfiler profiler(isolate, kDebugNaming, kLazyLogging);
profiler.StartProfiling("");
CpuProfile* profile = profiler.StopProfiling("");
CHECK(profile);
// Check that our code is still in the code map.
CodeMap* code_map = profiler.code_map_for_test();
CodeEntry* code1_entry = code_map->FindEntry(code1->InstructionStart());
CHECK(code1_entry);
CHECK_EQ(0, strcmp("function_1", code1_entry->name()));
profiler.DeleteProfile(profile);
// Check that the code map is emptied once the last profile is deleted.
CHECK(!code_map->FindEntry(code1->InstructionStart()));
// Create code between profiles. This should not be logged yet.
i::Handle<i::AbstractCode> code2(CreateCode(&env), isolate);
CHECK(!code_map->FindEntry(code2->InstructionStart()));
}
TEST(CodeMapNotClearedBetweenProfilesWithEagerLogging) {
TestSetup test_setup;
LocalContext env;
i::Isolate* isolate = CcTest::i_isolate();
i::HandleScope scope(isolate);
// This gets logged when the profiler starts up and scans the heap.
i::Handle<i::AbstractCode> code1(CreateCode(&env), isolate);
CpuProfiler profiler(isolate, kDebugNaming, kEagerLogging);
profiler.StartProfiling("");
CpuProfile* profile = profiler.StopProfiling("");
CHECK(profile);
// Check that our code is still in the code map.
CodeMap* code_map = profiler.code_map_for_test();
CodeEntry* code1_entry = code_map->FindEntry(code1->InstructionStart());
CHECK(code1_entry);
CHECK_EQ(0, strcmp("function_1", code1_entry->name()));
profiler.DeleteProfile(profile);
// We should still have an entry in kEagerLogging mode.
code1_entry = code_map->FindEntry(code1->InstructionStart());
CHECK(code1_entry);
CHECK_EQ(0, strcmp("function_1", code1_entry->name()));
// Create code between profiles. This should be logged too.
i::Handle<i::AbstractCode> code2(CreateCode(&env), isolate);
CHECK(code_map->FindEntry(code2->InstructionStart()));
profiler.StartProfiling("");
CpuProfile* profile2 = profiler.StopProfiling("");
CHECK(profile2);
// Check that we still have code map entries for both code objects.
code1_entry = code_map->FindEntry(code1->InstructionStart());
CHECK(code1_entry);
CHECK_EQ(0, strcmp("function_1", code1_entry->name()));
CodeEntry* code2_entry = code_map->FindEntry(code2->InstructionStart());
CHECK(code2_entry);
CHECK_EQ(0, strcmp("function_2", code2_entry->name()));
profiler.DeleteProfile(profile2);
// Check that we still have code map entries for both code objects, even after
// the last profile is deleted.
code1_entry = code_map->FindEntry(code1->InstructionStart());
CHECK(code1_entry);
CHECK_EQ(0, strcmp("function_1", code1_entry->name()));
code2_entry = code_map->FindEntry(code2->InstructionStart());
CHECK(code2_entry);
CHECK_EQ(0, strcmp("function_2", code2_entry->name()));
}
// http://crbug/51594
// This test must not crash.
TEST(CrashIfStoppingLastNonExistentProfile) {
CcTest::InitializeVM();
TestSetup test_setup;
std::unique_ptr<CpuProfiler> profiler(new CpuProfiler(CcTest::i_isolate()));
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;
LocalContext env;
i::Isolate* isolate = CcTest::i_isolate();
i::HandleScope scope(isolate);
i::Handle<i::AbstractCode> code(CreateCode(&env), isolate);
CpuProfilesCollection* profiles = new CpuProfilesCollection(isolate);
ProfilerCodeObserver code_observer(isolate);
Symbolizer* symbolizer = new Symbolizer(code_observer.code_map());
ProfilerEventsProcessor* processor = new SamplingEventsProcessor(
CcTest::i_isolate(), symbolizer, &code_observer, profiles,
v8::base::TimeDelta::FromMicroseconds(100), true);
CpuProfiler profiler(isolate, kDebugNaming, kLazyLogging, profiles,
symbolizer, processor);
profiles->StartProfiling("");
CHECK(processor->Start());
ProfilerListener profiler_listener(isolate, processor);
profiler_listener.CodeCreateEvent(i::Logger::BUILTIN_TAG, code, "bbb");
v8::internal::TickSample sample;
sample.pc = reinterpret_cast<void*>(code->InstructionStart());
sample.tos = nullptr;
sample.frames_count = TickSample::kMaxFramesCount;
for (unsigned i = 0; i < sample.frames_count; ++i) {
sample.stack[i] = reinterpret_cast<void*>(code->InstructionStart());
}
sample.timestamp = base::TimeTicks::HighResolutionNow();
processor->AddSample(sample);
processor->StopSynchronously();
CpuProfile* profile = profiles->StopProfiling("");
CHECK(profile);
unsigned actual_depth = 0;
const ProfileNode* node = profile->top_down()->root();
while (!node->children()->empty()) {
node = node->children()->back();
++actual_depth;
}
CHECK_EQ(1 + TickSample::kMaxFramesCount, actual_depth); // +1 for PC.
}
TEST(DeleteAllCpuProfiles) {
CcTest::InitializeVM();
TestSetup test_setup;
std::unique_ptr<CpuProfiler> profiler(new CpuProfiler(CcTest::i_isolate()));
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());
}
static bool FindCpuProfile(v8::CpuProfiler* v8profiler,
const v8::CpuProfile* v8profile) {
i::CpuProfiler* profiler = reinterpret_cast<i::CpuProfiler*>(v8profiler);
const i::CpuProfile* profile =
reinterpret_cast<const i::CpuProfile*>(v8profile);
int length = profiler->GetProfilesCount();
for (int i = 0; i < length; i++) {
if (profile == profiler->GetProfile(i)) return true;
}
return false;
}
TEST(DeleteCpuProfile) {
LocalContext env;
v8::HandleScope scope(env->GetIsolate());
v8::CpuProfiler* cpu_profiler = v8::CpuProfiler::New(env->GetIsolate());
i::CpuProfiler* iprofiler = reinterpret_cast<i::CpuProfiler*>(cpu_profiler);
CHECK_EQ(0, iprofiler->GetProfilesCount());
v8::Local<v8::String> name1 = v8_str("1");
cpu_profiler->StartProfiling(name1);
v8::CpuProfile* p1 = cpu_profiler->StopProfiling(name1);
CHECK(p1);
CHECK_EQ(1, iprofiler->GetProfilesCount());
CHECK(FindCpuProfile(cpu_profiler, p1));
p1->Delete();
CHECK_EQ(0, iprofiler->GetProfilesCount());
v8::Local<v8::String> name2 = v8_str("2");
cpu_profiler->StartProfiling(name2);
v8::CpuProfile* p2 = cpu_profiler->StopProfiling(name2);
CHECK(p2);
CHECK_EQ(1, iprofiler->GetProfilesCount());
CHECK(FindCpuProfile(cpu_profiler, p2));
v8::Local<v8::String> name3 = v8_str("3");
cpu_profiler->StartProfiling(name3);
v8::CpuProfile* p3 = cpu_profiler->StopProfiling(name3);
CHECK(p3);
CHECK_EQ(2, iprofiler->GetProfilesCount());
CHECK_NE(p2, p3);
CHECK(FindCpuProfile(cpu_profiler, p3));
CHECK(FindCpuProfile(cpu_profiler, p2));
p2->Delete();
CHECK_EQ(1, iprofiler->GetProfilesCount());
CHECK(!FindCpuProfile(cpu_profiler, p2));
CHECK(FindCpuProfile(cpu_profiler, p3));
p3->Delete();
CHECK_EQ(0, iprofiler->GetProfilesCount());
cpu_profiler->Dispose();
}
TEST(ProfileStartEndTime) {
LocalContext env;
v8::HandleScope scope(env->GetIsolate());
v8::CpuProfiler* cpu_profiler = v8::CpuProfiler::New(env->GetIsolate());
v8::Local<v8::String> profile_name = v8_str("test");
cpu_profiler->StartProfiling(profile_name);
const v8::CpuProfile* profile = cpu_profiler->StopProfiling(profile_name);
CHECK(profile->GetStartTime() <= profile->GetEndTime());
cpu_profiler->Dispose();
}
class ProfilerHelper {
public:
explicit ProfilerHelper(const v8::Local<v8::Context>& context)
: context_(context),
profiler_(v8::CpuProfiler::New(context->GetIsolate())) {
i::ProfilerExtension::set_profiler(profiler_);
}
~ProfilerHelper() {
i::ProfilerExtension::set_profiler(static_cast<CpuProfiler*>(nullptr));
profiler_->Dispose();
}
using ProfilingMode = v8::CpuProfilingMode;
v8::CpuProfile* Run(
v8::Local<v8::Function> function, v8::Local<v8::Value> argv[], int argc,
unsigned min_js_samples = 0, unsigned min_external_samples = 0,
ProfilingMode mode = ProfilingMode::kLeafNodeLineNumbers,
unsigned max_samples = v8::CpuProfilingOptions::kNoSampleLimit);
v8::CpuProfiler* profiler() { return profiler_; }
private:
v8::Local<v8::Context> context_;
v8::CpuProfiler* profiler_;
};
v8::CpuProfile* ProfilerHelper::Run(v8::Local<v8::Function> function,
v8::Local<v8::Value> argv[], int argc,
unsigned min_js_samples,
unsigned min_external_samples,
ProfilingMode mode, unsigned max_samples) {
v8::Local<v8::String> profile_name = v8_str("my_profile");
profiler_->SetSamplingInterval(100);
profiler_->StartProfiling(profile_name, {mode, max_samples, 0});
v8::internal::CpuProfiler* iprofiler =
reinterpret_cast<v8::internal::CpuProfiler*>(profiler_);
v8::sampler::Sampler* sampler =
reinterpret_cast<i::SamplingEventsProcessor*>(iprofiler->processor())
->sampler();
sampler->StartCountingSamples();
do {
function->Call(context_, context_->Global(), argc, argv).ToLocalChecked();
} while (sampler->js_sample_count() < min_js_samples ||
sampler->external_sample_count() < min_external_samples);
v8::CpuProfile* profile = profiler_->StopProfiling(profile_name);
CHECK(profile);
// Dump collected profile to have a better diagnostic in case of failure.
reinterpret_cast<i::CpuProfile*>(profile)->Print();
return profile;
}
static unsigned TotalHitCount(const v8::CpuProfileNode* node) {
unsigned hit_count = node->GetHitCount();
for (int i = 0, count = node->GetChildrenCount(); i < count; ++i)
hit_count += TotalHitCount(node->GetChild(i));
return hit_count;
}
static const v8::CpuProfileNode* FindChild(v8::Local<v8::Context> context,
const v8::CpuProfileNode* node,
const char* name) {
int count = node->GetChildrenCount();
v8::Local<v8::String> name_handle = v8_str(name);
for (int i = 0; i < count; i++) {
const v8::CpuProfileNode* child = node->GetChild(i);
if (name_handle->Equals(context, child->GetFunctionName()).FromJust()) {
return child;
}
}
return nullptr;
}
static const v8::CpuProfileNode* FindChild(const v8::CpuProfileNode* node,
const char* name) {
for (int i = 0, count = node->GetChildrenCount(); i < count; ++i) {
const v8::CpuProfileNode* child = node->GetChild(i);
if (strcmp(child->GetFunctionNameStr(), name) == 0) {
return child;
}
}
return nullptr;
}
static const v8::CpuProfileNode* GetChild(v8::Local<v8::Context> context,
const v8::CpuProfileNode* node,
const char* name) {
const v8::CpuProfileNode* result = FindChild(context, node, name);
if (!result) FATAL("Failed to GetChild: %s", name);
return result;
}
static void CheckSimpleBranch(v8::Local<v8::Context> context,
const v8::CpuProfileNode* node,
const char* names[], int length) {
for (int i = 0; i < length; i++) {
const char* name = names[i];
node = GetChild(context, node, name);
}
}
static const ProfileNode* GetSimpleBranch(v8::Local<v8::Context> context,
v8::CpuProfile* profile,
const char* names[], int length) {
const v8::CpuProfileNode* node = profile->GetTopDownRoot();
for (int i = 0; i < length; i++) {
node = GetChild(context, node, names[i]);
}
return reinterpret_cast<const ProfileNode*>(node);
}
struct NameLinePair {
const char* name;
int line_number;
};
static const v8::CpuProfileNode* FindChild(const v8::CpuProfileNode* node,
NameLinePair pair) {
for (int i = 0, count = node->GetChildrenCount(); i < count; ++i) {
const v8::CpuProfileNode* child = node->GetChild(i);
// The name and line number must match, or if the requested line number was
// -1, then match any function of the same name.
if (strcmp(child->GetFunctionNameStr(), pair.name) == 0 &&
(child->GetLineNumber() == pair.line_number ||
pair.line_number == -1)) {
return child;
}
}
return nullptr;
}
static const v8::CpuProfileNode* GetChild(const v8::CpuProfileNode* node,
NameLinePair pair) {
const v8::CpuProfileNode* result = FindChild(node, pair);
if (!result) FATAL("Failed to GetChild: %s:%d", pair.name, pair.line_number);
return result;
}
static void CheckBranch(const v8::CpuProfileNode* node, NameLinePair path[],
int length) {
for (int i = 0; i < length; i++) {
NameLinePair pair = path[i];
node = GetChild(node, pair);
}
}
static const char* cpu_profiler_test_source =
"%NeverOptimizeFunction(loop);\n"
"%NeverOptimizeFunction(delay);\n"
"%NeverOptimizeFunction(bar);\n"
"%NeverOptimizeFunction(baz);\n"
"%NeverOptimizeFunction(foo);\n"
"%NeverOptimizeFunction(start);\n"
"function loop(timeout) {\n"
" this.mmm = 0;\n"
" var start = Date.now();\n"
" do {\n"
" var n = 1000;\n"
" while(n > 1) {\n"
" n--;\n"
" this.mmm += n * n * n;\n"
" }\n"
" } while (Date.now() - start < timeout);\n"
"}\n"
"function delay() { loop(10); }\n"
"function bar() { delay(); }\n"
"function baz() { delay(); }\n"
"function foo() {\n"
" delay();\n"
" bar();\n"
" delay();\n"
" baz();\n"
"}\n"
"function start(duration) {\n"
" var start = Date.now();\n"
" do {\n"
" foo();\n"
" } while (Date.now() - start < 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) {
i::FLAG_allow_natives_syntax = true;
LocalContext env;
v8::HandleScope scope(env->GetIsolate());
CompileRun(cpu_profiler_test_source);
v8::Local<v8::Function> function = GetFunction(env.local(), "start");
int32_t profiling_interval_ms = 200;
v8::Local<v8::Value> args[] = {
v8::Integer::New(env->GetIsolate(), profiling_interval_ms)};
ProfilerHelper helper(env.local());
v8::CpuProfile* profile = helper.Run(function, args, arraysize(args), 1000);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env.local(), root, "start");
const v8::CpuProfileNode* foo_node = GetChild(env.local(), start_node, "foo");
const char* bar_branch[] = {"bar", "delay", "loop"};
CheckSimpleBranch(env.local(), foo_node, bar_branch, arraysize(bar_branch));
const char* baz_branch[] = {"baz", "delay", "loop"};
CheckSimpleBranch(env.local(), foo_node, baz_branch, arraysize(baz_branch));
const char* delay_branch[] = {"delay", "loop"};
CheckSimpleBranch(env.local(), foo_node, delay_branch,
arraysize(delay_branch));
profile->Delete();
}
TEST(CollectCpuProfileCallerLineNumbers) {
i::FLAG_allow_natives_syntax = true;
LocalContext env;
v8::HandleScope scope(env->GetIsolate());
CompileRun(cpu_profiler_test_source);
v8::Local<v8::Function> function = GetFunction(env.local(), "start");
int32_t profiling_interval_ms = 200;
v8::Local<v8::Value> args[] = {
v8::Integer::New(env->GetIsolate(), profiling_interval_ms)};
ProfilerHelper helper(env.local());
helper.Run(function, args, arraysize(args), 1000, 0,
v8::CpuProfilingMode::kCallerLineNumbers, 0);
v8::CpuProfile* profile =
helper.Run(function, args, arraysize(args), 1000, 0,
v8::CpuProfilingMode::kCallerLineNumbers, 0);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(root, {"start", 27});
const v8::CpuProfileNode* foo_node = GetChild(start_node, {"foo", 30});
NameLinePair bar_branch[] = {{"bar", 23}, {"delay", 19}, {"loop", 18}};
CheckBranch(foo_node, bar_branch, arraysize(bar_branch));
NameLinePair baz_branch[] = {{"baz", 25}, {"delay", 20}, {"loop", 18}};
CheckBranch(foo_node, baz_branch, arraysize(baz_branch));
NameLinePair delay_at22_branch[] = {{"delay", 22}, {"loop", 18}};
CheckBranch(foo_node, delay_at22_branch, arraysize(delay_at22_branch));
NameLinePair delay_at24_branch[] = {{"delay", 24}, {"loop", 18}};
CheckBranch(foo_node, delay_at24_branch, arraysize(delay_at24_branch));
profile->Delete();
}
static const char* hot_deopt_no_frame_entry_test_source =
"%NeverOptimizeFunction(foo);\n"
"%NeverOptimizeFunction(start);\n"
"function foo(a, b) {\n"
" return a + b;\n"
"}\n"
"function start(timeout) {\n"
" var start = Date.now();\n"
" do {\n"
" for (var i = 1; i < 1000; ++i) foo(1, i);\n"
" var duration = Date.now() - start;\n"
" } while (duration < timeout);\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]
// 2 2 (program) [-1]
// 6 6 (garbage collector) [-1]
//
// The test checks no FP ranges are present in a deoptimized function.
// If 'foo' has no ranges the samples falling into the prologue will miss the
// 'start' function on the stack, so 'foo' will be attached to the (root).
TEST(HotDeoptNoFrameEntry) {
i::FLAG_allow_natives_syntax = true;
LocalContext env;
v8::HandleScope scope(env->GetIsolate());
CompileRun(hot_deopt_no_frame_entry_test_source);
v8::Local<v8::Function> function = GetFunction(env.local(), "start");
int32_t profiling_interval_ms = 200;
v8::Local<v8::Value> args[] = {
v8::Integer::New(env->GetIsolate(), profiling_interval_ms)};
ProfilerHelper helper(env.local());
v8::CpuProfile* profile = helper.Run(function, args, arraysize(args), 1000);
function->Call(env.local(), env->Global(), arraysize(args), args)
.ToLocalChecked();
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env.local(), root, "start");
GetChild(env.local(), start_node, "foo");
profile->Delete();
}
TEST(CollectCpuProfileSamples) {
i::FLAG_allow_natives_syntax = true;
LocalContext env;
v8::HandleScope scope(env->GetIsolate());
CompileRun(cpu_profiler_test_source);
v8::Local<v8::Function> function = GetFunction(env.local(), "start");
int32_t profiling_interval_ms = 200;
v8::Local<v8::Value> args[] = {
v8::Integer::New(env->GetIsolate(), profiling_interval_ms)};
ProfilerHelper helper(env.local());
v8::CpuProfile* profile =
helper.Run(function, args, arraysize(args), 1000, 0);
CHECK_LE(200, profile->GetSamplesCount());
uint64_t end_time = profile->GetEndTime();
uint64_t current_time = profile->GetStartTime();
CHECK_LE(current_time, end_time);
for (int i = 0; i < profile->GetSamplesCount(); i++) {
CHECK(profile->GetSample(i));
uint64_t timestamp = profile->GetSampleTimestamp(i);
CHECK_LE(current_time, timestamp);
CHECK_LE(timestamp, end_time);
current_time = timestamp;
}
profile->Delete();
}
static const char* cpu_profiler_test_source2 =
"%NeverOptimizeFunction(loop);\n"
"%NeverOptimizeFunction(delay);\n"
"%NeverOptimizeFunction(start);\n"
"function loop() {}\n"
"function delay() { loop(); }\n"
"function start(duration) {\n"
" var start = Date.now();\n"
" do {\n"
" for (var i = 0; i < 10000; ++i) delay();\n"
" } while (Date.now() - start < duration);\n"
"}";
// Check that the profile tree doesn't contain unexpected traces:
// - 'loop' can be called only by 'delay'
// - 'delay' may be called only by 'start'
// The profile will look like the following:
//
// [Top down]:
// 135 0 (root) [-1] #1
// 121 72 start [-1] #3
// 49 33 delay [-1] #4
// 16 16 loop [-1] #5
// 14 14 (program) [-1] #2
TEST(SampleWhenFrameIsNotSetup) {
i::FLAG_allow_natives_syntax = true;
LocalContext env;
v8::HandleScope scope(env->GetIsolate());
CompileRun(cpu_profiler_test_source2);
v8::Local<v8::Function> function = GetFunction(env.local(), "start");
int32_t duration_ms = 100;
v8::Local<v8::Value> args[] = {
v8::Integer::New(env->GetIsolate(), duration_ms)};
ProfilerHelper helper(env.local());
v8::CpuProfile* profile = helper.Run(function, args, arraysize(args), 1000);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env.local(), root, "start");
const v8::CpuProfileNode* delay_node =
GetChild(env.local(), start_node, "delay");
GetChild(env.local(), delay_node, "loop");
profile->Delete();
}
static const char* native_accessor_test_source =
"function start(count) {\n"
" for (var i = 0; i < count; i++) {\n"
" var o = instance.foo;\n"
" instance.foo = o + 1;\n"
" }\n"
"}\n";
class TestApiCallbacks {
public:
explicit TestApiCallbacks(int min_duration_ms)
: min_duration_ms_(min_duration_ms), is_warming_up_(false) {}
static void Getter(v8::Local<v8::String> name,
const v8::PropertyCallbackInfo<v8::Value>& info) {
TestApiCallbacks* data = FromInfo(info);
data->Wait();
}
static void Setter(v8::Local<v8::String> name, v8::Local<v8::Value> value,
const v8::PropertyCallbackInfo<void>& info) {
TestApiCallbacks* data = FromInfo(info);
data->Wait();
}
static void Callback(const v8::FunctionCallbackInfo<v8::Value>& info) {
TestApiCallbacks* data = FromInfo(info);
data->Wait();
}
void set_warming_up(bool value) { is_warming_up_ = value; }
private:
void Wait() {
if (is_warming_up_) return;
v8::Platform* platform = v8::internal::V8::GetCurrentPlatform();
double start = platform->CurrentClockTimeMillis();
double duration = 0;
while (duration < min_duration_ms_) {
v8::base::OS::Sleep(v8::base::TimeDelta::FromMilliseconds(1));
duration = platform->CurrentClockTimeMillis() - start;
}
}
template <typename T>
static TestApiCallbacks* FromInfo(const T& info) {
void* data = v8::External::Cast(*info.Data())->Value();
return reinterpret_cast<TestApiCallbacks*>(data);
}
int min_duration_ms_;
bool is_warming_up_;
};
// Test that native accessors are properly reported in the CPU profile.
// This test checks the case when the long-running accessors are called
// only once and the optimizer doesn't have chance to change the invocation
// code.
TEST(NativeAccessorUninitializedIC) {
LocalContext env;
v8::Isolate* isolate = env->GetIsolate();
v8::HandleScope scope(isolate);
v8::Local<v8::FunctionTemplate> func_template =
v8::FunctionTemplate::New(isolate);
v8::Local<v8::ObjectTemplate> instance_template =
func_template->InstanceTemplate();
TestApiCallbacks accessors(100);
v8::Local<v8::External> data = v8::External::New(isolate, &accessors);
instance_template->SetAccessor(v8_str("foo"), &TestApiCallbacks::Getter,
&TestApiCallbacks::Setter, data);
v8::Local<v8::Function> func =
func_template->GetFunction(env.local()).ToLocalChecked();
v8::Local<v8::Object> instance =
func->NewInstance(env.local()).ToLocalChecked();
env->Global()->Set(env.local(), v8_str("instance"), instance).FromJust();
CompileRun(native_accessor_test_source);
v8::Local<v8::Function> function = GetFunction(env.local(), "start");
ProfilerHelper helper(env.local());
int32_t repeat_count = 1;
v8::Local<v8::Value> args[] = {v8::Integer::New(isolate, repeat_count)};
v8::CpuProfile* profile = helper.Run(function, args, arraysize(args), 0, 100);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env.local(), root, "start");
GetChild(env.local(), start_node, "get foo");
GetChild(env.local(), start_node, "set foo");
profile->Delete();
}
// Test that native accessors are properly reported in the CPU profile.
// This test makes sure that the accessors are called enough times to become
// hot and to trigger optimizations.
TEST(NativeAccessorMonomorphicIC) {
LocalContext env;
v8::Isolate* isolate = env->GetIsolate();
v8::HandleScope scope(isolate);
v8::Local<v8::FunctionTemplate> func_template =
v8::FunctionTemplate::New(isolate);
v8::Local<v8::ObjectTemplate> instance_template =
func_template->InstanceTemplate();
TestApiCallbacks accessors(1);
v8::Local<v8::External> data = v8::External::New(isolate, &accessors);
instance_template->SetAccessor(v8_str("foo"), &TestApiCallbacks::Getter,
&TestApiCallbacks::Setter, data);
v8::Local<v8::Function> func =
func_template->GetFunction(env.local()).ToLocalChecked();
v8::Local<v8::Object> instance =
func->NewInstance(env.local()).ToLocalChecked();
env->Global()->Set(env.local(), v8_str("instance"), instance).FromJust();
CompileRun(native_accessor_test_source);
v8::Local<v8::Function> function = GetFunction(env.local(), "start");
{
// Make sure accessors ICs are in monomorphic state before starting
// profiling.
accessors.set_warming_up(true);
int32_t warm_up_iterations = 3;
v8::Local<v8::Value> args[] = {
v8::Integer::New(isolate, warm_up_iterations)};
function->Call(env.local(), env->Global(), arraysize(args), args)
.ToLocalChecked();
accessors.set_warming_up(false);
}
int32_t repeat_count = 100;
v8::Local<v8::Value> args[] = {v8::Integer::New(isolate, repeat_count)};
ProfilerHelper helper(env.local());
v8::CpuProfile* profile = helper.Run(function, args, arraysize(args), 0, 100);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env.local(), root, "start");
GetChild(env.local(), start_node, "get foo");
GetChild(env.local(), start_node, "set foo");
profile->Delete();
}
static const char* native_method_test_source =
"function start(count) {\n"
" for (var i = 0; i < count; i++) {\n"
" instance.fooMethod();\n"
" }\n"
"}\n";
TEST(NativeMethodUninitializedIC) {
LocalContext env;
v8::Isolate* isolate = env->GetIsolate();
v8::HandleScope scope(isolate);
TestApiCallbacks callbacks(100);
v8::Local<v8::External> data = v8::External::New(isolate, &callbacks);
v8::Local<v8::FunctionTemplate> func_template =
v8::FunctionTemplate::New(isolate);
func_template->SetClassName(v8_str("Test_InstanceConstructor"));
v8::Local<v8::ObjectTemplate> proto_template =
func_template->PrototypeTemplate();
v8::Local<v8::Signature> signature =
v8::Signature::New(isolate, func_template);
proto_template->Set(
isolate, "fooMethod",
v8::FunctionTemplate::New(isolate, &TestApiCallbacks::Callback, data,
signature, 0));
v8::Local<v8::Function> func =
func_template->GetFunction(env.local()).ToLocalChecked();
v8::Local<v8::Object> instance =
func->NewInstance(env.local()).ToLocalChecked();
env->Global()->Set(env.local(), v8_str("instance"), instance).FromJust();
CompileRun(native_method_test_source);
v8::Local<v8::Function> function = GetFunction(env.local(), "start");
ProfilerHelper helper(env.local());
int32_t repeat_count = 1;
v8::Local<v8::Value> args[] = {v8::Integer::New(isolate, repeat_count)};
v8::CpuProfile* profile = helper.Run(function, args, arraysize(args), 0, 100);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env.local(), root, "start");
GetChild(env.local(), start_node, "fooMethod");
profile->Delete();
}
TEST(NativeMethodMonomorphicIC) {
LocalContext env;
v8::Isolate* isolate = env->GetIsolate();
v8::HandleScope scope(isolate);
TestApiCallbacks callbacks(1);
v8::Local<v8::External> data = v8::External::New(isolate, &callbacks);
v8::Local<v8::FunctionTemplate> func_template =
v8::FunctionTemplate::New(isolate);
func_template->SetClassName(v8_str("Test_InstanceCostructor"));
v8::Local<v8::ObjectTemplate> proto_template =
func_template->PrototypeTemplate();
v8::Local<v8::Signature> signature =
v8::Signature::New(isolate, func_template);
proto_template->Set(
isolate, "fooMethod",
v8::FunctionTemplate::New(isolate, &TestApiCallbacks::Callback, data,
signature, 0));
v8::Local<v8::Function> func =
func_template->GetFunction(env.local()).ToLocalChecked();
v8::Local<v8::Object> instance =
func->NewInstance(env.local()).ToLocalChecked();
env->Global()->Set(env.local(), v8_str("instance"), instance).FromJust();
CompileRun(native_method_test_source);
v8::Local<v8::Function> function = GetFunction(env.local(), "start");
{
// Make sure method ICs are in monomorphic state before starting
// profiling.
callbacks.set_warming_up(true);
int32_t warm_up_iterations = 3;
v8::Local<v8::Value> args[] = {
v8::Integer::New(isolate, warm_up_iterations)};
function->Call(env.local(), env->Global(), arraysize(args), args)
.ToLocalChecked();
callbacks.set_warming_up(false);
}
ProfilerHelper helper(env.local());
int32_t repeat_count = 100;
v8::Local<v8::Value> args[] = {v8::Integer::New(isolate, repeat_count)};
v8::CpuProfile* profile = helper.Run(function, args, arraysize(args), 0, 200);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
GetChild(env.local(), root, "start");
const v8::CpuProfileNode* start_node = GetChild(env.local(), root, "start");
GetChild(env.local(), start_node, "fooMethod");
profile->Delete();
}
static const char* bound_function_test_source =
"function foo() {\n"
" startProfiling('my_profile');\n"
"}\n"
"function start() {\n"
" var callback = foo.bind(this);\n"
" callback();\n"
"}";
TEST(BoundFunctionCall) {
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
CompileRun(bound_function_test_source);
v8::Local<v8::Function> function = GetFunction(env, "start");
ProfilerHelper helper(env);
v8::CpuProfile* profile = helper.Run(function, nullptr, 0);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env, root, "start");
GetChild(env, start_node, "foo");
profile->Delete();
}
// This tests checks distribution of the samples through the source lines.
static void TickLines(bool optimize) {
#ifndef V8_LITE_MODE
FLAG_opt = optimize;
#endif // V8_LITE_MODE
CcTest::InitializeVM();
LocalContext env;
i::FLAG_allow_natives_syntax = true;
i::Isolate* isolate = CcTest::i_isolate();
i::Factory* factory = isolate->factory();
i::HandleScope scope(isolate);
i::EmbeddedVector<char, 512> script;
i::EmbeddedVector<char, 64> prepare_opt;
i::EmbeddedVector<char, 64> optimize_call;
const char* func_name = "func";
if (optimize) {
i::SNPrintF(prepare_opt, "%%PrepareFunctionForOptimization(%s);\n",
func_name);
i::SNPrintF(optimize_call, "%%OptimizeFunctionOnNextCall(%s);\n",
func_name);
} else {
prepare_opt[0] = '\0';
optimize_call[0] = '\0';
}
i::SNPrintF(script,
"function %s() {\n"
" var n = 0;\n"
" var m = 100*100;\n"
" while (m > 1) {\n"
" m--;\n"
" n += m * m * m;\n"
" }\n"
"}\n"
"%s"
"%s();\n"
"%s"
"%s();\n",
func_name, prepare_opt.begin(), func_name, optimize_call.begin(),
func_name);
CompileRun(script.begin());
i::Handle<i::JSFunction> func = i::Handle<i::JSFunction>::cast(
v8::Utils::OpenHandle(*GetFunction(env.local(), func_name)));
CHECK(!func->shared().is_null());
CHECK(!func->shared().abstract_code().is_null());
CHECK(!optimize || func->HasAttachedOptimizedCode() ||
!CcTest::i_isolate()->use_optimizer());
i::Handle<i::AbstractCode> code(func->abstract_code(), isolate);
CHECK(!code->is_null());
i::Address code_address = code->raw_instruction_start();
CHECK_NE(code_address, kNullAddress);
CpuProfilesCollection* profiles = new CpuProfilesCollection(isolate);
ProfilerCodeObserver code_observer(isolate);
Symbolizer* symbolizer = new Symbolizer(code_observer.code_map());
ProfilerEventsProcessor* processor = new SamplingEventsProcessor(
CcTest::i_isolate(), symbolizer, &code_observer, profiles,
v8::base::TimeDelta::FromMicroseconds(100), true);
CpuProfiler profiler(isolate, kDebugNaming, kLazyLogging, profiles,
symbolizer, processor);
profiles->StartProfiling("");
// TODO(delphick): Stop using the CpuProfiler internals here: This forces
// LogCompiledFunctions so that source positions are collected everywhere.
// This would normally happen automatically with CpuProfiler::StartProfiling
// but doesn't because it's constructed with a symbolizer and a processor.
isolate->logger()->LogCompiledFunctions();
CHECK(processor->Start());
ProfilerListener profiler_listener(isolate, processor);
// Enqueue code creation events.
i::Handle<i::String> str = factory->NewStringFromAsciiChecked(func_name);
int line = 1;
int column = 1;
profiler_listener.CodeCreateEvent(i::Logger::FUNCTION_TAG, code,
handle(func->shared(), isolate), str, line,
column);
// Enqueue a tick event to enable code events processing.
EnqueueTickSampleEvent(processor, code_address);
processor->StopSynchronously();
CpuProfile* profile = profiles->StopProfiling("");
CHECK(profile);
// Check the state of the symbolizer.
CodeEntry* func_entry = symbolizer->code_map()->FindEntry(code_address);
CHECK(func_entry);
CHECK_EQ(0, strcmp(func_name, func_entry->name()));
const i::SourcePositionTable* line_info = func_entry->line_info();
CHECK(line_info);
CHECK_NE(v8::CpuProfileNode::kNoLineNumberInfo,
line_info->GetSourceLineNumber(100));
// Check the hit source lines using V8 Public APIs.
const i::ProfileTree* tree = profile->top_down();
ProfileNode* root = tree->root();
CHECK(root);
ProfileNode* func_node = root->FindChild(func_entry);
CHECK(func_node);
// Add 10 faked ticks to source line #5.
int hit_line = 5;
int hit_count = 10;
for (int i = 0; i < hit_count; i++) func_node->IncrementLineTicks(hit_line);
unsigned int line_count = func_node->GetHitLineCount();
CHECK_EQ(2u, line_count); // Expect two hit source lines - #1 and #5.
ScopedVector<v8::CpuProfileNode::LineTick> entries(line_count);
CHECK(func_node->GetLineTicks(&entries[0], line_count));
int value = 0;
for (int i = 0; i < entries.length(); i++)
if (entries[i].line == hit_line) {
value = entries[i].hit_count;
break;
}
CHECK_EQ(hit_count, value);
}
TEST(TickLinesBaseline) { TickLines(false); }
TEST(TickLinesOptimized) { TickLines(true); }
static const char* call_function_test_source =
"%NeverOptimizeFunction(bar);\n"
"%NeverOptimizeFunction(start);\n"
"function bar(n) {\n"
" var s = 0;\n"
" for (var i = 0; i < n; i++) s += i * i * i;\n"
" return s;\n"
"}\n"
"function start(duration) {\n"
" var start = Date.now();\n"
" do {\n"
" for (var i = 0; i < 100; ++i)\n"
" bar.call(this, 1000);\n"
" } while (Date.now() - start < duration);\n"
"}";
// Test that if we sampled thread when it was inside FunctionCall builtin then
// its caller frame will be '(unresolved function)' as we have no reliable way
// to resolve it.
//
// [Top down]:
// 96 0 (root) [-1] #1
// 1 1 (garbage collector) [-1] #4
// 5 0 (unresolved function) [-1] #5
// 5 5 call [-1] #6
// 71 70 start [-1] #3
// 1 1 bar [-1] #7
// 19 19 (program) [-1] #2
TEST(FunctionCallSample) {
i::FLAG_allow_natives_syntax = true;
LocalContext env;
v8::HandleScope scope(env->GetIsolate());
// Collect garbage that might have be generated while installing
// extensions.
CcTest::CollectAllGarbage();
CompileRun(call_function_test_source);
v8::Local<v8::Function> function = GetFunction(env.local(), "start");
ProfilerHelper helper(env.local());
int32_t duration_ms = 100;
v8::Local<v8::Value> args[] = {
v8::Integer::New(env->GetIsolate(), duration_ms)};
v8::CpuProfile* profile = helper.Run(function, args, arraysize(args), 1000);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env.local(), root, "start");
GetChild(env.local(), start_node, "bar");
const v8::CpuProfileNode* unresolved_node =
FindChild(env.local(), root, i::CodeEntry::kUnresolvedFunctionName);
CHECK(!unresolved_node || GetChild(env.local(), unresolved_node, "call"));
profile->Delete();
}
static const char* function_apply_test_source =
"%NeverOptimizeFunction(bar);\n"
"%NeverOptimizeFunction(test);\n"
"%NeverOptimizeFunction(start);\n"
"function bar(n) {\n"
" var s = 0;\n"
" for (var i = 0; i < n; i++) s += i * i * i;\n"
" return s;\n"
"}\n"
"function test() {\n"
" bar.apply(this, [1000]);\n"
"}\n"
"function start(duration) {\n"
" var start = Date.now();\n"
" do {\n"
" for (var i = 0; i < 100; ++i) test();\n"
" } while (Date.now() - start < duration);\n"
"}";
// [Top down]:
// 94 0 (root) [-1] #0 1
// 2 2 (garbage collector) [-1] #0 7
// 82 49 start [-1] #16 3
// 1 0 (unresolved function) [-1] #0 8
// 1 1 apply [-1] #0 9
// 32 21 test [-1] #16 4
// 2 2 bar [-1] #16 6
// 10 10 (program) [-1] #0 2
TEST(FunctionApplySample) {
i::FLAG_allow_natives_syntax = true;
LocalContext env;
v8::HandleScope scope(env->GetIsolate());
CompileRun(function_apply_test_source);
v8::Local<v8::Function> function = GetFunction(env.local(), "start");
ProfilerHelper helper(env.local());
int32_t duration_ms = 100;
v8::Local<v8::Value> args[] = {
v8::Integer::New(env->GetIsolate(), duration_ms)};
v8::CpuProfile* profile = helper.Run(function, args, arraysize(args), 1000);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env.local(), root, "start");
const v8::CpuProfileNode* test_node =
GetChild(env.local(), start_node, "test");
GetChild(env.local(), test_node, "bar");
const v8::CpuProfileNode* unresolved_node =
FindChild(env.local(), start_node, CodeEntry::kUnresolvedFunctionName);
CHECK(!unresolved_node || GetChild(env.local(), unresolved_node, "apply"));
profile->Delete();
}
static const char* cpu_profiler_deep_stack_test_source =
"function foo(n) {\n"
" if (n)\n"
" foo(n - 1);\n"
" else\n"
" collectSample();\n"
"}\n"
"function start() {\n"
" startProfiling('my_profile');\n"
" foo(250);\n"
"}\n";
// Check a deep stack
//
// [Top down]:
// 0 (root) 0 #1
// 2 (program) 0 #2
// 0 start 21 #3 no reason
// 0 foo 21 #4 no reason
// 0 foo 21 #5 no reason
// ....
// 0 foo 21 #254 no reason
TEST(CpuProfileDeepStack) {
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
ProfilerHelper helper(env);
CompileRun(cpu_profiler_deep_stack_test_source);
v8::Local<v8::Function> function = GetFunction(env, "start");
v8::Local<v8::String> profile_name = v8_str("my_profile");
function->Call(env, env->Global(), 0, nullptr).ToLocalChecked();
v8::CpuProfile* profile = helper.profiler()->StopProfiling(profile_name);
CHECK(profile);
// Dump collected profile to have a better diagnostic in case of failure.
reinterpret_cast<i::CpuProfile*>(profile)->Print();
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* node = GetChild(env, root, "start");
for (int i = 0; i <= 250; ++i) {
node = GetChild(env, node, "foo");
}
CHECK(!FindChild(env, node, "foo"));
profile->Delete();
}
static const char* js_native_js_test_source =
"%NeverOptimizeFunction(foo);\n"
"%NeverOptimizeFunction(bar);\n"
"%NeverOptimizeFunction(start);\n"
"function foo(n) {\n"
" var s = 0;\n"
" for (var i = 0; i < n; i++) s += i * i * i;\n"
" return s;\n"
"}\n"
"function bar() {\n"
" foo(1000);\n"
"}\n"
"function start() {\n"
" CallJsFunction(bar);\n"
"}";
static void CallJsFunction(const v8::FunctionCallbackInfo<v8::Value>& info) {
v8::Local<v8::Function> function = info[0].As<v8::Function>();
v8::Local<v8::Value> argv[] = {info[1]};
function
->Call(info.GetIsolate()->GetCurrentContext(), info.This(),
arraysize(argv), argv)
.ToLocalChecked();
}
// [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) {
i::FLAG_allow_natives_syntax = true;
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
v8::Local<v8::FunctionTemplate> func_template =
v8::FunctionTemplate::New(env->GetIsolate(), CallJsFunction);
v8::Local<v8::Function> func =
func_template->GetFunction(env).ToLocalChecked();
func->SetName(v8_str("CallJsFunction"));
env->Global()->Set(env, v8_str("CallJsFunction"), func).FromJust();
CompileRun(js_native_js_test_source);
v8::Local<v8::Function> function = GetFunction(env, "start");
ProfilerHelper helper(env);
v8::CpuProfile* profile = helper.Run(function, nullptr, 0, 1000);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env, root, "start");
const v8::CpuProfileNode* native_node =
GetChild(env, start_node, "CallJsFunction");
const v8::CpuProfileNode* bar_node = GetChild(env, native_node, "bar");
GetChild(env, bar_node, "foo");
profile->Delete();
}
static const char* js_native_js_runtime_js_test_source =
"%NeverOptimizeFunction(foo);\n"
"%NeverOptimizeFunction(bar);\n"
"%NeverOptimizeFunction(start);\n"
"function foo(n) {\n"
" var s = 0;\n"
" for (var i = 0; i < n; i++) s += i * i * i;\n"
" return s;\n"
"}\n"
"var bound = foo.bind(this);\n"
"function bar() {\n"
" bound(1000);\n"
"}\n"
"function start() {\n"
" CallJsFunction(bar);\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) {
i::FLAG_allow_natives_syntax = true;
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
v8::Local<v8::FunctionTemplate> func_template =
v8::FunctionTemplate::New(env->GetIsolate(), CallJsFunction);
v8::Local<v8::Function> func =
func_template->GetFunction(env).ToLocalChecked();
func->SetName(v8_str("CallJsFunction"));
env->Global()->Set(env, v8_str("CallJsFunction"), func).FromJust();
CompileRun(js_native_js_runtime_js_test_source);
ProfilerHelper helper(env);
v8::Local<v8::Function> function = GetFunction(env, "start");
v8::CpuProfile* profile = helper.Run(function, nullptr, 0, 1000);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env, root, "start");
const v8::CpuProfileNode* native_node =
GetChild(env, start_node, "CallJsFunction");
const v8::CpuProfileNode* bar_node = GetChild(env, native_node, "bar");
GetChild(env, bar_node, "foo");
profile->Delete();
}
static void CallJsFunction2(const v8::FunctionCallbackInfo<v8::Value>& info) {
v8::base::OS::Print("In CallJsFunction2\n");
CallJsFunction(info);
}
static const char* js_native1_js_native2_js_test_source =
"%NeverOptimizeFunction(foo);\n"
"%NeverOptimizeFunction(bar);\n"
"%NeverOptimizeFunction(start);\n"
"function foo() {\n"
" var s = 0;\n"
" for (var i = 0; i < 1000; i++) s += i * i * i;\n"
" return s;\n"
"}\n"
"function bar() {\n"
" CallJsFunction2(foo);\n"
"}\n"
"function start() {\n"
" CallJsFunction1(bar);\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) {
i::FLAG_allow_natives_syntax = true;
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
v8::Local<v8::Function> func1 =
v8::FunctionTemplate::New(env->GetIsolate(), CallJsFunction)
->GetFunction(env)
.ToLocalChecked();
func1->SetName(v8_str("CallJsFunction1"));
env->Global()->Set(env, v8_str("CallJsFunction1"), func1).FromJust();
v8::Local<v8::Function> func2 =
v8::FunctionTemplate::New(env->GetIsolate(), CallJsFunction2)
->GetFunction(env)
.ToLocalChecked();
func2->SetName(v8_str("CallJsFunction2"));
env->Global()->Set(env, v8_str("CallJsFunction2"), func2).FromJust();
CompileRun(js_native1_js_native2_js_test_source);
ProfilerHelper helper(env);
v8::Local<v8::Function> function = GetFunction(env, "start");
v8::CpuProfile* profile = helper.Run(function, nullptr, 0, 1000);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env, root, "start");
const v8::CpuProfileNode* native_node1 =
GetChild(env, start_node, "CallJsFunction1");
const v8::CpuProfileNode* bar_node = GetChild(env, native_node1, "bar");
const v8::CpuProfileNode* native_node2 =
GetChild(env, bar_node, "CallJsFunction2");
GetChild(env, native_node2, "foo");
profile->Delete();
}
static const char* js_force_collect_sample_source =
"function start() {\n"
" CallCollectSample();\n"
"}";
static void CallCollectSample(const v8::FunctionCallbackInfo<v8::Value>& info) {
v8::CpuProfiler::CollectSample(info.GetIsolate());
}
TEST(CollectSampleAPI) {
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
v8::Local<v8::FunctionTemplate> func_template =
v8::FunctionTemplate::New(env->GetIsolate(), CallCollectSample);
v8::Local<v8::Function> func =
func_template->GetFunction(env).ToLocalChecked();
func->SetName(v8_str("CallCollectSample"));
env->Global()->Set(env, v8_str("CallCollectSample"), func).FromJust();
CompileRun(js_force_collect_sample_source);
ProfilerHelper helper(env);
v8::Local<v8::Function> function = GetFunction(env, "start");
v8::CpuProfile* profile = helper.Run(function, nullptr, 0, 0);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env, root, "start");
CHECK_LE(1, start_node->GetChildrenCount());
GetChild(env, start_node, "CallCollectSample");
profile->Delete();
}
static const char* js_native_js_runtime_multiple_test_source =
"%NeverOptimizeFunction(foo);\n"
"%NeverOptimizeFunction(bar);\n"
"%NeverOptimizeFunction(start);\n"
"function foo() {\n"
" return Math.sin(Math.random());\n"
"}\n"
"var bound = foo.bind(this);\n"
"function bar() {\n"
" return bound();\n"
"}\n"
"function start() {\n"
" startProfiling('my_profile');\n"
" var startTime = Date.now();\n"
" do {\n"
" CallJsFunction(bar);\n"
" } while (Date.now() - startTime < 200);\n"
"}";
// The test check multiple entrances/exits between JS and native code.
//
// [Top down]:
// (root) #0 1
// start #16 3
// CallJsFunction #0 4
// bar #16 5
// foo #16 6
// (program) #0 2
TEST(JsNativeJsRuntimeJsSampleMultiple) {
i::FLAG_allow_natives_syntax = true;
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
v8::Local<v8::FunctionTemplate> func_template =
v8::FunctionTemplate::New(env->GetIsolate(), CallJsFunction);
v8::Local<v8::Function> func =
func_template->GetFunction(env).ToLocalChecked();
func->SetName(v8_str("CallJsFunction"));
env->Global()->Set(env, v8_str("CallJsFunction"), func).FromJust();
CompileRun(js_native_js_runtime_multiple_test_source);
ProfilerHelper helper(env);
v8::Local<v8::Function> function = GetFunction(env, "start");
v8::CpuProfile* profile = helper.Run(function, nullptr, 0, 500, 500);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env, root, "start");
const v8::CpuProfileNode* native_node =
GetChild(env, start_node, "CallJsFunction");
const v8::CpuProfileNode* bar_node = GetChild(env, native_node, "bar");
GetChild(env, bar_node, "foo");
profile->Delete();
}
static const char* inlining_test_source =
"var finish = false;\n"
"function action(n) {\n"
" var s = 0;\n"
" for (var i = 0; i < n; ++i) s += i*i*i;\n"
" if (finish)\n"
" startProfiling('my_profile');\n"
" return s;\n"
"}\n"
"function level3() { return action(100); }\n"
"function level2() { return level3() * 2; }\n"
"function level1() { return level2(); }\n"
"function start() {\n"
" var n = 100;\n"
" while (--n)\n"
" level1();\n"
" finish = true;\n"
" level1();\n"
"}"
"%PrepareFunctionForOptimization(level1);\n"
"%PrepareFunctionForOptimization(level2);\n"
"%PrepareFunctionForOptimization(level3);\n"
"%NeverOptimizeFunction(action);\n"
"%NeverOptimizeFunction(start);\n"
"level1();\n"
"%OptimizeFunctionOnNextCall(level1);\n"
"%OptimizeFunctionOnNextCall(level2);\n"
"%OptimizeFunctionOnNextCall(level3);\n";
// The test check multiple entrances/exits between JS and native code.
//
// [Top down]:
// (root) #0 1
// start #16 3
// level1 #0 4
// level2 #16 5
// level3 #16 6
// action #16 7
// (program) #0 2
TEST(Inlining) {
i::FLAG_allow_natives_syntax = true;
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
ProfilerHelper helper(env);
CompileRun(inlining_test_source);
v8::Local<v8::Function> function = GetFunction(env, "start");
v8::Local<v8::String> profile_name = v8_str("my_profile");
function->Call(env, env->Global(), 0, nullptr).ToLocalChecked();
v8::CpuProfile* profile = helper.profiler()->StopProfiling(profile_name);
CHECK(profile);
// Dump collected profile to have a better diagnostic in case of failure.
reinterpret_cast<i::CpuProfile*>(profile)->Print();
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env, root, "start");
const v8::CpuProfileNode* level1_node = GetChild(env, start_node, "level1");
const v8::CpuProfileNode* level2_node = GetChild(env, level1_node, "level2");
const v8::CpuProfileNode* level3_node = GetChild(env, level2_node, "level3");
GetChild(env, level3_node, "action");
profile->Delete();
}
static const char* inlining_test_source2 = R"(
function action(n) {
var s = 0;
for (var i = 0; i < n; ++i) s += i*i*i;
return s;
}
function level4() {
action(100);
return action(100);
}
function level3() {
const a = level4();
const b = level4();
return a + b * 1.1;
}
function level2() {
return level3() * 2;
}
function level1() {
action(1);
action(200);
action(1);
return level2();
}
function start(n) {
while (--n)
level1();
};
%NeverOptimizeFunction(action);
%NeverOptimizeFunction(start);
%PrepareFunctionForOptimization(level1);
%PrepareFunctionForOptimization(level2);
%PrepareFunctionForOptimization(level3);
%PrepareFunctionForOptimization(level4);
level1();
level1();
%OptimizeFunctionOnNextCall(level1);
%OptimizeFunctionOnNextCall(level2);
%OptimizeFunctionOnNextCall(level3);
%OptimizeFunctionOnNextCall(level4);
level1();
)";
// [Top down]:
// 0 (root):0 0 #1
// 13 start:34 6 #3
// bailed out due to 'Optimization is always disabled'
// 19 level1:36 6 #4
// 16 action:29 6 #14
// bailed out due to 'Optimization is always disabled'
// 2748 action:30 6 #10
// bailed out due to 'Optimization is always disabled'
// 18 action:31 6 #15
// bailed out due to 'Optimization is always disabled'
// 0 level2:32 6 #5
// 0 level3:26 6 #6
// 12 level4:22 6 #11
// 1315 action:17 6 #13
// bailed out due to 'Optimization is always disabled'
// 1324 action:18 6 #12
// bailed out due to 'Optimization is always disabled'
// 16 level4:21 6 #7
// 1268 action:17 6 #9
// bailed out due to 'Optimization is always disabled'
// 1322 action:18 6 #8
// bailed out due to 'Optimization is always disabled'
// 2 (program):0 0 #2
TEST(Inlining2) {
FLAG_allow_natives_syntax = true;
v8::Isolate* isolate = CcTest::isolate();
LocalContext env;
v8::CpuProfiler::UseDetailedSourcePositionsForProfiling(isolate);
v8::HandleScope scope(isolate);
ProfilerHelper helper(env.local());
CompileRun(inlining_test_source2);
v8::Local<v8::Function> function = GetFunction(env.local(), "start");
v8::Local<v8::Value> args[] = {v8::Integer::New(env->GetIsolate(), 20)};
static const unsigned min_samples = 4000;
static const unsigned min_ext_samples = 0;
v8::CpuProfile* profile =
helper.Run(function, args, arraysize(args), min_samples, min_ext_samples,
v8::CpuProfilingMode::kCallerLineNumbers);
CHECK(profile);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env.local(), root, "start");
NameLinePair l421_a17[] = {{"level1", 27},
{"level2", 23},
{"level3", 17},
{"level4", 12},
{"action", 8}};
CheckBranch(start_node, l421_a17, arraysize(l421_a17));
NameLinePair l422_a17[] = {{"level1", 27},
{"level2", 23},
{"level3", 17},
{"level4", 13},
{"action", 8}};
CheckBranch(start_node, l422_a17, arraysize(l422_a17));
NameLinePair l421_a18[] = {{"level1", 27},
{"level2", 23},
{"level3", 17},
{"level4", 12},
{"action", 9}};
CheckBranch(start_node, l421_a18, arraysize(l421_a18));
NameLinePair l422_a18[] = {{"level1", 27},
{"level2", 23},
{"level3", 17},
{"level4", 13},
{"action", 9}};
CheckBranch(start_node, l422_a18, arraysize(l422_a18));
NameLinePair action_direct[] = {{"level1", 27}, {"action", 21}};
CheckBranch(start_node, action_direct, arraysize(action_direct));
profile->Delete();
}
static const char* cross_script_source_a = R"(
%NeverOptimizeFunction(action);
function action(n) {
var s = 0;
for (var i = 0; i < n; ++i) s += i*i*i;
return s;
}
function level1() {
const a = action(1);
const b = action(200);
const c = action(1);
return a + b + c;
}
)";
static const char* cross_script_source_b = R"(
%PrepareFunctionForOptimization(start);
%PrepareFunctionForOptimization(level1);
start(1);
start(1);
%OptimizeFunctionOnNextCall(start);
%OptimizeFunctionOnNextCall(level1);
start(1);
function start(n) {
while (--n)
level1();
};
)";
TEST(CrossScriptInliningCallerLineNumbers) {
i::FLAG_allow_natives_syntax = true;
v8::Isolate* isolate = CcTest::isolate();
LocalContext env;
v8::CpuProfiler::UseDetailedSourcePositionsForProfiling(isolate);
v8::HandleScope scope(isolate);
ProfilerHelper helper(env.local());
v8::Local<v8::Script> script_a =
CompileWithOrigin(cross_script_source_a, "script_a", false);
v8::Local<v8::Script> script_b =
CompileWithOrigin(cross_script_source_b, "script_b", false);
script_a->Run(env.local()).ToLocalChecked();
script_b->Run(env.local()).ToLocalChecked();
v8::Local<v8::Function> function = GetFunction(env.local(), "start");
v8::Local<v8::Value> args[] = {v8::Integer::New(env->GetIsolate(), 10)};
static const unsigned min_samples = 1000;
static const unsigned min_ext_samples = 0;
v8::CpuProfile* profile =
helper.Run(function, args, arraysize(args), min_samples, min_ext_samples,
v8::CpuProfilingMode::kCallerLineNumbers);
CHECK(profile);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env.local(), root, "start");
CHECK_EQ(0, strcmp("script_b", start_node->GetScriptResourceNameStr()));
NameLinePair l19_a10[] = {{"level1", 11}, {"action", 15}};
CheckBranch(start_node, l19_a10, arraysize(l19_a10));
const v8::CpuProfileNode* level1_node =
GetChild(env.local(), start_node, "level1");
CHECK_EQ(0, strcmp("script_a", level1_node->GetScriptResourceNameStr()));
const v8::CpuProfileNode* action_node =
GetChild(env.local(), level1_node, "action");
CHECK_EQ(0, strcmp("script_a", action_node->GetScriptResourceNameStr()));
profile->Delete();
}
static const char* cross_script_source_c = R"(
function level3() {
const a = action(1);
const b = action(100);
const c = action(1);
return a + b + c;
}
%NeverOptimizeFunction(action);
function action(n) {
var s = 0;
for (var i = 0; i < n; ++i) s += i*i*i;
return s;
}
)";
static const char* cross_script_source_d = R"(
function level2() {
const p = level3();
const q = level3();
return p + q;
}
)";
static const char* cross_script_source_e = R"(
function level1() {
return level2() + 1000;
}
)";
static const char* cross_script_source_f = R"(
%PrepareFunctionForOptimization(start);
%PrepareFunctionForOptimization(level1);
%PrepareFunctionForOptimization(level2);
%PrepareFunctionForOptimization(level3);
start(1);
start(1);
%OptimizeFunctionOnNextCall(start);
%OptimizeFunctionOnNextCall(level1);
%OptimizeFunctionOnNextCall(level2);
%OptimizeFunctionOnNextCall(level3);
start(1);
function start(n) {
while (--n)
level1();
};
)";
TEST(CrossScriptInliningCallerLineNumbers2) {
i::FLAG_allow_natives_syntax = true;
LocalContext env;
v8::HandleScope scope(CcTest::isolate());
ProfilerHelper helper(env.local());
v8::Local<v8::Script> script_c =
CompileWithOrigin(cross_script_source_c, "script_c", false);
v8::Local<v8::Script> script_d =
CompileWithOrigin(cross_script_source_d, "script_d", false);
v8::Local<v8::Script> script_e =
CompileWithOrigin(cross_script_source_e, "script_e", false);
v8::Local<v8::Script> script_f =
CompileWithOrigin(cross_script_source_f, "script_f", false);
script_c->Run(env.local()).ToLocalChecked();
script_d->Run(env.local()).ToLocalChecked();
script_e->Run(env.local()).ToLocalChecked();
script_f->Run(env.local()).ToLocalChecked();
v8::Local<v8::Function> function = GetFunction(env.local(), "start");
v8::Local<v8::Value> args[] = {v8::Integer::New(env->GetIsolate(), 10)};
static const unsigned min_samples = 1000;
static const unsigned min_ext_samples = 0;
v8::CpuProfile* profile =
helper.Run(function, args, arraysize(args), min_samples, min_ext_samples,
v8::CpuProfilingMode::kCallerLineNumbers);
CHECK(profile);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env.local(), root, "start");
CHECK_EQ(0, strcmp("script_f", start_node->GetScriptResourceNameStr()));
const v8::CpuProfileNode* level1_node =
GetChild(env.local(), start_node, "level1");
CHECK_EQ(0, strcmp("script_e", level1_node->GetScriptResourceNameStr()));
const v8::CpuProfileNode* level2_node =
GetChild(env.local(), level1_node, "level2");
CHECK_EQ(0, strcmp("script_d", level2_node->GetScriptResourceNameStr()));
const v8::CpuProfileNode* level3_node =
GetChild(env.local(), level2_node, "level3");
CHECK_EQ(0, strcmp("script_c", level3_node->GetScriptResourceNameStr()));
const v8::CpuProfileNode* action_node =
GetChild(env.local(), level3_node, "action");
CHECK_EQ(0, strcmp("script_c", action_node->GetScriptResourceNameStr()));
profile->Delete();
}
// [Top down]:
// 0 (root) #0 1
// 2 (program) #0 2
// 3 (idle) #0 3
TEST(IdleTime) {
LocalContext env;
v8::HandleScope scope(env->GetIsolate());
v8::CpuProfiler* cpu_profiler = v8::CpuProfiler::New(env->GetIsolate());
v8::Local<v8::String> profile_name = v8_str("my_profile");
cpu_profiler->StartProfiling(profile_name);
i::Isolate* isolate = CcTest::i_isolate();
i::ProfilerEventsProcessor* processor =
reinterpret_cast<i::CpuProfiler*>(cpu_profiler)->processor();
processor->AddCurrentStack(true);
isolate->SetIdle(true);
for (int i = 0; i < 3; i++) {
processor->AddCurrentStack(true);
}
isolate->SetIdle(false);
processor->AddCurrentStack(true);
v8::CpuProfile* profile = cpu_profiler->StopProfiling(profile_name);
CHECK(profile);
// Dump collected profile to have a better diagnostic in case of failure.
reinterpret_cast<i::CpuProfile*>(profile)->Print();
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* program_node =
GetChild(env.local(), root, CodeEntry::kProgramEntryName);
CHECK_EQ(0, program_node->GetChildrenCount());
CHECK_GE(program_node->GetHitCount(), 2u);
const v8::CpuProfileNode* idle_node =
GetChild(env.local(), root, CodeEntry::kIdleEntryName);
CHECK_EQ(0, idle_node->GetChildrenCount());
CHECK_GE(idle_node->GetHitCount(), 3u);
profile->Delete();
cpu_profiler->Dispose();
}
static void CheckFunctionDetails(v8::Isolate* isolate,
const v8::CpuProfileNode* node,
const char* name, const char* script_name,
bool is_shared_cross_origin, int script_id,
int line, int column,
const v8::CpuProfileNode* parent) {
v8::Local<v8::Context> context = isolate->GetCurrentContext();
CHECK(v8_str(name)->Equals(context, node->GetFunctionName()).FromJust());
CHECK_EQ(0, strcmp(name, node->GetFunctionNameStr()));
CHECK(v8_str(script_name)
->Equals(context, node->GetScriptResourceName())
.FromJust());
CHECK_EQ(0, strcmp(script_name, node->GetScriptResourceNameStr()));
CHECK_EQ(script_id, node->GetScriptId());
CHECK_EQ(line, node->GetLineNumber());
CHECK_EQ(column, node->GetColumnNumber());
CHECK_EQ(parent, node->GetParent());
CHECK_EQ(v8::CpuProfileNode::kScript, node->GetSourceType());
}
TEST(FunctionDetails) {
i::FLAG_allow_natives_syntax = true;
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
ProfilerHelper helper(env);
v8::Local<v8::Script> script_a = CompileWithOrigin(
"%NeverOptimizeFunction(foo);\n"
"%NeverOptimizeFunction(bar);\n"
" function foo\n() { bar(); }\n"
" function bar() { startProfiling(); }\n",
"script_a", false);
script_a->Run(env).ToLocalChecked();
v8::Local<v8::Script> script_b = CompileWithOrigin(
"%NeverOptimizeFunction(baz);"
"\n\n function baz() { foo(); }\n"
"\n\nbaz();\n"
"stopProfiling();\n",
"script_b", true);
script_b->Run(env).ToLocalChecked();
const v8::CpuProfile* profile = i::ProfilerExtension::last_profile;
reinterpret_cast<const i::CpuProfile*>(profile)->Print();
// The tree should look like this:
// 0 (root) 0 #1
// 0 "" 19 #2 no reason script_b:1
// 0 baz 19 #3 TryCatchStatement script_b:3
// 0 foo 18 #4 TryCatchStatement script_a:2
// 1 bar 18 #5 no reason script_a:3
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
CHECK_EQ(root->GetParent(), nullptr);
const v8::CpuProfileNode* script = GetChild(env, root, "");
CheckFunctionDetails(env->GetIsolate(), script, "", "script_b", true,
script_b->GetUnboundScript()->GetId(), 1, 1, root);
const v8::CpuProfileNode* baz = GetChild(env, script, "baz");
CheckFunctionDetails(env->GetIsolate(), baz, "baz", "script_b", true,
script_b->GetUnboundScript()->GetId(), 3, 16, script);
const v8::CpuProfileNode* foo = GetChild(env, baz, "foo");
CheckFunctionDetails(env->GetIsolate(), foo, "foo", "script_a", false,
script_a->GetUnboundScript()->GetId(), 4, 1, baz);
const v8::CpuProfileNode* bar = GetChild(env, foo, "bar");
CheckFunctionDetails(env->GetIsolate(), bar, "bar", "script_a", false,
script_a->GetUnboundScript()->GetId(), 5, 14, foo);
}
TEST(FunctionDetailsInlining) {
if (!CcTest::i_isolate()->use_optimizer() || i::FLAG_always_opt) return;
i::FLAG_allow_natives_syntax = true;
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
ProfilerHelper helper(env);
// alpha is in a_script, beta in b_script. beta is
// inlined in alpha, but it should be attributed to b_script.
v8::Local<v8::Script> script_b = CompileWithOrigin(
"function beta(k) {\n"
" let sum = 2;\n"
" for(let i = 0; i < k; i ++) {\n"
" sum += i;\n"
" sum = sum + 'a';\n"
" }\n"
" return sum;\n"
"}\n"
"\n",
"script_b", true);
v8::Local<v8::Script> script_a = CompileWithOrigin(
"function alpha(p) {\n"
" let res = beta(p);\n"
" res = res + res;\n"
" return res;\n"
"}\n"
"let p = 2;\n"
"\n"
"\n"
"// Warm up before profiling or the inlining doesn't happen.\n"
"%PrepareFunctionForOptimization(alpha);\n"
"p = alpha(p);\n"
"p = alpha(p);\n"
"%OptimizeFunctionOnNextCall(alpha);\n"
"p = alpha(p);\n"
"\n"
"\n"
"startProfiling();\n"
"for(let i = 0; i < 10000; i++) {\n"
" p = alpha(p);\n"
"}\n"
"stopProfiling();\n"
"\n"
"\n",
"script_a", false);
script_b->Run(env).ToLocalChecked();
script_a->Run(env).ToLocalChecked();
const v8::CpuProfile* profile = i::ProfilerExtension::last_profile;
reinterpret_cast<const i::CpuProfile*>(profile)->Print();
// The tree should look like this:
// 0 (root) 0 #1
// 5 (program) 0 #6
// 2 14 #2 script_a:1
// ;;; deopted at script_id: 14 position: 299 with reason 'Insufficient
// type feedback for call'.
// 1 alpha 14 #4 script_a:1
// 9 beta 13 #5 script_b:0
// 0 startProfiling 0 #3
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
CHECK_EQ(root->GetParent(), nullptr);
const v8::CpuProfileNode* script = GetChild(env, root, "");
CheckFunctionDetails(env->GetIsolate(), script, "", "script_a", false,
script_a->GetUnboundScript()->GetId(), 1, 1, root);
const v8::CpuProfileNode* alpha = FindChild(env, script, "alpha");
// Return early if profiling didn't sample alpha.
if (!alpha) return;
CheckFunctionDetails(env->GetIsolate(), alpha, "alpha", "script_a", false,
script_a->GetUnboundScript()->GetId(), 1, 15, script);
const v8::CpuProfileNode* beta = FindChild(env, alpha, "beta");
if (!beta) return;
CheckFunctionDetails(env->GetIsolate(), beta, "beta", "script_b", true,
script_b->GetUnboundScript()->GetId(), 1, 14, alpha);
}
static const char* pre_profiling_osr_script = R"(
const kMinIterationDurationMs = 1;
function whenPass(pass, optDuration) {
if (pass == 5) startProfiling();
}
function hot(optDuration, deoptDuration) {
%PrepareFunctionForOptimization(hot);
for (let pass = 0; pass <= optDuration + deoptDuration; pass++) {
const startTime = Date.now();
// Let a few passes go by to ensure we have enough feeback info
if (pass == 3) %OptimizeOsr();
// Force deoptimization. %DeoptimizeNow and %DeoptimizeFunction don't
// doptimize OSRs.
if (pass == optDuration) whenPass = () => {};
whenPass(pass, optDuration);
while (Date.now() - startTime < kMinIterationDurationMs) {
for (let j = 0; j < 1000; j++) {
x = Math.random() * j;
}
}
}
}
function notHot(optDuration, deoptDuration) {
hot(optDuration, deoptDuration);
stopProfiling()
}
)";
// Testing profiling of OSR code that was OSR optimized before profiling
// started. Currently the behavior is not quite right so we're currently
// testing a deopt event being sent to the sampling thread for a function
// it knows nothing about. This deopt does mean we start getting samples
// for hot so we expect some samples, just fewer than for notHot.
//
// We should get something like:
// 0 (root):0 3 0 #1
// 12 (garbage collector):0 3 0 #5
// 5 notHot:22 0 4 #2
// 85 hot:5 0 4 #6
// 0 whenPass:2 0 4 #3
// 0 startProfiling:0 2 0 #4
//
// But currently get something like:
// 0 (root):0 3 0 #1
// 12 (garbage collector):0 3 0 #5
// 57 notHot:22 0 4 #2
// 33 hot:5 0 4 #6
// 0 whenPass:2 0 4 #3
// 0 startProfiling:0 2 0 #4
TEST(StartProfilingAfterOsr) {
i::FLAG_allow_natives_syntax = true;
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
ProfilerHelper helper(env);
helper.profiler()->SetSamplingInterval(100);
CompileRun(pre_profiling_osr_script);
v8::Local<v8::Function> function = GetFunction(env, "notHot");
int32_t profiling_optimized_ms = 120;
int32_t profiling_deoptimized_ms = 40;
v8::Local<v8::Value> args[] = {
v8::Integer::New(env->GetIsolate(), profiling_optimized_ms),
v8::Integer::New(env->GetIsolate(), profiling_deoptimized_ms)};
function->Call(env, env->Global(), arraysize(args), args).ToLocalChecked();
const v8::CpuProfile* profile = i::ProfilerExtension::last_profile;
CHECK(profile);
reinterpret_cast<const i::CpuProfile*>(profile)->Print();
const CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* notHotNode = GetChild(env, root, "notHot");
const v8::CpuProfileNode* hotNode = GetChild(env, notHotNode, "hot");
USE(hotNode);
// If/when OSR sampling is fixed the following CHECK_GT could/should be
// uncommented and the node = node line deleted.
// CHECK_GT(hotNode->GetHitCount(), notHotNode->GetHitCount());
}
TEST(DontStopOnFinishedProfileDelete) {
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
v8::CpuProfiler* profiler = v8::CpuProfiler::New(env->GetIsolate());
i::CpuProfiler* iprofiler = reinterpret_cast<i::CpuProfiler*>(profiler);
CHECK_EQ(0, iprofiler->GetProfilesCount());
v8::Local<v8::String> outer = v8_str("outer");
profiler->StartProfiling(outer);
CHECK_EQ(0, iprofiler->GetProfilesCount());
v8::Local<v8::String> inner = v8_str("inner");
profiler->StartProfiling(inner);
CHECK_EQ(0, iprofiler->GetProfilesCount());
v8::CpuProfile* inner_profile = profiler->StopProfiling(inner);
CHECK(inner_profile);
CHECK_EQ(1, iprofiler->GetProfilesCount());
inner_profile->Delete();
inner_profile = nullptr;
CHECK_EQ(0, iprofiler->GetProfilesCount());
v8::CpuProfile* outer_profile = profiler->StopProfiling(outer);
CHECK(outer_profile);
CHECK_EQ(1, iprofiler->GetProfilesCount());
outer_profile->Delete();
outer_profile = nullptr;
CHECK_EQ(0, iprofiler->GetProfilesCount());
profiler->Dispose();
}
const char* GetBranchDeoptReason(v8::Local<v8::Context> context,
i::CpuProfile* iprofile, const char* branch[],
int length) {
v8::CpuProfile* profile = reinterpret_cast<v8::CpuProfile*>(iprofile);
const ProfileNode* iopt_function = nullptr;
iopt_function = GetSimpleBranch(context, profile, branch, length);
CHECK_EQ(1U, iopt_function->deopt_infos().size());
return iopt_function->deopt_infos()[0].deopt_reason;
}
// deopt at top function
TEST(CollectDeoptEvents) {
if (!CcTest::i_isolate()->use_optimizer() || i::FLAG_always_opt) return;
i::FLAG_allow_natives_syntax = true;
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
ProfilerHelper helper(env);
i::CpuProfiler* iprofiler =
reinterpret_cast<i::CpuProfiler*>(helper.profiler());
const char opt_source[] =
"function opt_function%d(value, depth) {\n"
" if (depth) return opt_function%d(value, depth - 1);\n"
"\n"
" return 10 / value;\n"
"}\n"
"\n";
for (int i = 0; i < 3; ++i) {
i::EmbeddedVector<char, sizeof(opt_source) + 100> buffer;
i::SNPrintF(buffer, opt_source, i, i);
v8::Script::Compile(env, v8_str(buffer.begin()))
.ToLocalChecked()
->Run(env)
.ToLocalChecked();
}
const char* source =
"startProfiling();\n"
"\n"
"%PrepareFunctionForOptimization(opt_function0);\n"
"\n"
"opt_function0(1, 1);\n"
"\n"
"%OptimizeFunctionOnNextCall(opt_function0)\n"
"\n"
"opt_function0(1, 1);\n"
"\n"
"opt_function0(undefined, 1);\n"
"\n"
"%PrepareFunctionForOptimization(opt_function1);\n"
"\n"
"opt_function1(1, 1);\n"
"\n"
"%OptimizeFunctionOnNextCall(opt_function1)\n"
"\n"
"opt_function1(1, 1);\n"
"\n"
"opt_function1(NaN, 1);\n"
"\n"
"%PrepareFunctionForOptimization(opt_function2);\n"
"\n"
"opt_function2(1, 1);\n"
"\n"
"%OptimizeFunctionOnNextCall(opt_function2)\n"
"\n"
"opt_function2(1, 1);\n"
"\n"
"opt_function2(0, 1);\n"
"\n"
"stopProfiling();\n"
"\n";
v8::Script::Compile(env, v8_str(source))
.ToLocalChecked()
->Run(env)
.ToLocalChecked();
i::CpuProfile* iprofile = iprofiler->GetProfile(0);
iprofile->Print();
/* The expected profile
[Top down]:
0 (root) 0 #1
23 32 #2
1 opt_function2 31 #7
1 opt_function2 31 #8
;;; deopted at script_id: 31 position: 106 with reason
'division by zero'.
2 opt_function0 29 #3
4 opt_function0 29 #4
;;; deopted at script_id: 29 position: 108 with reason 'not a
heap number'.
0 opt_function1 30 #5
1 opt_function1 30 #6
;;; deopted at script_id: 30 position: 108 with reason 'lost
precision or NaN'.
*/
{
const char* branch[] = {"", "opt_function0", "opt_function0"};
const char* deopt_reason =
GetBranchDeoptReason(env, iprofile, branch, arraysize(branch));
if (deopt_reason != reason(i::DeoptimizeReason::kNotAHeapNumber) &&
deopt_reason != reason(i::DeoptimizeReason::kNotASmi)) {
FATAL("%s", deopt_reason);
}
}
{
const char* branch[] = {"", "opt_function1", "opt_function1"};
const char* deopt_reason =
GetBranchDeoptReason(env, iprofile, branch, arraysize(branch));
if (deopt_reason != reason(i::DeoptimizeReason::kNaN) &&
deopt_reason != reason(i::DeoptimizeReason::kLostPrecisionOrNaN) &&
deopt_reason != reason(i::DeoptimizeReason::kNotASmi)) {
FATAL("%s", deopt_reason);
}
}
{
const char* branch[] = {"", "opt_function2", "opt_function2"};
CHECK_EQ(reason(i::DeoptimizeReason::kDivisionByZero),
GetBranchDeoptReason(env, iprofile, branch, arraysize(branch)));
}
iprofiler->DeleteProfile(iprofile);
}
TEST(SourceLocation) {
i::FLAG_always_opt = true;
LocalContext env;
v8::HandleScope scope(CcTest::isolate());
const char* source =
"function CompareStatementWithThis() {\n"
" if (this === 1) {}\n"
"}\n"
"CompareStatementWithThis();\n";
v8::Script::Compile(env.local(), v8_str(source))
.ToLocalChecked()
->Run(env.local())
.ToLocalChecked();
}
static const char* inlined_source =
"function opt_function(left, right) { var k = left*right; return k + 1; "
"}\n";
// 0.........1.........2.........3.........4....*....5.........6......*..7
// deopt at the first level inlined function
TEST(DeoptAtFirstLevelInlinedSource) {
if (!CcTest::i_isolate()->use_optimizer() || i::FLAG_always_opt) return;
i::FLAG_allow_natives_syntax = true;
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
ProfilerHelper helper(env);
i::CpuProfiler* iprofiler =
reinterpret_cast<i::CpuProfiler*>(helper.profiler());
// 0.........1.........2.........3.........4.........5.........6.........7
const char* source =
"function test(left, right) { return opt_function(left, right); }\n"
"\n"
"startProfiling();\n"
"\n"
"%EnsureFeedbackVectorForFunction(opt_function);\n"
"%PrepareFunctionForOptimization(test);\n"
"\n"
"test(10, 10);\n"
"\n"
"%OptimizeFunctionOnNextCall(test)\n"
"\n"
"test(10, 10);\n"
"\n"
"test(undefined, 1e9);\n"
"\n"
"stopProfiling();\n"
"\n";
v8::Local<v8::Script> inlined_script = v8_compile(inlined_source);
inlined_script->Run(env).ToLocalChecked();
int inlined_script_id = inlined_script->GetUnboundScript()->GetId();
v8::Local<v8::Script> script = v8_compile(source);
script->Run(env).ToLocalChecked();
int script_id = script->GetUnboundScript()->GetId();
i::CpuProfile* iprofile = iprofiler->GetProfile(0);
iprofile->Print();
/* The expected profile output
[Top down]:
0 (root) 0 #1
10 30 #2
1 test 30 #3
;;; deopted at script_id: 29 position: 45 with reason 'not a
heap number'.
;;; Inline point: script_id 30 position: 36.
4 opt_function 29 #4
*/
v8::CpuProfile* profile = reinterpret_cast<v8::CpuProfile*>(iprofile);
const char* branch[] = {"", "test"};
const ProfileNode* itest_node =
GetSimpleBranch(env, profile, branch, arraysize(branch));
const std::vector<v8::CpuProfileDeoptInfo>& deopt_infos =
itest_node->deopt_infos();
CHECK_EQ(1U, deopt_infos.size());
const v8::CpuProfileDeoptInfo& info = deopt_infos[0];
CHECK(reason(i::DeoptimizeReason::kNotASmi) == info.deopt_reason ||
reason(i::DeoptimizeReason::kNotAHeapNumber) == info.deopt_reason);
CHECK_EQ(2U, info.stack.size());
CHECK_EQ(inlined_script_id, info.stack[0].script_id);
CHECK_LE(dist(offset(inlined_source, "*right"), info.stack[0].position), 1);
CHECK_EQ(script_id, info.stack[1].script_id);
CHECK_EQ(offset(source, "opt_function(left,"), info.stack[1].position);
iprofiler->DeleteProfile(iprofile);
}
// deopt at the second level inlined function
TEST(DeoptAtSecondLevelInlinedSource) {
if (!CcTest::i_isolate()->use_optimizer() || i::FLAG_always_opt) return;
i::FLAG_allow_natives_syntax = true;
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
ProfilerHelper helper(env);
i::CpuProfiler* iprofiler =
reinterpret_cast<i::CpuProfiler*>(helper.profiler());
// 0.........1.........2.........3.........4.........5.........6.........7
const char* source =
"function test2(left, right) { return opt_function(left, right); }\n"
"function test1(left, right) { return test2(left, right); } \n"
"\n"
"startProfiling();\n"
"\n"
"%EnsureFeedbackVectorForFunction(opt_function);\n"
"%EnsureFeedbackVectorForFunction(test2);\n"
"%PrepareFunctionForOptimization(test1);\n"
"\n"
"test1(10, 10);\n"
"\n"
"%OptimizeFunctionOnNextCall(test1)\n"
"\n"
"test1(10, 10);\n"
"\n"
"test1(undefined, 1e9);\n"
"\n"
"stopProfiling();\n"
"\n";
v8::Local<v8::Script> inlined_script = v8_compile(inlined_source);
inlined_script->Run(env).ToLocalChecked();
int inlined_script_id = inlined_script->GetUnboundScript()->GetId();
v8::Local<v8::Script> script = v8_compile(source);
script->Run(env).ToLocalChecked();
int script_id = script->GetUnboundScript()->GetId();
i::CpuProfile* iprofile = iprofiler->GetProfile(0);
iprofile->Print();
/* The expected profile output
[Top down]:
0 (root) 0 #1
11 30 #2
1 test1 30 #3
;;; deopted at script_id: 29 position: 45 with reason 'not a
heap number'.
;;; Inline point: script_id 30 position: 37.
;;; Inline point: script_id 30 position: 103.
1 test2 30 #4
3 opt_function 29 #5
*/
v8::CpuProfile* profile = reinterpret_cast<v8::CpuProfile*>(iprofile);
const char* branch[] = {"", "test1"};
const ProfileNode* itest_node =
GetSimpleBranch(env, profile, branch, arraysize(branch));
const std::vector<v8::CpuProfileDeoptInfo>& deopt_infos =
itest_node->deopt_infos();
CHECK_EQ(1U, deopt_infos.size());
const v8::CpuProfileDeoptInfo info = deopt_infos[0];
CHECK(reason(i::DeoptimizeReason::kNotASmi) == info.deopt_reason ||
reason(i::DeoptimizeReason::kNotAHeapNumber) == info.deopt_reason);
CHECK_EQ(3U, info.stack.size());
CHECK_EQ(inlined_script_id, info.stack[0].script_id);
CHECK_LE(dist(offset(inlined_source, "*right"), info.stack[0].position), 1);
CHECK_EQ(script_id, info.stack[1].script_id);
CHECK_EQ(offset(source, "opt_function(left,"), info.stack[1].position);
CHECK_EQ(offset(source, "test2(left, right);"), info.stack[2].position);
iprofiler->DeleteProfile(iprofile);
}
// deopt in untracked function
TEST(DeoptUntrackedFunction) {
if (!CcTest::i_isolate()->use_optimizer() || i::FLAG_always_opt) return;
i::FLAG_allow_natives_syntax = true;
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
ProfilerHelper helper(env);
i::CpuProfiler* iprofiler =
reinterpret_cast<i::CpuProfiler*>(helper.profiler());
// 0.........1.........2.........3.........4.........5.........6.........7
const char* source =
"function test(left, right) { return opt_function(left, right); }\n"
"\n"
"%EnsureFeedbackVectorForFunction(opt_function);"
"%PrepareFunctionForOptimization(test);\n"
"\n"
"test(10, 10);\n"
"\n"
"%OptimizeFunctionOnNextCall(test)\n"
"\n"
"test(10, 10);\n"
"\n"
"startProfiling();\n" // profiler started after compilation.
"\n"
"test(undefined, 10);\n"
"\n"
"stopProfiling();\n"
"\n";
v8::Local<v8::Script> inlined_script = v8_compile(inlined_source);
inlined_script->Run(env).ToLocalChecked();
v8::Local<v8::Script> script = v8_compile(source);
script->Run(env).ToLocalChecked();
i::CpuProfile* iprofile = iprofiler->GetProfile(0);
iprofile->Print();
v8::CpuProfile* profile = reinterpret_cast<v8::CpuProfile*>(iprofile);
const char* branch[] = {"", "test"};
const ProfileNode* itest_node =
GetSimpleBranch(env, profile, branch, arraysize(branch));
CHECK_EQ(0U, itest_node->deopt_infos().size());
iprofiler->DeleteProfile(iprofile);
}
using v8::platform::tracing::TraceBuffer;
using v8::platform::tracing::TraceConfig;
using v8::platform::tracing::TraceObject;
namespace {
#ifdef V8_USE_PERFETTO
class CpuProfilerListener : public platform::tracing::TraceEventListener {
public:
void ProcessPacket(const ::perfetto::protos::TracePacket& packet) {
auto& seq_state = sequence_state_[packet.trusted_packet_sequence_id()];
if (packet.incremental_state_cleared()) seq_state = SequenceState{};
if (!packet.has_track_event()) return;
// Update incremental state.
if (packet.has_interned_data()) {
const auto& interned_data = packet.interned_data();
for (const auto& it : interned_data.event_names()) {
CHECK_EQ(seq_state.event_names_.find(it.iid()),
seq_state.event_names_.end());
seq_state.event_names_[it.iid()] = it.name();
}
}
const auto& track_event = packet.track_event();
auto name = seq_state.event_names_[track_event.name_iid()];
if (name != "Profile" && name != "ProfileChunk") return;
CHECK_EQ(1, track_event.debug_annotations_size());
CHECK(track_event.debug_annotations()[0].has_legacy_json_value());
CHECK(!profile_id_ ||
track_event.legacy_event().unscoped_id() == profile_id_);
profile_id_ = track_event.legacy_event().unscoped_id();
result_json_ += result_json_.empty() ? "[" : ",\n";
result_json_ += track_event.debug_annotations()[0].legacy_json_value();
}
const std::string& result_json() {
result_json_ += "]";
return result_json_;
}
void Reset() {
result_json_.clear();
profile_id_ = 0;
sequence_state_.clear();
}
private:
std::string result_json_;
uint64_t profile_id_ = 0;
struct SequenceState {
std::map<uint64_t, std::string> event_names_;
};
std::map<uint32_t, SequenceState> sequence_state_;
};
#else
class CpuProfileEventChecker : public v8::platform::tracing::TraceWriter {
public:
void AppendTraceEvent(TraceObject* trace_event) override {
if (trace_event->name() != std::string("Profile") &&
trace_event->name() != std::string("ProfileChunk"))
return;
CHECK(!profile_id_ || trace_event->id() == profile_id_);
CHECK_EQ(1, trace_event->num_args());
CHECK_EQ(TRACE_VALUE_TYPE_CONVERTABLE, trace_event->arg_types()[0]);
profile_id_ = trace_event->id();
v8::ConvertableToTraceFormat* arg =
trace_event->arg_convertables()[0].get();
result_json_ += result_json_.empty() ? "[" : ",\n";
arg->AppendAsTraceFormat(&result_json_);
}
void Flush() override { result_json_ += "]"; }
const std::string& result_json() const { return result_json_; }
void Reset() {
result_json_.clear();
profile_id_ = 0;
}
private:
std::string result_json_;
uint64_t profile_id_ = 0;
};
#endif // !V8_USE_PERFETTO
} // namespace
TEST(TracingCpuProfiler) {
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
auto* tracing_controller =
static_cast<v8::platform::tracing::TracingController*>(
i::V8::GetCurrentPlatform()->GetTracingController());
#ifdef V8_USE_PERFETTO
std::ostringstream perfetto_output;
tracing_controller->InitializeForPerfetto(&perfetto_output);
CpuProfilerListener listener;
tracing_controller->SetTraceEventListenerForTesting(&listener);
#else
CpuProfileEventChecker* event_checker = new CpuProfileEventChecker();
TraceBuffer* ring_buffer =
TraceBuffer::CreateTraceBufferRingBuffer(1, event_checker);
tracing_controller->Initialize(ring_buffer);
#endif
bool result = false;
for (int run_duration = 50; !result; run_duration += 50) {
TraceConfig* trace_config = new TraceConfig();
trace_config->AddIncludedCategory(
TRACE_DISABLED_BY_DEFAULT("v8.cpu_profiler"));
std::string test_code = R"(
function foo() {
let s = 0;
const endTime = Date.now() + )" +
std::to_string(run_duration) + R"(
while (Date.now() < endTime) s += Math.cos(s);
return s;
}
foo();)";
tracing_controller->StartTracing(trace_config);
CompileRun(test_code.c_str());
#ifdef V8_USE_PERFETTO
TrackEvent::Flush();
#endif
tracing_controller->StopTracing();
#ifdef V8_USE_PERFETTO
std::string profile_json = listener.result_json();
listener.Reset();
#else
std::string profile_json = event_checker->result_json();
event_checker->Reset();
#endif
CHECK_LT(0u, profile_json.length());
printf("Profile JSON: %s\n", profile_json.c_str());
std::string profile_checker_code = R"(
function checkProfile(json) {
const profile_header = json[0];
if (typeof profile_header['startTime'] !== 'number')
return false;
return json.some(event => (event.lines || []).some(line => line));
}
checkProfile()" + profile_json +
")";
result = CompileRunChecked(CcTest::isolate(), profile_checker_code.c_str())
->IsTrue();
}
#ifndef V8_USE_PERFETTO
static_cast<v8::platform::tracing::TracingController*>(
i::V8::GetCurrentPlatform()->GetTracingController())
->Initialize(nullptr);
#endif // !V8_USE_PERFETTO
}
TEST(Issue763073) {
class AllowNativesSyntax {
public:
AllowNativesSyntax()
: allow_natives_syntax_(i::FLAG_allow_natives_syntax),
trace_deopt_(i::FLAG_trace_deopt) {
i::FLAG_allow_natives_syntax = true;
i::FLAG_trace_deopt = true;
}
~AllowNativesSyntax() {
i::FLAG_allow_natives_syntax = allow_natives_syntax_;
i::FLAG_trace_deopt = trace_deopt_;
}
private:
bool allow_natives_syntax_;
bool trace_deopt_;
};
AllowNativesSyntax allow_natives_syntax_scope;
LocalContext env;
v8::HandleScope scope(env->GetIsolate());
CompileRun(
"function f() { return function g(x) { }; }"
// Create first closure, optimize it, and deoptimize it.
"var g = f();"
"%PrepareFunctionForOptimization(g);\n"
"g(1);"
"%OptimizeFunctionOnNextCall(g);"
"g(1);"
"%DeoptimizeFunction(g);"
// Create second closure, and optimize it. This will create another
// optimized code object and put in the (shared) type feedback vector.
"var h = f();"
"%PrepareFunctionForOptimization(h);\n"
"h(1);"
"%OptimizeFunctionOnNextCall(h);"
"h(1);");
// Start profiling.
v8::CpuProfiler* cpu_profiler = v8::CpuProfiler::New(env->GetIsolate());
v8::Local<v8::String> profile_name = v8_str("test");
// Here we test that the heap iteration upon profiling start is not
// confused by having a deoptimized code object for a closure while
// having a different optimized code object in the type feedback vector.
cpu_profiler->StartProfiling(profile_name);
v8::CpuProfile* p = cpu_profiler->StopProfiling(profile_name);
p->Delete();
cpu_profiler->Dispose();
}
static const char* js_collect_sample_api_source =
"%NeverOptimizeFunction(start);\n"
"function start() {\n"
" CallStaticCollectSample();\n"
"}";
static void CallStaticCollectSample(
const v8::FunctionCallbackInfo<v8::Value>& info) {
v8::CpuProfiler::CollectSample(info.GetIsolate());
}
TEST(StaticCollectSampleAPI) {
i::FLAG_allow_natives_syntax = true;
LocalContext env;
v8::HandleScope scope(env->GetIsolate());
v8::Local<v8::FunctionTemplate> func_template =
v8::FunctionTemplate::New(env->GetIsolate(), CallStaticCollectSample);
v8::Local<v8::Function> func =
func_template->GetFunction(env.local()).ToLocalChecked();
func->SetName(v8_str("CallStaticCollectSample"));
env->Global()
->Set(env.local(), v8_str("CallStaticCollectSample"), func)
.FromJust();
CompileRun(js_collect_sample_api_source);
v8::Local<v8::Function> function = GetFunction(env.local(), "start");
ProfilerHelper helper(env.local());
v8::CpuProfile* profile = helper.Run(function, nullptr, 0, 100);
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* start_node = GetChild(env.local(), root, "start");
GetChild(env.local(), start_node, "CallStaticCollectSample");
profile->Delete();
}
TEST(CodeEntriesMemoryLeak) {
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
std::string source = "function start() {}\n";
for (int i = 0; i < 1000; ++i) {
source += "function foo" + std::to_string(i) + "() { return " +
std::to_string(i) +
"; }\n"
"foo" +
std::to_string(i) + "();\n";
}
CompileRun(source.c_str());
v8::Local<v8::Function> function = GetFunction(env, "start");
ProfilerHelper helper(env);
for (int j = 0; j < 100; ++j) {
v8::CpuProfile* profile = helper.Run(function, nullptr, 0);
profile->Delete();
}
i::CpuProfiler* profiler =
reinterpret_cast<i::CpuProfiler*>(helper.profiler());
CHECK(!profiler->profiler_listener_for_test());
}
TEST(NativeFrameStackTrace) {
// A test for issue https://crbug.com/768540
// When a sample lands in a native function which has not EXIT frame
// stack frame iterator used to bail out and produce an empty stack trace.
// The source code below makes v8 call the
// v8::internal::StringTable::TryStringToIndexOrLookupExisting native function
// without producing an EXIT frame.
v8::HandleScope scope(CcTest::isolate());
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
const char* source = R"(
function jsFunction() {
var s = {};
for (var i = 0; i < 1e4; ++i) {
for (var j = 0; j < 100; j++) {
s['item' + j] = 'alph';
}
}
})";
CompileRun(source);
v8::Local<v8::Function> function = GetFunction(env, "jsFunction");
ProfilerHelper helper(env);
v8::CpuProfile* profile = helper.Run(function, nullptr, 0, 100, 0);
// Count the fraction of samples landing in 'jsFunction' (valid stack)
// vs '(program)' (no stack captured).
const v8::CpuProfileNode* root = profile->GetTopDownRoot();
const v8::CpuProfileNode* js_function = FindChild(root, "jsFunction");
const v8::CpuProfileNode* program = FindChild(root, "(program)");
if (program) {
unsigned js_function_samples = TotalHitCount(js_function);
unsigned program_samples = TotalHitCount(program);
double valid_samples_ratio =
1. * js_function_samples / (js_function_samples + program_samples);
i::PrintF("Ratio: %f\n", valid_samples_ratio);
// TODO(alph): Investigate other causes of dropped frames. The ratio
// should be close to 99%.
CHECK_GE(valid_samples_ratio, 0.3);
}
profile->Delete();
}
TEST(SourcePositionTable) {
i::SourcePositionTable info;
// Newly created tables should return NoLineNumberInfo for any lookup.
int no_info = v8::CpuProfileNode::kNoLineNumberInfo;
CHECK_EQ(no_info, info.GetSourceLineNumber(std::numeric_limits<int>::min()));
CHECK_EQ(no_info, info.GetSourceLineNumber(0));
CHECK_EQ(SourcePosition::kNotInlined, info.GetInliningId(0));
CHECK_EQ(no_info, info.GetSourceLineNumber(1));
CHECK_EQ(no_info, info.GetSourceLineNumber(9));
CHECK_EQ(no_info, info.GetSourceLineNumber(10));
CHECK_EQ(no_info, info.GetSourceLineNumber(11));
CHECK_EQ(no_info, info.GetSourceLineNumber(19));
CHECK_EQ(no_info, info.GetSourceLineNumber(20));
CHECK_EQ(no_info, info.GetSourceLineNumber(21));
CHECK_EQ(no_info, info.GetSourceLineNumber(100));
CHECK_EQ(SourcePosition::kNotInlined, info.GetInliningId(100));
CHECK_EQ(no_info, info.GetSourceLineNumber(std::numeric_limits<int>::max()));
info.SetPosition(10, 1, SourcePosition::kNotInlined);
info.SetPosition(20, 2, SourcePosition::kNotInlined);
// The only valid return values are 1 or 2 - every pc maps to a line
// number.
CHECK_EQ(1, info.GetSourceLineNumber(std::numeric_limits<int>::min()));
CHECK_EQ(1, info.GetSourceLineNumber(0));
CHECK_EQ(1, info.GetSourceLineNumber(1));
CHECK_EQ(1, info.GetSourceLineNumber(9));
CHECK_EQ(1, info.GetSourceLineNumber(10));
CHECK_EQ(1, info.GetSourceLineNumber(11));
CHECK_EQ(1, info.GetSourceLineNumber(19));
CHECK_EQ(1, info.GetSourceLineNumber(20));
CHECK_EQ(2, info.GetSourceLineNumber(21));
CHECK_EQ(2, info.GetSourceLineNumber(100));
CHECK_EQ(2, info.GetSourceLineNumber(std::numeric_limits<int>::max()));
CHECK_EQ(SourcePosition::kNotInlined, info.GetInliningId(0));
CHECK_EQ(SourcePosition::kNotInlined, info.GetInliningId(100));
// Test SetPosition behavior.
info.SetPosition(25, 3, 0);
CHECK_EQ(2, info.GetSourceLineNumber(21));
CHECK_EQ(3, info.GetSourceLineNumber(100));
CHECK_EQ(3, info.GetSourceLineNumber(std::numeric_limits<int>::max()));
CHECK_EQ(SourcePosition::kNotInlined, info.GetInliningId(21));
CHECK_EQ(0, info.GetInliningId(100));
// Test that subsequent SetPosition calls with the same pc_offset are ignored.
info.SetPosition(25, 4, SourcePosition::kNotInlined);
CHECK_EQ(2, info.GetSourceLineNumber(21));
CHECK_EQ(3, info.GetSourceLineNumber(100));
CHECK_EQ(3, info.GetSourceLineNumber(std::numeric_limits<int>::max()));
CHECK_EQ(SourcePosition::kNotInlined, info.GetInliningId(21));
CHECK_EQ(0, info.GetInliningId(100));
}
TEST(MultipleProfilers) {
std::unique_ptr<CpuProfiler> profiler1(new CpuProfiler(CcTest::i_isolate()));
std::unique_ptr<CpuProfiler> profiler2(new CpuProfiler(CcTest::i_isolate()));
profiler1->StartProfiling("1");
profiler2->StartProfiling("2");
profiler1->StopProfiling("1");
profiler2->StopProfiling("2");
}
// Tests that logged CodeCreateEvent calls do not crash a reused CpuProfiler.
// crbug.com/929928
TEST(CrashReusedProfiler) {
LocalContext env;
i::Isolate* isolate = CcTest::i_isolate();
i::HandleScope scope(isolate);
std::unique_ptr<CpuProfiler> profiler(new CpuProfiler(isolate));
profiler->StartProfiling("1");
profiler->StopProfiling("1");
profiler->StartProfiling("2");
CreateCode(&env);
profiler->StopProfiling("2");
}
// Tests that samples from different profilers on the same isolate do not leak
// samples to each other. See crbug.com/v8/8835.
TEST(MultipleProfilersSampleIndependently) {
LocalContext env;
i::Isolate* isolate = CcTest::i_isolate();
i::HandleScope scope(isolate);
// Create two profilers- one slow ticking one, and one fast ticking one.
// Ensure that the slow ticking profiler does not receive samples from the
// fast ticking one.
std::unique_ptr<CpuProfiler> slow_profiler(
new CpuProfiler(CcTest::i_isolate()));
slow_profiler->set_sampling_interval(base::TimeDelta::FromSeconds(1));
slow_profiler->StartProfiling("1", {kLeafNodeLineNumbers});
CompileRun(R"(
function start() {
let val = 1;
for (let i = 0; i < 10e3; i++) {
val = (val * 2) % 3;
}
return val;
}
)");
v8::Local<v8::Function> function = GetFunction(env.local(), "start");
ProfilerHelper helper(env.local());
v8::CpuProfile* profile = helper.Run(function, nullptr, 0, 100, 0);
auto slow_profile = slow_profiler->StopProfiling("1");
CHECK_GT(profile->GetSamplesCount(), slow_profile->samples_count());
}
void ProfileSomeCode(v8::Isolate* isolate) {
v8::Isolate::Scope isolate_scope(isolate);
v8::HandleScope scope(isolate);
LocalContext context(isolate);
v8::CpuProfiler* profiler = v8::CpuProfiler::New(isolate);
v8::Local<v8::String> profile_name = v8_str("1");
profiler->StartProfiling(profile_name);
const char* source = R"(
function foo() {
var x = 0;
for (var i = 0; i < 1e3; i++) {
for (var j = 0; j < 1e3; j++) {
x = i * j;
}
}
return x;
}
foo();
)";
CompileRun(source);
profiler->StopProfiling(profile_name);
profiler->Dispose();
}
class IsolateThread : public v8::base::Thread {
public:
IsolateThread() : Thread(Options("IsolateThread")) {}
void Run() override {
v8::Isolate::CreateParams create_params;
create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
v8::Isolate* isolate = v8::Isolate::New(create_params);
ProfileSomeCode(isolate);
isolate->Dispose();
}
};
// Checking for crashes and TSAN issues with multiple isolates profiling.
TEST(MultipleIsolates) {
IsolateThread thread1;
IsolateThread thread2;
CHECK(thread1.Start());
CHECK(thread2.Start());
thread1.Join();
thread2.Join();
}
// Varying called function frame sizes increases the chance of something going
// wrong if sampling an unlocked frame. We also prevent optimization to prevent
// inlining so each function call has its own frame.
const char* varying_frame_size_script = R"(
%NeverOptimizeFunction(maybeYield);
%NeverOptimizeFunction(bar);
%NeverOptimizeFunction(foo);
function maybeYield(n) {
YieldIsolate(Math.random() > yieldLimit);
}
function bar(a, b, c, d) {
maybeYield(Math.random());
return a.length + b.length + c.length + d.length;
}
function foo(timeLimit, yieldProbability) {
yieldLimit = 1 - yieldProbability;
const startTime = Date.now();
for (let i = 0; i < 1e6; i++) {
maybeYield(1);
bar("Hickory", "Dickory", "Doc", "Mouse");
YieldIsolate(Math.random() > 0.999);
if ((Date.now() - startTime) > timeLimit) break;
}
}
)";
class UnlockingThread : public v8::base::Thread {
public:
explicit UnlockingThread(v8::Local<v8::Context> env)
: Thread(Options("UnlockingThread")), env_(CcTest::isolate(), env) {}
void Run() override {
v8::Isolate* isolate = CcTest::isolate();
v8::Locker locker(isolate);
v8::Isolate::Scope isolate_scope(isolate);
v8::HandleScope scope(isolate);
v8::Local<v8::Context> env = v8::Local<v8::Context>::New(isolate, env_);
Profile(env);
}
static void Profile(v8::Local<v8::Context> env) {
v8::Isolate* isolate = CcTest::isolate();
v8::Context::Scope context_scope(env);
v8::CpuProfiler* profiler = v8::CpuProfiler::New(isolate);
profiler->SetSamplingInterval(200);
v8::Local<v8::String> profile_name = v8_str("1");
profiler->StartProfiling(profile_name);
int32_t time_limit = 200;
double yield_probability = 0.001;
v8::Local<v8::Value> args[] = {v8::Integer::New(isolate, time_limit),
v8::Number::New(isolate, yield_probability)};
v8::Local<v8::Function> function = GetFunction(env, "foo");
function->Call(env, env->Global(), arraysize(args), args).ToLocalChecked();
profiler->StopProfiling(profile_name);
profiler->Dispose();
}
private:
v8::Persistent<v8::Context> env_;
};
// Checking for crashes with multiple thread/single Isolate profiling.
TEST(MultipleThreadsSingleIsolate) {
i::FLAG_allow_natives_syntax = true;
v8::Isolate* isolate = CcTest::isolate();
v8::Locker locker(isolate);
v8::HandleScope scope(isolate);
v8::Local<v8::Context> env = CcTest::NewContext({PROFILER_EXTENSION_ID});
v8::Context::Scope context_scope(env);
CcTest::AddGlobalFunction(
env, "YieldIsolate", [](const v8::FunctionCallbackInfo<v8::Value>& info) {
v8::Isolate* isolate = info.GetIsolate();
if (!info[0]->IsTrue()) return;
v8::Unlocker unlocker(isolate);
v8::base::OS::Sleep(v8::base::TimeDelta::FromMilliseconds(1));
});
CompileRun(varying_frame_size_script);
UnlockingThread thread1(env);
UnlockingThread thread2(env);
CHECK(thread1.Start());
CHECK(thread2.Start());
// For good measure, profile on our own thread
UnlockingThread::Profile(env);
{
v8::Unlocker unlocker(isolate);
thread1.Join();
thread2.Join();
}
}
// Tests that StopProfiling doesn't wait for the next sample tick in order to
// stop, but rather exits early before a given wait threshold.
TEST(FastStopProfiling) {
static const base::TimeDelta kLongInterval = base::TimeDelta::FromSeconds(10);
static const base::TimeDelta kWaitThreshold = base::TimeDelta::FromSeconds(5);
std::unique_ptr<CpuProfiler> profiler(new CpuProfiler(CcTest::i_isolate()));
profiler->set_sampling_interval(kLongInterval);
profiler->StartProfiling("", {kLeafNodeLineNumbers});
v8::Platform* platform = v8::internal::V8::GetCurrentPlatform();
double start = platform->CurrentClockTimeMillis();
profiler->StopProfiling("");
double duration = platform->CurrentClockTimeMillis() - start;
CHECK_LT(duration, kWaitThreshold.InMillisecondsF());
}
// Tests that when current_profiles->size() is greater than the max allowable
// number of concurrent profiles (100), we don't allow a new Profile to be
// profiled
TEST(MaxSimultaneousProfiles) {
LocalContext env;
i::Isolate* isolate = CcTest::i_isolate();
i::HandleScope scope(isolate);
v8::CpuProfiler* profiler = v8::CpuProfiler::New(env->GetIsolate());
// Spin up first profiler. Verify that status is kStarted
CpuProfilingStatus firstStatus = profiler->StartProfiling(
v8_str("1us"), {v8::CpuProfilingMode::kLeafNodeLineNumbers,
v8::CpuProfilingOptions::kNoSampleLimit, 1});
CHECK_EQ(firstStatus, CpuProfilingStatus::kStarted);
// Spin up profiler with same title. Verify that status is kAlreadyStarted
CpuProfilingStatus startedStatus = profiler->StartProfiling(
v8_str("1us"), {v8::CpuProfilingMode::kLeafNodeLineNumbers,
v8::CpuProfilingOptions::kNoSampleLimit, 1});
CHECK_EQ(startedStatus, CpuProfilingStatus::kAlreadyStarted);
// Spin up 99 more profilers, maxing out CpuProfilersCollection.
// Check they all return status of kStarted
for (int i = 2; i <= CpuProfilesCollection::kMaxSimultaneousProfiles; i++) {
CpuProfilingStatus status =
profiler->StartProfiling(v8_str((std::to_string(i) + "us").c_str()),
{v8::CpuProfilingMode::kLeafNodeLineNumbers,
v8::CpuProfilingOptions::kNoSampleLimit, i});
CHECK_EQ(status, CpuProfilingStatus::kStarted);
}
// Spin up 101st profiler. Verify status is kErrorTooManyProfilers
CpuProfilingStatus errorStatus = profiler->StartProfiling(
v8_str("101us"), {v8::CpuProfilingMode::kLeafNodeLineNumbers,
v8::CpuProfilingOptions::kNoSampleLimit, 2});
CHECK_EQ(errorStatus, CpuProfilingStatus::kErrorTooManyProfilers);
// Clean up, otherwise will show a crash.
for (int i = 1; i <= CpuProfilesCollection::kMaxSimultaneousProfiles + 1;
i++) {
profiler->StopProfiling(v8_str((std::to_string(i) + "us").c_str()));
}
}
TEST(LowPrecisionSamplingStartStopInternal) {
i::Isolate* isolate = CcTest::i_isolate();
CpuProfilesCollection profiles(isolate);
ProfilerCodeObserver code_observer(isolate);
Symbolizer symbolizer(code_observer.code_map());
std::unique_ptr<ProfilerEventsProcessor> processor(
new SamplingEventsProcessor(
isolate, &symbolizer, &code_observer, &profiles,
v8::base::TimeDelta::FromMicroseconds(100), false));
CHECK(processor->Start());
processor->StopSynchronously();
}
TEST(LowPrecisionSamplingStartStopPublic) {
LocalContext env;
v8::HandleScope scope(env->GetIsolate());
v8::CpuProfiler* cpu_profiler = v8::CpuProfiler::New(env->GetIsolate());
cpu_profiler->SetUsePreciseSampling(false);
v8::Local<v8::String> profile_name = v8_str("");
cpu_profiler->StartProfiling(profile_name, true);
cpu_profiler->StopProfiling(profile_name);
cpu_profiler->Dispose();
}
const char* naming_test_source = R"(
(function testAssignmentPropertyNamedFunction() {
let object = {};
object.propNamed = function () {
CallCollectSample();
};
object.propNamed();
})();
)";
TEST(StandardNaming) {
LocalContext env;
i::Isolate* isolate = CcTest::i_isolate();
i::HandleScope scope(isolate);
v8::Local<v8::FunctionTemplate> func_template =
v8::FunctionTemplate::New(env->GetIsolate(), CallCollectSample);
v8::Local<v8::Function> func =
func_template->GetFunction(env.local()).ToLocalChecked();
func->SetName(v8_str("CallCollectSample"));
env->Global()->Set(env.local(), v8_str("CallCollectSample"), func).FromJust();
v8::CpuProfiler* profiler =
v8::CpuProfiler::New(env->GetIsolate(), kStandardNaming);
const auto profile_name = v8_str("");
profiler->StartProfiling(profile_name);
CompileRun(naming_test_source);
auto* profile = profiler->StopProfiling(profile_name);
auto* root = profile->GetTopDownRoot();
auto* toplevel = FindChild(root, "");
DCHECK(toplevel);
auto* prop_assignment_named_test =
GetChild(env.local(), toplevel, "testAssignmentPropertyNamedFunction");
CHECK(FindChild(prop_assignment_named_test, ""));
profiler->Dispose();
}
TEST(DebugNaming) {
LocalContext env;
i::Isolate* isolate = CcTest::i_isolate();
i::HandleScope scope(isolate);
v8::Local<v8::FunctionTemplate> func_template =
v8::FunctionTemplate::New(env->GetIsolate(), CallCollectSample);
v8::Local<v8::Function> func =
func_template->GetFunction(env.local()).ToLocalChecked();
func->SetName(v8_str("CallCollectSample"));
env->Global()->Set(env.local(), v8_str("CallCollectSample"), func).FromJust();
v8::CpuProfiler* profiler =
v8::CpuProfiler::New(env->GetIsolate(), kDebugNaming);
const auto profile_name = v8_str("");
profiler->StartProfiling(profile_name);
CompileRun(naming_test_source);
auto* profile = profiler->StopProfiling(profile_name);
auto* root = profile->GetTopDownRoot();
auto* toplevel = FindChild(root, "");
DCHECK(toplevel);
auto* prop_assignment_named_test =
GetChild(env.local(), toplevel, "testAssignmentPropertyNamedFunction");
CHECK(FindChild(prop_assignment_named_test, "object.propNamed"));
profiler->Dispose();
}
TEST(SampleLimit) {
LocalContext env;
i::Isolate* isolate = CcTest::i_isolate();
i::HandleScope scope(isolate);
CompileRun(R"(
function start() {
let val = 1;
for (let i = 0; i < 10e3; i++) {
val = (val * 2) % 3;
}
return val;
}
)");
// Take 100 samples of `start`, but set the max samples to 50.
v8::Local<v8::Function> function = GetFunction(env.local(), "start");
ProfilerHelper helper(env.local());
v8::CpuProfile* profile =
helper.Run(function, nullptr, 0, 100, 0,
v8::CpuProfilingMode::kLeafNodeLineNumbers, 50);
CHECK_EQ(profile->GetSamplesCount(), 50);
}
// Tests that a CpuProfile instance subsamples from a stream of tick samples
// appropriately.
TEST(ProflilerSubsampling) {
LocalContext env;
i::Isolate* isolate = CcTest::i_isolate();
i::HandleScope scope(isolate);
CpuProfilesCollection* profiles = new CpuProfilesCollection(isolate);
ProfilerCodeObserver code_observer(isolate);
Symbolizer* symbolizer = new Symbolizer(code_observer.code_map());
ProfilerEventsProcessor* processor =
new SamplingEventsProcessor(isolate, symbolizer, &code_observer, profiles,
v8::base::TimeDelta::FromMicroseconds(1),
/* use_precise_sampling */ true);
CpuProfiler profiler(isolate, kDebugNaming, kLazyLogging, profiles,
symbolizer, processor);
// Create a new CpuProfile that wants samples at 8us.
CpuProfile profile(&profiler, "",
{v8::CpuProfilingMode::kLeafNodeLineNumbers,
v8::CpuProfilingOptions::kNoSampleLimit, 8});
// Verify that the first sample is always included.
CHECK(profile.CheckSubsample(base::TimeDelta::FromMicroseconds(10)));
// 4 2us samples should result in one 8us sample.
CHECK(!profile.CheckSubsample(base::TimeDelta::FromMicroseconds(2)));
CHECK(!profile.CheckSubsample(base::TimeDelta::FromMicroseconds(2)));
CHECK(!profile.CheckSubsample(base::TimeDelta::FromMicroseconds(2)));
CHECK(profile.CheckSubsample(base::TimeDelta::FromMicroseconds(2)));
// Profiles should expect the source sample interval to change, in which case
// they should still take the first sample elapsed after their interval.
CHECK(!profile.CheckSubsample(base::TimeDelta::FromMicroseconds(2)));
CHECK(!profile.CheckSubsample(base::TimeDelta::FromMicroseconds(2)));
CHECK(!profile.CheckSubsample(base::TimeDelta::FromMicroseconds(2)));
CHECK(profile.CheckSubsample(base::TimeDelta::FromMicroseconds(4)));
// Aligned samples (at 8us) are always included.
CHECK(profile.CheckSubsample(base::TimeDelta::FromMicroseconds(8)));
// Samples with a rate of 0 should always be included.
CHECK(profile.CheckSubsample(base::TimeDelta::FromMicroseconds(0)));
}
// Tests that the base sampling rate of a CpuProfilesCollection is dynamically
// chosen based on the GCD of its child profiles.
TEST(DynamicResampling) {
LocalContext env;
i::Isolate* isolate = CcTest::i_isolate();
i::HandleScope scope(isolate);
CpuProfilesCollection* profiles = new CpuProfilesCollection(isolate);
ProfilerCodeObserver code_observer(isolate);
Symbolizer* symbolizer = new Symbolizer(code_observer.code_map());
ProfilerEventsProcessor* processor =
new SamplingEventsProcessor(isolate, symbolizer, &code_observer, profiles,
v8::base::TimeDelta::FromMicroseconds(1),
/* use_precise_sampling */ true);
CpuProfiler profiler(isolate, kDebugNaming, kLazyLogging, profiles,
symbolizer, processor);
// Set a 1us base sampling rate, dividing all possible intervals.
profiler.set_sampling_interval(base::TimeDelta::FromMicroseconds(1));
// Verify that the sampling interval with no started profilers is unset.
CHECK_EQ(profiles->GetCommonSamplingInterval(), base::TimeDelta());
// Add a 10us profiler, verify that the base sampling interval is as high as
// possible (10us).
profiles->StartProfiling("10us",
{v8::CpuProfilingMode::kLeafNodeLineNumbers,
v8::CpuProfilingOptions::kNoSampleLimit, 10});
CHECK_EQ(profiles->GetCommonSamplingInterval(),
base::TimeDelta::FromMicroseconds(10));
// Add a 5us profiler, verify that the base sampling interval is as high as
// possible given a 10us and 5us profiler (5us).
profiles->StartProfiling("5us", {v8::CpuProfilingMode::kLeafNodeLineNumbers,
v8::CpuProfilingOptions::kNoSampleLimit, 5});
CHECK_EQ(profiles->GetCommonSamplingInterval(),
base::TimeDelta::FromMicroseconds(5));
// Add a 3us profiler, verify that the base sampling interval is 1us (due to
// coprime intervals).
profiles->StartProfiling("3us", {v8::CpuProfilingMode::kLeafNodeLineNumbers,
v8::CpuProfilingOptions::kNoSampleLimit, 3});
CHECK_EQ(profiles->GetCommonSamplingInterval(),
base::TimeDelta::FromMicroseconds(1));
// Remove the 5us profiler, verify that the sample interval stays at 1us.
profiles->StopProfiling("5us");
CHECK_EQ(profiles->GetCommonSamplingInterval(),
base::TimeDelta::FromMicroseconds(1));
// Remove the 10us profiler, verify that the sample interval becomes 3us.
profiles->StopProfiling("10us");
CHECK_EQ(profiles->GetCommonSamplingInterval(),
base::TimeDelta::FromMicroseconds(3));
// Remove the 3us profiler, verify that the sample interval becomes unset.
profiles->StopProfiling("3us");
CHECK_EQ(profiles->GetCommonSamplingInterval(), base::TimeDelta());
}
// Ensures that when a non-unit base sampling interval is set on the profiler,
// that the sampling rate gets snapped to the nearest multiple prior to GCD
// computation.
TEST(DynamicResamplingWithBaseInterval) {
LocalContext env;
i::Isolate* isolate = CcTest::i_isolate();
i::HandleScope scope(isolate);
CpuProfilesCollection* profiles = new CpuProfilesCollection(isolate);
ProfilerCodeObserver code_observer(isolate);
Symbolizer* symbolizer = new Symbolizer(code_observer.code_map());
ProfilerEventsProcessor* processor =
new SamplingEventsProcessor(isolate, symbolizer, &code_observer, profiles,
v8::base::TimeDelta::FromMicroseconds(1),
/* use_precise_sampling */ true);
CpuProfiler profiler(isolate, kDebugNaming, kLazyLogging, profiles,
symbolizer, processor);
profiler.set_sampling_interval(base::TimeDelta::FromMicroseconds(7));
// Verify that the sampling interval with no started profilers is unset.
CHECK_EQ(profiles->GetCommonSamplingInterval(), base::TimeDelta());
// Add a profiler with an unset sampling interval, verify that the common
// sampling interval is equal to the base.
profiles->StartProfiling("unset", {v8::CpuProfilingMode::kLeafNodeLineNumbers,
v8::CpuProfilingOptions::kNoSampleLimit});
CHECK_EQ(profiles->GetCommonSamplingInterval(),
base::TimeDelta::FromMicroseconds(7));
profiles->StopProfiling("unset");
// Adding a 8us sampling interval rounds to a 14us base interval.
profiles->StartProfiling("8us", {v8::CpuProfilingMode::kLeafNodeLineNumbers,
v8::CpuProfilingOptions::kNoSampleLimit, 8});
CHECK_EQ(profiles->GetCommonSamplingInterval(),
base::TimeDelta::FromMicroseconds(14));
// Adding a 4us sampling interval should cause a lowering to a 7us interval.
profiles->StartProfiling("4us", {v8::CpuProfilingMode::kLeafNodeLineNumbers,
v8::CpuProfilingOptions::kNoSampleLimit, 4});
CHECK_EQ(profiles->GetCommonSamplingInterval(),
base::TimeDelta::FromMicroseconds(7));
// Removing the 4us sampling interval should restore the 14us sampling
// interval.
profiles->StopProfiling("4us");
CHECK_EQ(profiles->GetCommonSamplingInterval(),
base::TimeDelta::FromMicroseconds(14));
// Removing the 8us sampling interval should unset the common sampling
// interval.
profiles->StopProfiling("8us");
CHECK_EQ(profiles->GetCommonSamplingInterval(), base::TimeDelta());
// A sampling interval of 0us should enforce all profiles to have a sampling
// interval of 0us (the only multiple of 0).
profiler.set_sampling_interval(base::TimeDelta::FromMicroseconds(0));
profiles->StartProfiling("5us", {v8::CpuProfilingMode::kLeafNodeLineNumbers,
v8::CpuProfilingOptions::kNoSampleLimit, 5});
CHECK_EQ(profiles->GetCommonSamplingInterval(),
base::TimeDelta::FromMicroseconds(0));
profiles->StopProfiling("5us");
}
// Tests that functions compiled after a started profiler is stopped are still
// visible when the profiler is started again. (https://crbug.com/v8/9151)
TEST(Bug9151StaleCodeEntries) {
LocalContext env;
v8::HandleScope scope(env->GetIsolate());
v8::Local<v8::FunctionTemplate> func_template =
v8::FunctionTemplate::New(env->GetIsolate(), CallCollectSample);
v8::Local<v8::Function> func =
func_template->GetFunction(env.local()).ToLocalChecked();
func->SetName(v8_str("CallCollectSample"));
env->Global()->Set(env.local(), v8_str("CallCollectSample"), func).FromJust();
v8::CpuProfiler* profiler =
v8::CpuProfiler::New(env->GetIsolate(), kDebugNaming, kEagerLogging);
v8::Local<v8::String> profile_name = v8_str("");
// Warm up the profiler to create the initial code map.
profiler->StartProfiling(profile_name);
profiler->StopProfiling(profile_name);
// Log a function compilation (executed once to force a compilation).
CompileRun(R"(
function start() {
CallCollectSample();
}
start();
)");
// Restart the profiler, and execute both the JS function and callback.
profiler->StartProfiling(profile_name, true);
CompileRun("start();");
v8::CpuProfile* profile = profiler->StopProfiling(profile_name);
auto* root = profile->GetTopDownRoot();
auto* toplevel = GetChild(env.local(), root, "");
auto* start = FindChild(env.local(), toplevel, "start");
CHECK(start);
auto* callback = FindChild(env.local(), start, "CallCollectSample");
CHECK(callback);
}
enum class EntryCountMode { kAll, kOnlyInlined };
// Count the number of unique source positions.
int GetSourcePositionEntryCount(i::Isolate* isolate, const char* source,
EntryCountMode mode = EntryCountMode::kAll) {
std::unordered_set<int64_t> raw_position_set;
i::Handle<i::JSFunction> function = i::Handle<i::JSFunction>::cast(
v8::Utils::OpenHandle(*CompileRun(source)));
if (function->ActiveTierIsIgnition()) return -1;
i::Handle<i::Code> code(function->code(), isolate);
i::SourcePositionTableIterator iterator(
ByteArray::cast(code->source_position_table()));
while (!iterator.done()) {
if (mode == EntryCountMode::kAll ||
iterator.source_position().isInlined()) {
raw_position_set.insert(iterator.source_position().raw());
}
iterator.Advance();
}
return static_cast<int>(raw_position_set.size());
}
UNINITIALIZED_TEST(DetailedSourcePositionAPI) {
i::FLAG_detailed_line_info = false;
i::FLAG_allow_natives_syntax = true;
v8::Isolate::CreateParams create_params;
create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
v8::Isolate* isolate = v8::Isolate::New(create_params);
const char* source =
"function fib(i) {"
" if (i <= 1) return 1; "
" return fib(i - 1) +"
" fib(i - 2);"
"}"
"%PrepareFunctionForOptimization(fib);\n"
"fib(5);"
"%OptimizeFunctionOnNextCall(fib);"
"fib(5);"
"fib";
{
v8::Isolate::Scope isolate_scope(isolate);
v8::HandleScope handle_scope(isolate);
v8::Local<v8::Context> context = v8::Context::New(isolate);
v8::Context::Scope context_scope(context);
i::Isolate* i_isolate = reinterpret_cast<i::Isolate*>(isolate);
CHECK(!i_isolate->NeedsDetailedOptimizedCodeLineInfo());
int non_detailed_positions = GetSourcePositionEntryCount(i_isolate, source);
v8::CpuProfiler::UseDetailedSourcePositionsForProfiling(isolate);
CHECK(i_isolate->NeedsDetailedOptimizedCodeLineInfo());
int detailed_positions = GetSourcePositionEntryCount(i_isolate, source);
CHECK((non_detailed_positions == -1 && detailed_positions == -1) ||
non_detailed_positions < detailed_positions);
}
isolate->Dispose();
}
UNINITIALIZED_TEST(DetailedSourcePositionAPI_Inlining) {
i::FLAG_detailed_line_info = false;
i::FLAG_turbo_inlining = true;
i::FLAG_stress_inline = true;
i::FLAG_always_opt = false;
i::FLAG_allow_natives_syntax = true;
v8::Isolate::CreateParams create_params;
create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
v8::Isolate* isolate = v8::Isolate::New(create_params);
const char* source = R"(
function foo(x) {
return bar(x) + 1;
}
function bar(x) {
var y = 1;
for (var i = 0; i < x; ++i) {
y = y * x;
}
return x;
}
%EnsureFeedbackVectorForFunction(bar);
%PrepareFunctionForOptimization(foo);
foo(5);
%OptimizeFunctionOnNextCall(foo);
foo(5);
foo;
)";
{
v8::Isolate::Scope isolate_scope(isolate);
v8::HandleScope handle_scope(isolate);
v8::Local<v8::Context> context = v8::Context::New(isolate);
v8::Context::Scope context_scope(context);
i::Isolate* i_isolate = reinterpret_cast<i::Isolate*>(isolate);
CHECK(!i_isolate->NeedsDetailedOptimizedCodeLineInfo());
int non_detailed_positions =
GetSourcePositionEntryCount(i_isolate, source, EntryCountMode::kAll);
int non_detailed_inlined_positions = GetSourcePositionEntryCount(
i_isolate, source, EntryCountMode::kOnlyInlined);
v8::CpuProfiler::UseDetailedSourcePositionsForProfiling(isolate);
CHECK(i_isolate->NeedsDetailedOptimizedCodeLineInfo());
int detailed_positions =
GetSourcePositionEntryCount(i_isolate, source, EntryCountMode::kAll);
int detailed_inlined_positions = GetSourcePositionEntryCount(
i_isolate, source, EntryCountMode::kOnlyInlined);
if (non_detailed_positions == -1) {
CHECK_EQ(non_detailed_positions, detailed_positions);
} else {
CHECK_LT(non_detailed_positions, detailed_positions);
CHECK_LT(non_detailed_inlined_positions, detailed_inlined_positions);
}
}
isolate->Dispose();
}
} // namespace test_cpu_profiler
} // namespace internal
} // namespace v8