1 // Copyright 2010 the V8 project authors. All rights reserved. 2 // Redistribution and use in source and binary forms, with or without 3 // modification, are permitted provided that the following conditions are 4 // met: 5 // 6 // * Redistributions of source code must retain the above copyright 7 // notice, this list of conditions and the following disclaimer. 8 // * Redistributions in binary form must reproduce the above 9 // copyright notice, this list of conditions and the following 10 // disclaimer in the documentation and/or other materials provided 11 // with the distribution. 12 // * Neither the name of Google Inc. nor the names of its 13 // contributors may be used to endorse or promote products derived 14 // from this software without specific prior written permission. 15 // 16 // THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS 17 // "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT 18 // LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR 19 // A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT 20 // OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, 21 // SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT 22 // LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, 23 // DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY 24 // THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT 25 // (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE 26 // OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. 27 // 28 // Tests of profiles generator and utilities. 29 30 #include "src/v8.h" 31 32 #include "include/v8-profiler.h" 33 #include "src/base/platform/platform.h" 34 #include "src/base/smart-pointers.h" 35 #include "src/deoptimizer.h" 36 #include "src/profiler/cpu-profiler-inl.h" 37 #include "src/utils.h" 38 #include "test/cctest/cctest.h" 39 #include "test/cctest/profiler-extension.h" 40 using i::CodeEntry; 41 using i::CpuProfile; 42 using i::CpuProfiler; 43 using i::CpuProfilesCollection; 44 using i::Heap; 45 using i::ProfileGenerator; 46 using i::ProfileNode; 47 using i::ProfilerEventsProcessor; 48 using i::ScopedVector; 49 using i::Vector; 50 using v8::base::SmartPointer; 51 52 53 // Helper methods 54 static v8::Local<v8::Function> GetFunction(v8::Local<v8::Context> env, 55 const char* name) { 56 return v8::Local<v8::Function>::Cast( 57 env->Global()->Get(env, v8_str(name)).ToLocalChecked()); 58 } 59 60 61 static size_t offset(const char* src, const char* substring) { 62 const char* it = strstr(src, substring); 63 CHECK(it); 64 return static_cast<size_t>(it - src); 65 } 66 67 68 static const char* reason(const i::Deoptimizer::DeoptReason reason) { 69 return i::Deoptimizer::GetDeoptReason(reason); 70 } 71 72 73 TEST(StartStop) { 74 i::Isolate* isolate = CcTest::i_isolate(); 75 CpuProfilesCollection profiles(isolate->heap()); 76 ProfileGenerator generator(&profiles); 77 SmartPointer<ProfilerEventsProcessor> processor(new ProfilerEventsProcessor( 78 &generator, NULL, v8::base::TimeDelta::FromMicroseconds(100))); 79 processor->Start(); 80 processor->StopSynchronously(); 81 } 82 83 84 static void EnqueueTickSampleEvent(ProfilerEventsProcessor* proc, 85 i::Address frame1, 86 i::Address frame2 = NULL, 87 i::Address frame3 = NULL) { 88 i::TickSample* sample = proc->StartTickSample(); 89 sample->pc = frame1; 90 sample->tos = frame1; 91 sample->frames_count = 0; 92 if (frame2 != NULL) { 93 sample->stack[0] = frame2; 94 sample->frames_count = 1; 95 } 96 if (frame3 != NULL) { 97 sample->stack[1] = frame3; 98 sample->frames_count = 2; 99 } 100 proc->FinishTickSample(); 101 } 102 103 namespace { 104 105 class TestSetup { 106 public: 107 TestSetup() 108 : old_flag_prof_browser_mode_(i::FLAG_prof_browser_mode) { 109 i::FLAG_prof_browser_mode = false; 110 } 111 112 ~TestSetup() { 113 i::FLAG_prof_browser_mode = old_flag_prof_browser_mode_; 114 } 115 116 private: 117 bool old_flag_prof_browser_mode_; 118 }; 119 120 } // namespace 121 122 123 i::Code* CreateCode(LocalContext* env) { 124 static int counter = 0; 125 i::EmbeddedVector<char, 256> script; 126 i::EmbeddedVector<char, 32> name; 127 128 i::SNPrintF(name, "function_%d", ++counter); 129 const char* name_start = name.start(); 130 i::SNPrintF(script, 131 "function %s() {\n" 132 "var counter = 0;\n" 133 "for (var i = 0; i < %d; ++i) counter += i;\n" 134 "return '%s_' + counter;\n" 135 "}\n" 136 "%s();\n", name_start, counter, name_start, name_start); 137 CompileRun(script.start()); 138 139 i::Handle<i::JSFunction> fun = i::Handle<i::JSFunction>::cast( 140 v8::Utils::OpenHandle(*GetFunction(env->local(), name_start))); 141 return fun->code(); 142 } 143 144 145 TEST(CodeEvents) { 146 CcTest::InitializeVM(); 147 LocalContext env; 148 i::Isolate* isolate = CcTest::i_isolate(); 149 i::Factory* factory = isolate->factory(); 150 TestSetup test_setup; 151 152 i::HandleScope scope(isolate); 153 154 i::Code* aaa_code = CreateCode(&env); 155 i::Code* comment_code = CreateCode(&env); 156 i::Code* args5_code = CreateCode(&env); 157 i::Code* comment2_code = CreateCode(&env); 158 i::Code* moved_code = CreateCode(&env); 159 i::Code* args3_code = CreateCode(&env); 160 i::Code* args4_code = CreateCode(&env); 161 162 CpuProfilesCollection* profiles = new CpuProfilesCollection(isolate->heap()); 163 profiles->StartProfiling("", false); 164 ProfileGenerator generator(profiles); 165 SmartPointer<ProfilerEventsProcessor> processor(new ProfilerEventsProcessor( 166 &generator, NULL, v8::base::TimeDelta::FromMicroseconds(100))); 167 processor->Start(); 168 CpuProfiler profiler(isolate, profiles, &generator, processor.get()); 169 170 // Enqueue code creation events. 171 const char* aaa_str = "aaa"; 172 i::Handle<i::String> aaa_name = factory->NewStringFromAsciiChecked(aaa_str); 173 profiler.CodeCreateEvent(i::Logger::FUNCTION_TAG, aaa_code, *aaa_name); 174 profiler.CodeCreateEvent(i::Logger::BUILTIN_TAG, comment_code, "comment"); 175 profiler.CodeCreateEvent(i::Logger::STUB_TAG, args5_code, 5); 176 profiler.CodeCreateEvent(i::Logger::BUILTIN_TAG, comment2_code, "comment2"); 177 profiler.CodeMoveEvent(comment2_code->address(), moved_code->address()); 178 profiler.CodeCreateEvent(i::Logger::STUB_TAG, args3_code, 3); 179 profiler.CodeCreateEvent(i::Logger::STUB_TAG, args4_code, 4); 180 181 // Enqueue a tick event to enable code events processing. 182 EnqueueTickSampleEvent(processor.get(), aaa_code->address()); 183 184 processor->StopSynchronously(); 185 186 // Check the state of profile generator. 187 CodeEntry* aaa = generator.code_map()->FindEntry(aaa_code->address()); 188 CHECK(aaa); 189 CHECK_EQ(0, strcmp(aaa_str, aaa->name())); 190 191 CodeEntry* comment = generator.code_map()->FindEntry(comment_code->address()); 192 CHECK(comment); 193 CHECK_EQ(0, strcmp("comment", comment->name())); 194 195 CodeEntry* args5 = generator.code_map()->FindEntry(args5_code->address()); 196 CHECK(args5); 197 CHECK_EQ(0, strcmp("5", args5->name())); 198 199 CHECK(!generator.code_map()->FindEntry(comment2_code->address())); 200 201 CodeEntry* comment2 = generator.code_map()->FindEntry(moved_code->address()); 202 CHECK(comment2); 203 CHECK_EQ(0, strcmp("comment2", comment2->name())); 204 } 205 206 207 template<typename T> 208 static int CompareProfileNodes(const T* p1, const T* p2) { 209 return strcmp((*p1)->entry()->name(), (*p2)->entry()->name()); 210 } 211 212 213 TEST(TickEvents) { 214 TestSetup test_setup; 215 LocalContext env; 216 i::Isolate* isolate = CcTest::i_isolate(); 217 i::HandleScope scope(isolate); 218 219 i::Code* frame1_code = CreateCode(&env); 220 i::Code* frame2_code = CreateCode(&env); 221 i::Code* frame3_code = CreateCode(&env); 222 223 CpuProfilesCollection* profiles = new CpuProfilesCollection(isolate->heap()); 224 profiles->StartProfiling("", false); 225 ProfileGenerator generator(profiles); 226 SmartPointer<ProfilerEventsProcessor> processor(new ProfilerEventsProcessor( 227 &generator, NULL, v8::base::TimeDelta::FromMicroseconds(100))); 228 processor->Start(); 229 CpuProfiler profiler(isolate, profiles, &generator, processor.get()); 230 231 profiler.CodeCreateEvent(i::Logger::BUILTIN_TAG, frame1_code, "bbb"); 232 profiler.CodeCreateEvent(i::Logger::STUB_TAG, frame2_code, 5); 233 profiler.CodeCreateEvent(i::Logger::BUILTIN_TAG, frame3_code, "ddd"); 234 235 EnqueueTickSampleEvent(processor.get(), frame1_code->instruction_start()); 236 EnqueueTickSampleEvent( 237 processor.get(), 238 frame2_code->instruction_start() + frame2_code->ExecutableSize() / 2, 239 frame1_code->instruction_start() + frame2_code->ExecutableSize() / 2); 240 EnqueueTickSampleEvent( 241 processor.get(), 242 frame3_code->instruction_end() - 1, 243 frame2_code->instruction_end() - 1, 244 frame1_code->instruction_end() - 1); 245 246 processor->StopSynchronously(); 247 CpuProfile* profile = profiles->StopProfiling(""); 248 CHECK(profile); 249 250 // Check call trees. 251 const i::List<ProfileNode*>* top_down_root_children = 252 profile->top_down()->root()->children(); 253 CHECK_EQ(1, top_down_root_children->length()); 254 CHECK_EQ(0, strcmp("bbb", top_down_root_children->last()->entry()->name())); 255 const i::List<ProfileNode*>* top_down_bbb_children = 256 top_down_root_children->last()->children(); 257 CHECK_EQ(1, top_down_bbb_children->length()); 258 CHECK_EQ(0, strcmp("5", top_down_bbb_children->last()->entry()->name())); 259 const i::List<ProfileNode*>* top_down_stub_children = 260 top_down_bbb_children->last()->children(); 261 CHECK_EQ(1, top_down_stub_children->length()); 262 CHECK_EQ(0, strcmp("ddd", top_down_stub_children->last()->entry()->name())); 263 const i::List<ProfileNode*>* top_down_ddd_children = 264 top_down_stub_children->last()->children(); 265 CHECK_EQ(0, top_down_ddd_children->length()); 266 } 267 268 269 // http://crbug/51594 270 // This test must not crash. 271 TEST(CrashIfStoppingLastNonExistentProfile) { 272 CcTest::InitializeVM(); 273 TestSetup test_setup; 274 CpuProfiler* profiler = CcTest::i_isolate()->cpu_profiler(); 275 profiler->StartProfiling("1"); 276 profiler->StopProfiling("2"); 277 profiler->StartProfiling("1"); 278 profiler->StopProfiling(""); 279 } 280 281 282 // http://code.google.com/p/v8/issues/detail?id=1398 283 // Long stacks (exceeding max frames limit) must not be erased. 284 TEST(Issue1398) { 285 TestSetup test_setup; 286 LocalContext env; 287 i::Isolate* isolate = CcTest::i_isolate(); 288 i::HandleScope scope(isolate); 289 290 i::Code* code = CreateCode(&env); 291 292 CpuProfilesCollection* profiles = new CpuProfilesCollection(isolate->heap()); 293 profiles->StartProfiling("", false); 294 ProfileGenerator generator(profiles); 295 SmartPointer<ProfilerEventsProcessor> processor(new ProfilerEventsProcessor( 296 &generator, NULL, v8::base::TimeDelta::FromMicroseconds(100))); 297 processor->Start(); 298 CpuProfiler profiler(isolate, profiles, &generator, processor.get()); 299 300 profiler.CodeCreateEvent(i::Logger::BUILTIN_TAG, code, "bbb"); 301 302 i::TickSample* sample = processor->StartTickSample(); 303 sample->pc = code->address(); 304 sample->tos = 0; 305 sample->frames_count = i::TickSample::kMaxFramesCount; 306 for (unsigned i = 0; i < sample->frames_count; ++i) { 307 sample->stack[i] = code->address(); 308 } 309 processor->FinishTickSample(); 310 311 processor->StopSynchronously(); 312 CpuProfile* profile = profiles->StopProfiling(""); 313 CHECK(profile); 314 315 unsigned actual_depth = 0; 316 const ProfileNode* node = profile->top_down()->root(); 317 while (node->children()->length() > 0) { 318 node = node->children()->last(); 319 ++actual_depth; 320 } 321 322 CHECK_EQ(1 + i::TickSample::kMaxFramesCount, actual_depth); // +1 for PC. 323 } 324 325 326 TEST(DeleteAllCpuProfiles) { 327 CcTest::InitializeVM(); 328 TestSetup test_setup; 329 CpuProfiler* profiler = CcTest::i_isolate()->cpu_profiler(); 330 CHECK_EQ(0, profiler->GetProfilesCount()); 331 profiler->DeleteAllProfiles(); 332 CHECK_EQ(0, profiler->GetProfilesCount()); 333 334 profiler->StartProfiling("1"); 335 profiler->StopProfiling("1"); 336 CHECK_EQ(1, profiler->GetProfilesCount()); 337 profiler->DeleteAllProfiles(); 338 CHECK_EQ(0, profiler->GetProfilesCount()); 339 profiler->StartProfiling("1"); 340 profiler->StartProfiling("2"); 341 profiler->StopProfiling("2"); 342 profiler->StopProfiling("1"); 343 CHECK_EQ(2, profiler->GetProfilesCount()); 344 profiler->DeleteAllProfiles(); 345 CHECK_EQ(0, profiler->GetProfilesCount()); 346 347 // Test profiling cancellation by the 'delete' command. 348 profiler->StartProfiling("1"); 349 profiler->StartProfiling("2"); 350 CHECK_EQ(0, profiler->GetProfilesCount()); 351 profiler->DeleteAllProfiles(); 352 CHECK_EQ(0, profiler->GetProfilesCount()); 353 } 354 355 356 static bool FindCpuProfile(v8::CpuProfiler* v8profiler, 357 const v8::CpuProfile* v8profile) { 358 i::CpuProfiler* profiler = reinterpret_cast<i::CpuProfiler*>(v8profiler); 359 const i::CpuProfile* profile = 360 reinterpret_cast<const i::CpuProfile*>(v8profile); 361 int length = profiler->GetProfilesCount(); 362 for (int i = 0; i < length; i++) { 363 if (profile == profiler->GetProfile(i)) 364 return true; 365 } 366 return false; 367 } 368 369 370 TEST(DeleteCpuProfile) { 371 LocalContext env; 372 v8::HandleScope scope(env->GetIsolate()); 373 v8::CpuProfiler* cpu_profiler = env->GetIsolate()->GetCpuProfiler(); 374 i::CpuProfiler* iprofiler = reinterpret_cast<i::CpuProfiler*>(cpu_profiler); 375 376 CHECK_EQ(0, iprofiler->GetProfilesCount()); 377 v8::Local<v8::String> name1 = v8_str("1"); 378 cpu_profiler->StartProfiling(name1); 379 v8::CpuProfile* p1 = cpu_profiler->StopProfiling(name1); 380 CHECK(p1); 381 CHECK_EQ(1, iprofiler->GetProfilesCount()); 382 CHECK(FindCpuProfile(cpu_profiler, p1)); 383 p1->Delete(); 384 CHECK_EQ(0, iprofiler->GetProfilesCount()); 385 386 v8::Local<v8::String> name2 = v8_str("2"); 387 cpu_profiler->StartProfiling(name2); 388 v8::CpuProfile* p2 = cpu_profiler->StopProfiling(name2); 389 CHECK(p2); 390 CHECK_EQ(1, iprofiler->GetProfilesCount()); 391 CHECK(FindCpuProfile(cpu_profiler, p2)); 392 v8::Local<v8::String> name3 = v8_str("3"); 393 cpu_profiler->StartProfiling(name3); 394 v8::CpuProfile* p3 = cpu_profiler->StopProfiling(name3); 395 CHECK(p3); 396 CHECK_EQ(2, iprofiler->GetProfilesCount()); 397 CHECK_NE(p2, p3); 398 CHECK(FindCpuProfile(cpu_profiler, p3)); 399 CHECK(FindCpuProfile(cpu_profiler, p2)); 400 p2->Delete(); 401 CHECK_EQ(1, iprofiler->GetProfilesCount()); 402 CHECK(!FindCpuProfile(cpu_profiler, p2)); 403 CHECK(FindCpuProfile(cpu_profiler, p3)); 404 p3->Delete(); 405 CHECK_EQ(0, iprofiler->GetProfilesCount()); 406 } 407 408 409 TEST(ProfileStartEndTime) { 410 LocalContext env; 411 v8::HandleScope scope(env->GetIsolate()); 412 v8::CpuProfiler* cpu_profiler = env->GetIsolate()->GetCpuProfiler(); 413 414 v8::Local<v8::String> profile_name = v8_str("test"); 415 cpu_profiler->StartProfiling(profile_name); 416 const v8::CpuProfile* profile = cpu_profiler->StopProfiling(profile_name); 417 CHECK(profile->GetStartTime() <= profile->GetEndTime()); 418 } 419 420 421 static v8::CpuProfile* RunProfiler(v8::Local<v8::Context> env, 422 v8::Local<v8::Function> function, 423 v8::Local<v8::Value> argv[], int argc, 424 unsigned min_js_samples, 425 bool collect_samples = false) { 426 v8::CpuProfiler* cpu_profiler = env->GetIsolate()->GetCpuProfiler(); 427 v8::Local<v8::String> profile_name = v8_str("my_profile"); 428 429 cpu_profiler->StartProfiling(profile_name, collect_samples); 430 431 i::Sampler* sampler = 432 reinterpret_cast<i::Isolate*>(env->GetIsolate())->logger()->sampler(); 433 sampler->StartCountingSamples(); 434 do { 435 function->Call(env, env->Global(), argc, argv).ToLocalChecked(); 436 } while (sampler->js_and_external_sample_count() < min_js_samples); 437 438 v8::CpuProfile* profile = cpu_profiler->StopProfiling(profile_name); 439 440 CHECK(profile); 441 // Dump collected profile to have a better diagnostic in case of failure. 442 reinterpret_cast<i::CpuProfile*>(profile)->Print(); 443 444 return profile; 445 } 446 447 448 static bool ContainsString(v8::Local<v8::Context> context, 449 v8::Local<v8::String> string, 450 const Vector<v8::Local<v8::String> >& vector) { 451 for (int i = 0; i < vector.length(); i++) { 452 if (string->Equals(context, vector[i]).FromJust()) return true; 453 } 454 return false; 455 } 456 457 458 static void CheckChildrenNames(v8::Local<v8::Context> context, 459 const v8::CpuProfileNode* node, 460 const Vector<v8::Local<v8::String> >& names) { 461 int count = node->GetChildrenCount(); 462 for (int i = 0; i < count; i++) { 463 v8::Local<v8::String> name = node->GetChild(i)->GetFunctionName(); 464 if (!ContainsString(context, name, names)) { 465 char buffer[100]; 466 i::SNPrintF(Vector<char>(buffer, arraysize(buffer)), 467 "Unexpected child '%s' found in '%s'", 468 *v8::String::Utf8Value(name), 469 *v8::String::Utf8Value(node->GetFunctionName())); 470 FATAL(buffer); 471 } 472 // Check that there are no duplicates. 473 for (int j = 0; j < count; j++) { 474 if (j == i) continue; 475 if (name->Equals(context, node->GetChild(j)->GetFunctionName()) 476 .FromJust()) { 477 char buffer[100]; 478 i::SNPrintF(Vector<char>(buffer, arraysize(buffer)), 479 "Second child with the same name '%s' found in '%s'", 480 *v8::String::Utf8Value(name), 481 *v8::String::Utf8Value(node->GetFunctionName())); 482 FATAL(buffer); 483 } 484 } 485 } 486 } 487 488 489 static const v8::CpuProfileNode* FindChild(v8::Local<v8::Context> context, 490 const v8::CpuProfileNode* node, 491 const char* name) { 492 int count = node->GetChildrenCount(); 493 v8::Local<v8::String> nameHandle = v8_str(name); 494 for (int i = 0; i < count; i++) { 495 const v8::CpuProfileNode* child = node->GetChild(i); 496 if (nameHandle->Equals(context, child->GetFunctionName()).FromJust()) { 497 return child; 498 } 499 } 500 return NULL; 501 } 502 503 504 static const v8::CpuProfileNode* GetChild(v8::Local<v8::Context> context, 505 const v8::CpuProfileNode* node, 506 const char* name) { 507 const v8::CpuProfileNode* result = FindChild(context, node, name); 508 if (!result) { 509 char buffer[100]; 510 i::SNPrintF(Vector<char>(buffer, arraysize(buffer)), 511 "Failed to GetChild: %s", name); 512 FATAL(buffer); 513 } 514 return result; 515 } 516 517 518 static void CheckSimpleBranch(v8::Local<v8::Context> context, 519 const v8::CpuProfileNode* node, 520 const char* names[], int length) { 521 for (int i = 0; i < length; i++) { 522 const char* name = names[i]; 523 node = GetChild(context, node, name); 524 int expectedChildrenCount = (i == length - 1) ? 0 : 1; 525 CHECK_EQ(expectedChildrenCount, node->GetChildrenCount()); 526 } 527 } 528 529 530 static const ProfileNode* GetSimpleBranch(v8::Local<v8::Context> context, 531 v8::CpuProfile* profile, 532 const char* names[], int length) { 533 const v8::CpuProfileNode* node = profile->GetTopDownRoot(); 534 for (int i = 0; i < length; i++) { 535 node = GetChild(context, node, names[i]); 536 } 537 return reinterpret_cast<const ProfileNode*>(node); 538 } 539 540 541 static const char* cpu_profiler_test_source = "function loop(timeout) {\n" 542 " this.mmm = 0;\n" 543 " var start = Date.now();\n" 544 " while (Date.now() - start < timeout) {\n" 545 " var n = 100*1000;\n" 546 " while(n > 1) {\n" 547 " n--;\n" 548 " this.mmm += n * n * n;\n" 549 " }\n" 550 " }\n" 551 "}\n" 552 "function delay() { try { loop(10); } catch(e) { } }\n" 553 "function bar() { delay(); }\n" 554 "function baz() { delay(); }\n" 555 "function foo() {\n" 556 " try {\n" 557 " delay();\n" 558 " bar();\n" 559 " delay();\n" 560 " baz();\n" 561 " } catch (e) { }\n" 562 "}\n" 563 "function start(timeout) {\n" 564 " var start = Date.now();\n" 565 " do {\n" 566 " foo();\n" 567 " var duration = Date.now() - start;\n" 568 " } while (duration < timeout);\n" 569 " return duration;\n" 570 "}\n"; 571 572 573 // Check that the profile tree for the script above will look like the 574 // following: 575 // 576 // [Top down]: 577 // 1062 0 (root) [-1] 578 // 1054 0 start [-1] 579 // 1054 1 foo [-1] 580 // 265 0 baz [-1] 581 // 265 1 delay [-1] 582 // 264 264 loop [-1] 583 // 525 3 delay [-1] 584 // 522 522 loop [-1] 585 // 263 0 bar [-1] 586 // 263 1 delay [-1] 587 // 262 262 loop [-1] 588 // 2 2 (program) [-1] 589 // 6 6 (garbage collector) [-1] 590 TEST(CollectCpuProfile) { 591 LocalContext env; 592 v8::HandleScope scope(env->GetIsolate()); 593 594 CompileRun(cpu_profiler_test_source); 595 v8::Local<v8::Function> function = GetFunction(env.local(), "start"); 596 597 int32_t profiling_interval_ms = 200; 598 v8::Local<v8::Value> args[] = { 599 v8::Integer::New(env->GetIsolate(), profiling_interval_ms)}; 600 v8::CpuProfile* profile = 601 RunProfiler(env.local(), function, args, arraysize(args), 200); 602 function->Call(env.local(), env->Global(), arraysize(args), args) 603 .ToLocalChecked(); 604 605 const v8::CpuProfileNode* root = profile->GetTopDownRoot(); 606 607 ScopedVector<v8::Local<v8::String> > names(3); 608 names[0] = v8_str(ProfileGenerator::kGarbageCollectorEntryName); 609 names[1] = v8_str(ProfileGenerator::kProgramEntryName); 610 names[2] = v8_str("start"); 611 CheckChildrenNames(env.local(), root, names); 612 613 const v8::CpuProfileNode* startNode = GetChild(env.local(), root, "start"); 614 CHECK_EQ(1, startNode->GetChildrenCount()); 615 616 const v8::CpuProfileNode* fooNode = GetChild(env.local(), startNode, "foo"); 617 CHECK_EQ(3, fooNode->GetChildrenCount()); 618 619 const char* barBranch[] = { "bar", "delay", "loop" }; 620 CheckSimpleBranch(env.local(), fooNode, barBranch, arraysize(barBranch)); 621 const char* bazBranch[] = { "baz", "delay", "loop" }; 622 CheckSimpleBranch(env.local(), fooNode, bazBranch, arraysize(bazBranch)); 623 const char* delayBranch[] = { "delay", "loop" }; 624 CheckSimpleBranch(env.local(), fooNode, delayBranch, arraysize(delayBranch)); 625 626 profile->Delete(); 627 } 628 629 630 static const char* hot_deopt_no_frame_entry_test_source = 631 "function foo(a, b) {\n" 632 " try {\n" 633 " return a + b;\n" 634 " } catch (e) { }\n" 635 "}\n" 636 "function start(timeout) {\n" 637 " var start = Date.now();\n" 638 " do {\n" 639 " for (var i = 1; i < 1000; ++i) foo(1, i);\n" 640 " var duration = Date.now() - start;\n" 641 " } while (duration < timeout);\n" 642 " return duration;\n" 643 "}\n"; 644 645 // Check that the profile tree for the script above will look like the 646 // following: 647 // 648 // [Top down]: 649 // 1062 0 (root) [-1] 650 // 1054 0 start [-1] 651 // 1054 1 foo [-1] 652 // 2 2 (program) [-1] 653 // 6 6 (garbage collector) [-1] 654 // 655 // The test checks no FP ranges are present in a deoptimized funcion. 656 // If 'foo' has no ranges the samples falling into the prologue will miss the 657 // 'start' function on the stack, so 'foo' will be attached to the (root). 658 TEST(HotDeoptNoFrameEntry) { 659 LocalContext env; 660 v8::HandleScope scope(env->GetIsolate()); 661 662 CompileRun(hot_deopt_no_frame_entry_test_source); 663 v8::Local<v8::Function> function = GetFunction(env.local(), "start"); 664 665 int32_t profiling_interval_ms = 200; 666 v8::Local<v8::Value> args[] = { 667 v8::Integer::New(env->GetIsolate(), profiling_interval_ms)}; 668 v8::CpuProfile* profile = 669 RunProfiler(env.local(), function, args, arraysize(args), 200); 670 function->Call(env.local(), env->Global(), arraysize(args), args) 671 .ToLocalChecked(); 672 673 const v8::CpuProfileNode* root = profile->GetTopDownRoot(); 674 675 ScopedVector<v8::Local<v8::String> > names(3); 676 names[0] = v8_str(ProfileGenerator::kGarbageCollectorEntryName); 677 names[1] = v8_str(ProfileGenerator::kProgramEntryName); 678 names[2] = v8_str("start"); 679 CheckChildrenNames(env.local(), root, names); 680 681 const v8::CpuProfileNode* startNode = GetChild(env.local(), root, "start"); 682 CHECK_EQ(1, startNode->GetChildrenCount()); 683 684 GetChild(env.local(), startNode, "foo"); 685 686 profile->Delete(); 687 } 688 689 690 TEST(CollectCpuProfileSamples) { 691 LocalContext env; 692 v8::HandleScope scope(env->GetIsolate()); 693 694 CompileRun(cpu_profiler_test_source); 695 v8::Local<v8::Function> function = GetFunction(env.local(), "start"); 696 697 int32_t profiling_interval_ms = 200; 698 v8::Local<v8::Value> args[] = { 699 v8::Integer::New(env->GetIsolate(), profiling_interval_ms)}; 700 v8::CpuProfile* profile = 701 RunProfiler(env.local(), function, args, arraysize(args), 200, true); 702 703 CHECK_LE(200, profile->GetSamplesCount()); 704 uint64_t end_time = profile->GetEndTime(); 705 uint64_t current_time = profile->GetStartTime(); 706 CHECK_LE(current_time, end_time); 707 for (int i = 0; i < profile->GetSamplesCount(); i++) { 708 CHECK(profile->GetSample(i)); 709 uint64_t timestamp = profile->GetSampleTimestamp(i); 710 CHECK_LE(current_time, timestamp); 711 CHECK_LE(timestamp, end_time); 712 current_time = timestamp; 713 } 714 715 profile->Delete(); 716 } 717 718 719 static const char* cpu_profiler_test_source2 = "function loop() {}\n" 720 "function delay() { loop(); }\n" 721 "function start(count) {\n" 722 " var k = 0;\n" 723 " do {\n" 724 " delay();\n" 725 " } while (++k < count*100*1000);\n" 726 "}\n"; 727 728 // Check that the profile tree doesn't contain unexpected traces: 729 // - 'loop' can be called only by 'delay' 730 // - 'delay' may be called only by 'start' 731 // The profile will look like the following: 732 // 733 // [Top down]: 734 // 135 0 (root) [-1] #1 735 // 121 72 start [-1] #3 736 // 49 33 delay [-1] #4 737 // 16 16 loop [-1] #5 738 // 14 14 (program) [-1] #2 739 TEST(SampleWhenFrameIsNotSetup) { 740 LocalContext env; 741 v8::HandleScope scope(env->GetIsolate()); 742 743 CompileRun(cpu_profiler_test_source2); 744 v8::Local<v8::Function> function = GetFunction(env.local(), "start"); 745 746 int32_t repeat_count = 100; 747 #if defined(USE_SIMULATOR) 748 // Simulators are much slower. 749 repeat_count = 1; 750 #endif 751 v8::Local<v8::Value> args[] = { 752 v8::Integer::New(env->GetIsolate(), repeat_count)}; 753 v8::CpuProfile* profile = 754 RunProfiler(env.local(), function, args, arraysize(args), 100); 755 756 const v8::CpuProfileNode* root = profile->GetTopDownRoot(); 757 758 ScopedVector<v8::Local<v8::String> > names(3); 759 names[0] = v8_str(ProfileGenerator::kGarbageCollectorEntryName); 760 names[1] = v8_str(ProfileGenerator::kProgramEntryName); 761 names[2] = v8_str("start"); 762 CheckChildrenNames(env.local(), root, names); 763 764 const v8::CpuProfileNode* startNode = FindChild(env.local(), root, "start"); 765 // On slow machines there may be no meaningfull samples at all, skip the 766 // check there. 767 if (startNode && startNode->GetChildrenCount() > 0) { 768 CHECK_EQ(1, startNode->GetChildrenCount()); 769 const v8::CpuProfileNode* delayNode = 770 GetChild(env.local(), startNode, "delay"); 771 if (delayNode->GetChildrenCount() > 0) { 772 CHECK_EQ(1, delayNode->GetChildrenCount()); 773 GetChild(env.local(), delayNode, "loop"); 774 } 775 } 776 777 profile->Delete(); 778 } 779 780 781 static const char* native_accessor_test_source = "function start(count) {\n" 782 " for (var i = 0; i < count; i++) {\n" 783 " var o = instance.foo;\n" 784 " instance.foo = o + 1;\n" 785 " }\n" 786 "}\n"; 787 788 789 class TestApiCallbacks { 790 public: 791 explicit TestApiCallbacks(int min_duration_ms) 792 : min_duration_ms_(min_duration_ms), 793 is_warming_up_(false) {} 794 795 static void Getter(v8::Local<v8::String> name, 796 const v8::PropertyCallbackInfo<v8::Value>& info) { 797 TestApiCallbacks* data = fromInfo(info); 798 data->Wait(); 799 } 800 801 static void Setter(v8::Local<v8::String> name, 802 v8::Local<v8::Value> value, 803 const v8::PropertyCallbackInfo<void>& info) { 804 TestApiCallbacks* data = fromInfo(info); 805 data->Wait(); 806 } 807 808 static void Callback(const v8::FunctionCallbackInfo<v8::Value>& info) { 809 TestApiCallbacks* data = fromInfo(info); 810 data->Wait(); 811 } 812 813 void set_warming_up(bool value) { is_warming_up_ = value; } 814 815 private: 816 void Wait() { 817 if (is_warming_up_) return; 818 double start = v8::base::OS::TimeCurrentMillis(); 819 double duration = 0; 820 while (duration < min_duration_ms_) { 821 v8::base::OS::Sleep(v8::base::TimeDelta::FromMilliseconds(1)); 822 duration = v8::base::OS::TimeCurrentMillis() - start; 823 } 824 } 825 826 template<typename T> 827 static TestApiCallbacks* fromInfo(const T& info) { 828 void* data = v8::External::Cast(*info.Data())->Value(); 829 return reinterpret_cast<TestApiCallbacks*>(data); 830 } 831 832 int min_duration_ms_; 833 bool is_warming_up_; 834 }; 835 836 837 // Test that native accessors are properly reported in the CPU profile. 838 // This test checks the case when the long-running accessors are called 839 // only once and the optimizer doesn't have chance to change the invocation 840 // code. 841 TEST(NativeAccessorUninitializedIC) { 842 LocalContext env; 843 v8::Isolate* isolate = env->GetIsolate(); 844 v8::HandleScope scope(isolate); 845 846 v8::Local<v8::FunctionTemplate> func_template = 847 v8::FunctionTemplate::New(isolate); 848 v8::Local<v8::ObjectTemplate> instance_template = 849 func_template->InstanceTemplate(); 850 851 TestApiCallbacks accessors(100); 852 v8::Local<v8::External> data = 853 v8::External::New(isolate, &accessors); 854 instance_template->SetAccessor(v8_str("foo"), &TestApiCallbacks::Getter, 855 &TestApiCallbacks::Setter, data); 856 v8::Local<v8::Function> func = 857 func_template->GetFunction(env.local()).ToLocalChecked(); 858 v8::Local<v8::Object> instance = 859 func->NewInstance(env.local()).ToLocalChecked(); 860 env->Global()->Set(env.local(), v8_str("instance"), instance).FromJust(); 861 862 CompileRun(native_accessor_test_source); 863 v8::Local<v8::Function> function = GetFunction(env.local(), "start"); 864 865 int32_t repeat_count = 1; 866 v8::Local<v8::Value> args[] = {v8::Integer::New(isolate, repeat_count)}; 867 v8::CpuProfile* profile = 868 RunProfiler(env.local(), function, args, arraysize(args), 180); 869 870 const v8::CpuProfileNode* root = profile->GetTopDownRoot(); 871 const v8::CpuProfileNode* startNode = GetChild(env.local(), root, "start"); 872 GetChild(env.local(), startNode, "get foo"); 873 GetChild(env.local(), startNode, "set foo"); 874 875 profile->Delete(); 876 } 877 878 879 // Test that native accessors are properly reported in the CPU profile. 880 // This test makes sure that the accessors are called enough times to become 881 // hot and to trigger optimizations. 882 TEST(NativeAccessorMonomorphicIC) { 883 LocalContext env; 884 v8::Isolate* isolate = env->GetIsolate(); 885 v8::HandleScope scope(isolate); 886 887 v8::Local<v8::FunctionTemplate> func_template = 888 v8::FunctionTemplate::New(isolate); 889 v8::Local<v8::ObjectTemplate> instance_template = 890 func_template->InstanceTemplate(); 891 892 TestApiCallbacks accessors(1); 893 v8::Local<v8::External> data = 894 v8::External::New(isolate, &accessors); 895 instance_template->SetAccessor(v8_str("foo"), &TestApiCallbacks::Getter, 896 &TestApiCallbacks::Setter, data); 897 v8::Local<v8::Function> func = 898 func_template->GetFunction(env.local()).ToLocalChecked(); 899 v8::Local<v8::Object> instance = 900 func->NewInstance(env.local()).ToLocalChecked(); 901 env->Global()->Set(env.local(), v8_str("instance"), instance).FromJust(); 902 903 CompileRun(native_accessor_test_source); 904 v8::Local<v8::Function> function = GetFunction(env.local(), "start"); 905 906 { 907 // Make sure accessors ICs are in monomorphic state before starting 908 // profiling. 909 accessors.set_warming_up(true); 910 int32_t warm_up_iterations = 3; 911 v8::Local<v8::Value> args[] = { 912 v8::Integer::New(isolate, warm_up_iterations)}; 913 function->Call(env.local(), env->Global(), arraysize(args), args) 914 .ToLocalChecked(); 915 accessors.set_warming_up(false); 916 } 917 918 int32_t repeat_count = 100; 919 v8::Local<v8::Value> args[] = {v8::Integer::New(isolate, repeat_count)}; 920 v8::CpuProfile* profile = 921 RunProfiler(env.local(), function, args, arraysize(args), 200); 922 923 const v8::CpuProfileNode* root = profile->GetTopDownRoot(); 924 const v8::CpuProfileNode* startNode = GetChild(env.local(), root, "start"); 925 GetChild(env.local(), startNode, "get foo"); 926 GetChild(env.local(), startNode, "set foo"); 927 928 profile->Delete(); 929 } 930 931 932 static const char* native_method_test_source = "function start(count) {\n" 933 " for (var i = 0; i < count; i++) {\n" 934 " instance.fooMethod();\n" 935 " }\n" 936 "}\n"; 937 938 939 TEST(NativeMethodUninitializedIC) { 940 LocalContext env; 941 v8::Isolate* isolate = env->GetIsolate(); 942 v8::HandleScope scope(isolate); 943 944 TestApiCallbacks callbacks(100); 945 v8::Local<v8::External> data = 946 v8::External::New(isolate, &callbacks); 947 948 v8::Local<v8::FunctionTemplate> func_template = 949 v8::FunctionTemplate::New(isolate); 950 func_template->SetClassName(v8_str("Test_InstanceCostructor")); 951 v8::Local<v8::ObjectTemplate> proto_template = 952 func_template->PrototypeTemplate(); 953 v8::Local<v8::Signature> signature = 954 v8::Signature::New(isolate, func_template); 955 proto_template->Set( 956 v8_str("fooMethod"), 957 v8::FunctionTemplate::New(isolate, &TestApiCallbacks::Callback, data, 958 signature, 0)); 959 960 v8::Local<v8::Function> func = 961 func_template->GetFunction(env.local()).ToLocalChecked(); 962 v8::Local<v8::Object> instance = 963 func->NewInstance(env.local()).ToLocalChecked(); 964 env->Global()->Set(env.local(), v8_str("instance"), instance).FromJust(); 965 966 CompileRun(native_method_test_source); 967 v8::Local<v8::Function> function = GetFunction(env.local(), "start"); 968 969 int32_t repeat_count = 1; 970 v8::Local<v8::Value> args[] = {v8::Integer::New(isolate, repeat_count)}; 971 v8::CpuProfile* profile = 972 RunProfiler(env.local(), function, args, arraysize(args), 100); 973 974 const v8::CpuProfileNode* root = profile->GetTopDownRoot(); 975 const v8::CpuProfileNode* startNode = GetChild(env.local(), root, "start"); 976 GetChild(env.local(), startNode, "fooMethod"); 977 978 profile->Delete(); 979 } 980 981 982 TEST(NativeMethodMonomorphicIC) { 983 LocalContext env; 984 v8::Isolate* isolate = env->GetIsolate(); 985 v8::HandleScope scope(isolate); 986 987 TestApiCallbacks callbacks(1); 988 v8::Local<v8::External> data = 989 v8::External::New(isolate, &callbacks); 990 991 v8::Local<v8::FunctionTemplate> func_template = 992 v8::FunctionTemplate::New(isolate); 993 func_template->SetClassName(v8_str("Test_InstanceCostructor")); 994 v8::Local<v8::ObjectTemplate> proto_template = 995 func_template->PrototypeTemplate(); 996 v8::Local<v8::Signature> signature = 997 v8::Signature::New(isolate, func_template); 998 proto_template->Set( 999 v8_str("fooMethod"), 1000 v8::FunctionTemplate::New(isolate, &TestApiCallbacks::Callback, data, 1001 signature, 0)); 1002 1003 v8::Local<v8::Function> func = 1004 func_template->GetFunction(env.local()).ToLocalChecked(); 1005 v8::Local<v8::Object> instance = 1006 func->NewInstance(env.local()).ToLocalChecked(); 1007 env->Global()->Set(env.local(), v8_str("instance"), instance).FromJust(); 1008 1009 CompileRun(native_method_test_source); 1010 v8::Local<v8::Function> function = GetFunction(env.local(), "start"); 1011 { 1012 // Make sure method ICs are in monomorphic state before starting 1013 // profiling. 1014 callbacks.set_warming_up(true); 1015 int32_t warm_up_iterations = 3; 1016 v8::Local<v8::Value> args[] = { 1017 v8::Integer::New(isolate, warm_up_iterations)}; 1018 function->Call(env.local(), env->Global(), arraysize(args), args) 1019 .ToLocalChecked(); 1020 callbacks.set_warming_up(false); 1021 } 1022 1023 int32_t repeat_count = 100; 1024 v8::Local<v8::Value> args[] = {v8::Integer::New(isolate, repeat_count)}; 1025 v8::CpuProfile* profile = 1026 RunProfiler(env.local(), function, args, arraysize(args), 100); 1027 1028 const v8::CpuProfileNode* root = profile->GetTopDownRoot(); 1029 GetChild(env.local(), root, "start"); 1030 const v8::CpuProfileNode* startNode = GetChild(env.local(), root, "start"); 1031 GetChild(env.local(), startNode, "fooMethod"); 1032 1033 profile->Delete(); 1034 } 1035 1036 1037 static const char* bound_function_test_source = 1038 "function foo() {\n" 1039 " startProfiling('my_profile');\n" 1040 "}\n" 1041 "function start() {\n" 1042 " var callback = foo.bind(this);\n" 1043 " callback();\n" 1044 "}"; 1045 1046 1047 TEST(BoundFunctionCall) { 1048 v8::HandleScope scope(CcTest::isolate()); 1049 v8::Local<v8::Context> env = CcTest::NewContext(PROFILER_EXTENSION); 1050 v8::Context::Scope context_scope(env); 1051 1052 CompileRun(bound_function_test_source); 1053 v8::Local<v8::Function> function = GetFunction(env, "start"); 1054 1055 v8::CpuProfile* profile = RunProfiler(env, function, NULL, 0, 0); 1056 1057 const v8::CpuProfileNode* root = profile->GetTopDownRoot(); 1058 ScopedVector<v8::Local<v8::String> > names(3); 1059 names[0] = v8_str(ProfileGenerator::kGarbageCollectorEntryName); 1060 names[1] = v8_str(ProfileGenerator::kProgramEntryName); 1061 names[2] = v8_str("start"); 1062 // Don't allow |foo| node to be at the top level. 1063 CheckChildrenNames(env, root, names); 1064 1065 const v8::CpuProfileNode* startNode = GetChild(env, root, "start"); 1066 GetChild(env, startNode, "foo"); 1067 1068 profile->Delete(); 1069 } 1070 1071 1072 // This tests checks distribution of the samples through the source lines. 1073 TEST(TickLines) { 1074 CcTest::InitializeVM(); 1075 LocalContext env; 1076 i::FLAG_turbo_source_positions = true; 1077 i::Isolate* isolate = CcTest::i_isolate(); 1078 i::Factory* factory = isolate->factory(); 1079 i::HandleScope scope(isolate); 1080 1081 i::EmbeddedVector<char, 512> script; 1082 1083 const char* func_name = "func"; 1084 i::SNPrintF(script, 1085 "function %s() {\n" 1086 " var n = 0;\n" 1087 " var m = 100*100;\n" 1088 " while (m > 1) {\n" 1089 " m--;\n" 1090 " n += m * m * m;\n" 1091 " }\n" 1092 "}\n" 1093 "%s();\n", 1094 func_name, func_name); 1095 1096 CompileRun(script.start()); 1097 1098 i::Handle<i::JSFunction> func = i::Handle<i::JSFunction>::cast( 1099 v8::Utils::OpenHandle(*GetFunction(env.local(), func_name))); 1100 CHECK(func->shared()); 1101 CHECK(func->shared()->code()); 1102 i::Code* code = NULL; 1103 if (func->code()->is_optimized_code()) { 1104 code = func->code(); 1105 } else { 1106 CHECK(func->shared()->code() == func->code() || !i::FLAG_crankshaft); 1107 code = func->shared()->code(); 1108 } 1109 CHECK(code); 1110 i::Address code_address = code->instruction_start(); 1111 CHECK(code_address); 1112 1113 CpuProfilesCollection* profiles = new CpuProfilesCollection(isolate->heap()); 1114 profiles->StartProfiling("", false); 1115 ProfileGenerator generator(profiles); 1116 SmartPointer<ProfilerEventsProcessor> processor(new ProfilerEventsProcessor( 1117 &generator, NULL, v8::base::TimeDelta::FromMicroseconds(100))); 1118 processor->Start(); 1119 CpuProfiler profiler(isolate, profiles, &generator, processor.get()); 1120 1121 // Enqueue code creation events. 1122 i::Handle<i::String> str = factory->NewStringFromAsciiChecked(func_name); 1123 int line = 1; 1124 int column = 1; 1125 profiler.CodeCreateEvent(i::Logger::FUNCTION_TAG, code, func->shared(), NULL, 1126 *str, line, column); 1127 1128 // Enqueue a tick event to enable code events processing. 1129 EnqueueTickSampleEvent(processor.get(), code_address); 1130 1131 processor->StopSynchronously(); 1132 1133 CpuProfile* profile = profiles->StopProfiling(""); 1134 CHECK(profile); 1135 1136 // Check the state of profile generator. 1137 CodeEntry* func_entry = generator.code_map()->FindEntry(code_address); 1138 CHECK(func_entry); 1139 CHECK_EQ(0, strcmp(func_name, func_entry->name())); 1140 const i::JITLineInfoTable* line_info = func_entry->line_info(); 1141 CHECK(line_info); 1142 CHECK(!line_info->empty()); 1143 1144 // Check the hit source lines using V8 Public APIs. 1145 const i::ProfileTree* tree = profile->top_down(); 1146 ProfileNode* root = tree->root(); 1147 CHECK(root); 1148 ProfileNode* func_node = root->FindChild(func_entry); 1149 CHECK(func_node); 1150 1151 // Add 10 faked ticks to source line #5. 1152 int hit_line = 5; 1153 int hit_count = 10; 1154 for (int i = 0; i < hit_count; i++) func_node->IncrementLineTicks(hit_line); 1155 1156 unsigned int line_count = func_node->GetHitLineCount(); 1157 CHECK_EQ(2u, line_count); // Expect two hit source lines - #1 and #5. 1158 ScopedVector<v8::CpuProfileNode::LineTick> entries(line_count); 1159 CHECK(func_node->GetLineTicks(&entries[0], line_count)); 1160 int value = 0; 1161 for (int i = 0; i < entries.length(); i++) 1162 if (entries[i].line == hit_line) { 1163 value = entries[i].hit_count; 1164 break; 1165 } 1166 CHECK_EQ(hit_count, value); 1167 } 1168 1169 1170 static const char* call_function_test_source = "function bar(iterations) {\n" 1171 "}\n" 1172 "function start(duration) {\n" 1173 " var start = Date.now();\n" 1174 " while (Date.now() - start < duration) {\n" 1175 " try {\n" 1176 " bar.call(this, 10 * 1000);\n" 1177 " } catch(e) {}\n" 1178 " }\n" 1179 "}"; 1180 1181 1182 // Test that if we sampled thread when it was inside FunctionCall buitin then 1183 // its caller frame will be '(unresolved function)' as we have no reliable way 1184 // to resolve it. 1185 // 1186 // [Top down]: 1187 // 96 0 (root) [-1] #1 1188 // 1 1 (garbage collector) [-1] #4 1189 // 5 0 (unresolved function) [-1] #5 1190 // 5 5 call [-1] #6 1191 // 71 70 start [-1] #3 1192 // 1 1 bar [-1] #7 1193 // 19 19 (program) [-1] #2 1194 TEST(FunctionCallSample) { 1195 LocalContext env; 1196 v8::HandleScope scope(env->GetIsolate()); 1197 1198 // Collect garbage that might have be generated while installing 1199 // extensions. 1200 CcTest::heap()->CollectAllGarbage(); 1201 1202 CompileRun(call_function_test_source); 1203 v8::Local<v8::Function> function = GetFunction(env.local(), "start"); 1204 1205 int32_t duration_ms = 100; 1206 v8::Local<v8::Value> args[] = { 1207 v8::Integer::New(env->GetIsolate(), duration_ms)}; 1208 v8::CpuProfile* profile = 1209 RunProfiler(env.local(), function, args, arraysize(args), 100); 1210 1211 const v8::CpuProfileNode* root = profile->GetTopDownRoot(); 1212 { 1213 ScopedVector<v8::Local<v8::String> > names(4); 1214 names[0] = v8_str(ProfileGenerator::kGarbageCollectorEntryName); 1215 names[1] = v8_str(ProfileGenerator::kProgramEntryName); 1216 names[2] = v8_str("start"); 1217 names[3] = v8_str(i::ProfileGenerator::kUnresolvedFunctionName); 1218 // Don't allow |bar| and |call| nodes to be at the top level. 1219 CheckChildrenNames(env.local(), root, names); 1220 } 1221 1222 // In case of GC stress tests all samples may be in GC phase and there 1223 // won't be |start| node in the profiles. 1224 bool is_gc_stress_testing = 1225 (i::FLAG_gc_interval != -1) || i::FLAG_stress_compaction; 1226 const v8::CpuProfileNode* startNode = FindChild(env.local(), root, "start"); 1227 CHECK(is_gc_stress_testing || startNode); 1228 if (startNode) { 1229 ScopedVector<v8::Local<v8::String> > names(2); 1230 names[0] = v8_str("bar"); 1231 names[1] = v8_str("call"); 1232 CheckChildrenNames(env.local(), startNode, names); 1233 } 1234 1235 const v8::CpuProfileNode* unresolvedNode = FindChild( 1236 env.local(), root, i::ProfileGenerator::kUnresolvedFunctionName); 1237 if (unresolvedNode) { 1238 ScopedVector<v8::Local<v8::String> > names(1); 1239 names[0] = v8_str("call"); 1240 CheckChildrenNames(env.local(), unresolvedNode, names); 1241 } 1242 1243 profile->Delete(); 1244 } 1245 1246 1247 static const char* function_apply_test_source = 1248 "function bar(iterations) {\n" 1249 "}\n" 1250 "function test() {\n" 1251 " bar.apply(this, [10 * 1000]);\n" 1252 "}\n" 1253 "function start(duration) {\n" 1254 " var start = Date.now();\n" 1255 " while (Date.now() - start < duration) {\n" 1256 " try {\n" 1257 " test();\n" 1258 " } catch(e) {}\n" 1259 " }\n" 1260 "}"; 1261 1262 1263 // [Top down]: 1264 // 94 0 (root) [-1] #0 1 1265 // 2 2 (garbage collector) [-1] #0 7 1266 // 82 49 start [-1] #16 3 1267 // 1 0 (unresolved function) [-1] #0 8 1268 // 1 1 apply [-1] #0 9 1269 // 32 21 test [-1] #16 4 1270 // 2 2 bar [-1] #16 6 1271 // 9 9 apply [-1] #0 5 1272 // 10 10 (program) [-1] #0 2 1273 TEST(FunctionApplySample) { 1274 LocalContext env; 1275 v8::HandleScope scope(env->GetIsolate()); 1276 1277 CompileRun(function_apply_test_source); 1278 v8::Local<v8::Function> function = GetFunction(env.local(), "start"); 1279 1280 int32_t duration_ms = 100; 1281 v8::Local<v8::Value> args[] = { 1282 v8::Integer::New(env->GetIsolate(), duration_ms)}; 1283 1284 v8::CpuProfile* profile = 1285 RunProfiler(env.local(), function, args, arraysize(args), 100); 1286 1287 const v8::CpuProfileNode* root = profile->GetTopDownRoot(); 1288 { 1289 ScopedVector<v8::Local<v8::String> > names(3); 1290 names[0] = v8_str(ProfileGenerator::kGarbageCollectorEntryName); 1291 names[1] = v8_str(ProfileGenerator::kProgramEntryName); 1292 names[2] = v8_str("start"); 1293 // Don't allow |test|, |bar| and |apply| nodes to be at the top level. 1294 CheckChildrenNames(env.local(), root, names); 1295 } 1296 1297 const v8::CpuProfileNode* startNode = FindChild(env.local(), root, "start"); 1298 if (startNode) { 1299 { 1300 ScopedVector<v8::Local<v8::String> > names(2); 1301 names[0] = v8_str("test"); 1302 names[1] = v8_str(ProfileGenerator::kUnresolvedFunctionName); 1303 CheckChildrenNames(env.local(), startNode, names); 1304 } 1305 1306 const v8::CpuProfileNode* testNode = 1307 FindChild(env.local(), startNode, "test"); 1308 if (testNode) { 1309 ScopedVector<v8::Local<v8::String> > names(3); 1310 names[0] = v8_str("bar"); 1311 names[1] = v8_str("apply"); 1312 // apply calls "get length" before invoking the function itself 1313 // and we may get hit into it. 1314 names[2] = v8_str("get length"); 1315 CheckChildrenNames(env.local(), testNode, names); 1316 } 1317 1318 if (const v8::CpuProfileNode* unresolvedNode = 1319 FindChild(env.local(), startNode, 1320 ProfileGenerator::kUnresolvedFunctionName)) { 1321 ScopedVector<v8::Local<v8::String> > names(1); 1322 names[0] = v8_str("apply"); 1323 CheckChildrenNames(env.local(), unresolvedNode, names); 1324 GetChild(env.local(), unresolvedNode, "apply"); 1325 } 1326 } 1327 1328 profile->Delete(); 1329 } 1330 1331 1332 static const char* cpu_profiler_deep_stack_test_source = 1333 "function foo(n) {\n" 1334 " if (n)\n" 1335 " foo(n - 1);\n" 1336 " else\n" 1337 " startProfiling('my_profile');\n" 1338 "}\n" 1339 "function start() {\n" 1340 " foo(250);\n" 1341 "}\n"; 1342 1343 1344 // Check a deep stack 1345 // 1346 // [Top down]: 1347 // 0 (root) 0 #1 1348 // 2 (program) 0 #2 1349 // 0 start 21 #3 no reason 1350 // 0 foo 21 #4 no reason 1351 // 0 foo 21 #5 no reason 1352 // .... 1353 // 0 foo 21 #253 no reason 1354 // 1 startProfiling 0 #254 1355 TEST(CpuProfileDeepStack) { 1356 v8::HandleScope scope(CcTest::isolate()); 1357 v8::Local<v8::Context> env = CcTest::NewContext(PROFILER_EXTENSION); 1358 v8::Context::Scope context_scope(env); 1359 1360 CompileRun(cpu_profiler_deep_stack_test_source); 1361 v8::Local<v8::Function> function = GetFunction(env, "start"); 1362 1363 v8::CpuProfiler* cpu_profiler = env->GetIsolate()->GetCpuProfiler(); 1364 v8::Local<v8::String> profile_name = v8_str("my_profile"); 1365 function->Call(env, env->Global(), 0, NULL).ToLocalChecked(); 1366 v8::CpuProfile* profile = cpu_profiler->StopProfiling(profile_name); 1367 CHECK(profile); 1368 // Dump collected profile to have a better diagnostic in case of failure. 1369 reinterpret_cast<i::CpuProfile*>(profile)->Print(); 1370 1371 const v8::CpuProfileNode* root = profile->GetTopDownRoot(); 1372 { 1373 ScopedVector<v8::Local<v8::String> > names(3); 1374 names[0] = v8_str(ProfileGenerator::kGarbageCollectorEntryName); 1375 names[1] = v8_str(ProfileGenerator::kProgramEntryName); 1376 names[2] = v8_str("start"); 1377 CheckChildrenNames(env, root, names); 1378 } 1379 1380 const v8::CpuProfileNode* node = GetChild(env, root, "start"); 1381 for (int i = 0; i < 250; ++i) { 1382 node = GetChild(env, node, "foo"); 1383 } 1384 // TODO(alph): 1385 // In theory there must be one more 'foo' and a 'startProfiling' nodes, 1386 // but due to unstable top frame extraction these might be missing. 1387 1388 profile->Delete(); 1389 } 1390 1391 1392 static const char* js_native_js_test_source = 1393 "function foo() {\n" 1394 " startProfiling('my_profile');\n" 1395 "}\n" 1396 "function bar() {\n" 1397 " try { foo(); } catch(e) {}\n" 1398 "}\n" 1399 "function start() {\n" 1400 " try {\n" 1401 " CallJsFunction(bar);\n" 1402 " } catch(e) {}\n" 1403 "}"; 1404 1405 static void CallJsFunction(const v8::FunctionCallbackInfo<v8::Value>& info) { 1406 v8::Local<v8::Function> function = info[0].As<v8::Function>(); 1407 v8::Local<v8::Value> argv[] = {info[1]}; 1408 function->Call(info.GetIsolate()->GetCurrentContext(), info.This(), 1409 arraysize(argv), argv) 1410 .ToLocalChecked(); 1411 } 1412 1413 1414 // [Top down]: 1415 // 58 0 (root) #0 1 1416 // 2 2 (program) #0 2 1417 // 56 1 start #16 3 1418 // 55 0 CallJsFunction #0 4 1419 // 55 1 bar #16 5 1420 // 54 54 foo #16 6 1421 TEST(JsNativeJsSample) { 1422 v8::HandleScope scope(CcTest::isolate()); 1423 v8::Local<v8::Context> env = CcTest::NewContext(PROFILER_EXTENSION); 1424 v8::Context::Scope context_scope(env); 1425 1426 v8::Local<v8::FunctionTemplate> func_template = v8::FunctionTemplate::New( 1427 env->GetIsolate(), CallJsFunction); 1428 v8::Local<v8::Function> func = 1429 func_template->GetFunction(env).ToLocalChecked(); 1430 func->SetName(v8_str("CallJsFunction")); 1431 env->Global()->Set(env, v8_str("CallJsFunction"), func).FromJust(); 1432 1433 CompileRun(js_native_js_test_source); 1434 v8::Local<v8::Function> function = GetFunction(env, "start"); 1435 1436 v8::CpuProfile* profile = RunProfiler(env, function, NULL, 0, 0); 1437 1438 const v8::CpuProfileNode* root = profile->GetTopDownRoot(); 1439 { 1440 ScopedVector<v8::Local<v8::String> > names(3); 1441 names[0] = v8_str(ProfileGenerator::kGarbageCollectorEntryName); 1442 names[1] = v8_str(ProfileGenerator::kProgramEntryName); 1443 names[2] = v8_str("start"); 1444 CheckChildrenNames(env, root, names); 1445 } 1446 1447 const v8::CpuProfileNode* startNode = GetChild(env, root, "start"); 1448 CHECK_EQ(1, startNode->GetChildrenCount()); 1449 const v8::CpuProfileNode* nativeFunctionNode = 1450 GetChild(env, startNode, "CallJsFunction"); 1451 1452 CHECK_EQ(1, nativeFunctionNode->GetChildrenCount()); 1453 const v8::CpuProfileNode* barNode = GetChild(env, nativeFunctionNode, "bar"); 1454 1455 CHECK_EQ(1, barNode->GetChildrenCount()); 1456 GetChild(env, barNode, "foo"); 1457 1458 profile->Delete(); 1459 } 1460 1461 1462 static const char* js_native_js_runtime_js_test_source = 1463 "function foo() {\n" 1464 " startProfiling('my_profile');\n" 1465 "}\n" 1466 "var bound = foo.bind(this);\n" 1467 "function bar() {\n" 1468 " try { bound(); } catch(e) {}\n" 1469 "}\n" 1470 "function start() {\n" 1471 " try {\n" 1472 " CallJsFunction(bar);\n" 1473 " } catch(e) {}\n" 1474 "}"; 1475 1476 1477 // [Top down]: 1478 // 57 0 (root) #0 1 1479 // 55 1 start #16 3 1480 // 54 0 CallJsFunction #0 4 1481 // 54 3 bar #16 5 1482 // 51 51 foo #16 6 1483 // 2 2 (program) #0 2 1484 TEST(JsNativeJsRuntimeJsSample) { 1485 v8::HandleScope scope(CcTest::isolate()); 1486 v8::Local<v8::Context> env = CcTest::NewContext(PROFILER_EXTENSION); 1487 v8::Context::Scope context_scope(env); 1488 1489 v8::Local<v8::FunctionTemplate> func_template = v8::FunctionTemplate::New( 1490 env->GetIsolate(), CallJsFunction); 1491 v8::Local<v8::Function> func = 1492 func_template->GetFunction(env).ToLocalChecked(); 1493 func->SetName(v8_str("CallJsFunction")); 1494 env->Global()->Set(env, v8_str("CallJsFunction"), func).FromJust(); 1495 1496 CompileRun(js_native_js_runtime_js_test_source); 1497 v8::Local<v8::Function> function = GetFunction(env, "start"); 1498 1499 v8::CpuProfile* profile = RunProfiler(env, function, NULL, 0, 0); 1500 1501 const v8::CpuProfileNode* root = profile->GetTopDownRoot(); 1502 ScopedVector<v8::Local<v8::String> > names(3); 1503 names[0] = v8_str(ProfileGenerator::kGarbageCollectorEntryName); 1504 names[1] = v8_str(ProfileGenerator::kProgramEntryName); 1505 names[2] = v8_str("start"); 1506 CheckChildrenNames(env, root, names); 1507 1508 const v8::CpuProfileNode* startNode = GetChild(env, root, "start"); 1509 CHECK_EQ(1, startNode->GetChildrenCount()); 1510 const v8::CpuProfileNode* nativeFunctionNode = 1511 GetChild(env, startNode, "CallJsFunction"); 1512 1513 CHECK_EQ(1, nativeFunctionNode->GetChildrenCount()); 1514 const v8::CpuProfileNode* barNode = GetChild(env, nativeFunctionNode, "bar"); 1515 1516 // The child is in fact a bound foo. 1517 // A bound function has a wrapper that may make calls to 1518 // other functions e.g. "get length". 1519 CHECK_LE(1, barNode->GetChildrenCount()); 1520 CHECK_GE(2, barNode->GetChildrenCount()); 1521 GetChild(env, barNode, "foo"); 1522 1523 profile->Delete(); 1524 } 1525 1526 1527 static void CallJsFunction2(const v8::FunctionCallbackInfo<v8::Value>& info) { 1528 v8::base::OS::Print("In CallJsFunction2\n"); 1529 CallJsFunction(info); 1530 } 1531 1532 1533 static const char* js_native1_js_native2_js_test_source = 1534 "function foo() {\n" 1535 " try {\n" 1536 " startProfiling('my_profile');\n" 1537 " } catch(e) {}\n" 1538 "}\n" 1539 "function bar() {\n" 1540 " CallJsFunction2(foo);\n" 1541 "}\n" 1542 "function start() {\n" 1543 " try {\n" 1544 " CallJsFunction1(bar);\n" 1545 " } catch(e) {}\n" 1546 "}"; 1547 1548 1549 // [Top down]: 1550 // 57 0 (root) #0 1 1551 // 55 1 start #16 3 1552 // 54 0 CallJsFunction1 #0 4 1553 // 54 0 bar #16 5 1554 // 54 0 CallJsFunction2 #0 6 1555 // 54 54 foo #16 7 1556 // 2 2 (program) #0 2 1557 TEST(JsNative1JsNative2JsSample) { 1558 v8::HandleScope scope(CcTest::isolate()); 1559 v8::Local<v8::Context> env = CcTest::NewContext(PROFILER_EXTENSION); 1560 v8::Context::Scope context_scope(env); 1561 1562 v8::Local<v8::FunctionTemplate> func_template = v8::FunctionTemplate::New( 1563 env->GetIsolate(), CallJsFunction); 1564 v8::Local<v8::Function> func1 = 1565 func_template->GetFunction(env).ToLocalChecked(); 1566 func1->SetName(v8_str("CallJsFunction1")); 1567 env->Global()->Set(env, v8_str("CallJsFunction1"), func1).FromJust(); 1568 1569 v8::Local<v8::Function> func2 = 1570 v8::FunctionTemplate::New(env->GetIsolate(), CallJsFunction2) 1571 ->GetFunction(env) 1572 .ToLocalChecked(); 1573 func2->SetName(v8_str("CallJsFunction2")); 1574 env->Global()->Set(env, v8_str("CallJsFunction2"), func2).FromJust(); 1575 1576 CompileRun(js_native1_js_native2_js_test_source); 1577 v8::Local<v8::Function> function = GetFunction(env, "start"); 1578 1579 v8::CpuProfile* profile = RunProfiler(env, function, NULL, 0, 0); 1580 1581 const v8::CpuProfileNode* root = profile->GetTopDownRoot(); 1582 ScopedVector<v8::Local<v8::String> > names(3); 1583 names[0] = v8_str(ProfileGenerator::kGarbageCollectorEntryName); 1584 names[1] = v8_str(ProfileGenerator::kProgramEntryName); 1585 names[2] = v8_str("start"); 1586 CheckChildrenNames(env, root, names); 1587 1588 const v8::CpuProfileNode* startNode = GetChild(env, root, "start"); 1589 CHECK_EQ(1, startNode->GetChildrenCount()); 1590 const v8::CpuProfileNode* nativeNode1 = 1591 GetChild(env, startNode, "CallJsFunction1"); 1592 1593 CHECK_EQ(1, nativeNode1->GetChildrenCount()); 1594 const v8::CpuProfileNode* barNode = GetChild(env, nativeNode1, "bar"); 1595 1596 CHECK_EQ(1, barNode->GetChildrenCount()); 1597 const v8::CpuProfileNode* nativeNode2 = 1598 GetChild(env, barNode, "CallJsFunction2"); 1599 1600 CHECK_EQ(1, nativeNode2->GetChildrenCount()); 1601 GetChild(env, nativeNode2, "foo"); 1602 1603 profile->Delete(); 1604 } 1605 1606 1607 // [Top down]: 1608 // 6 0 (root) #0 1 1609 // 3 3 (program) #0 2 1610 // 3 3 (idle) #0 3 1611 TEST(IdleTime) { 1612 LocalContext env; 1613 v8::HandleScope scope(env->GetIsolate()); 1614 v8::CpuProfiler* cpu_profiler = env->GetIsolate()->GetCpuProfiler(); 1615 1616 v8::Local<v8::String> profile_name = v8_str("my_profile"); 1617 cpu_profiler->StartProfiling(profile_name); 1618 1619 i::Isolate* isolate = CcTest::i_isolate(); 1620 i::ProfilerEventsProcessor* processor = isolate->cpu_profiler()->processor(); 1621 processor->AddCurrentStack(isolate); 1622 1623 cpu_profiler->SetIdle(true); 1624 1625 for (int i = 0; i < 3; i++) { 1626 processor->AddCurrentStack(isolate); 1627 } 1628 1629 cpu_profiler->SetIdle(false); 1630 processor->AddCurrentStack(isolate); 1631 1632 1633 v8::CpuProfile* profile = cpu_profiler->StopProfiling(profile_name); 1634 CHECK(profile); 1635 // Dump collected profile to have a better diagnostic in case of failure. 1636 reinterpret_cast<i::CpuProfile*>(profile)->Print(); 1637 1638 const v8::CpuProfileNode* root = profile->GetTopDownRoot(); 1639 ScopedVector<v8::Local<v8::String> > names(3); 1640 names[0] = v8_str(ProfileGenerator::kGarbageCollectorEntryName); 1641 names[1] = v8_str(ProfileGenerator::kProgramEntryName); 1642 names[2] = v8_str(ProfileGenerator::kIdleEntryName); 1643 CheckChildrenNames(env.local(), root, names); 1644 1645 const v8::CpuProfileNode* programNode = 1646 GetChild(env.local(), root, ProfileGenerator::kProgramEntryName); 1647 CHECK_EQ(0, programNode->GetChildrenCount()); 1648 CHECK_GE(programNode->GetHitCount(), 3u); 1649 1650 const v8::CpuProfileNode* idleNode = 1651 GetChild(env.local(), root, ProfileGenerator::kIdleEntryName); 1652 CHECK_EQ(0, idleNode->GetChildrenCount()); 1653 CHECK_GE(idleNode->GetHitCount(), 3u); 1654 1655 profile->Delete(); 1656 } 1657 1658 1659 static void CheckFunctionDetails(v8::Isolate* isolate, 1660 const v8::CpuProfileNode* node, 1661 const char* name, const char* script_name, 1662 int script_id, int line, int column) { 1663 v8::Local<v8::Context> context = isolate->GetCurrentContext(); 1664 CHECK(v8_str(name)->Equals(context, node->GetFunctionName()).FromJust()); 1665 CHECK(v8_str(script_name) 1666 ->Equals(context, node->GetScriptResourceName()) 1667 .FromJust()); 1668 CHECK_EQ(script_id, node->GetScriptId()); 1669 CHECK_EQ(line, node->GetLineNumber()); 1670 CHECK_EQ(column, node->GetColumnNumber()); 1671 } 1672 1673 1674 TEST(FunctionDetails) { 1675 v8::HandleScope scope(CcTest::isolate()); 1676 v8::Local<v8::Context> env = CcTest::NewContext(PROFILER_EXTENSION); 1677 v8::Context::Scope context_scope(env); 1678 1679 v8::Local<v8::Script> script_a = CompileWithOrigin( 1680 " function foo\n() { try { bar(); } catch(e) {} }\n" 1681 " function bar() { startProfiling(); }\n", 1682 "script_a"); 1683 script_a->Run(env).ToLocalChecked(); 1684 v8::Local<v8::Script> script_b = CompileWithOrigin( 1685 "\n\n function baz() { try { foo(); } catch(e) {} }\n" 1686 "\n\nbaz();\n" 1687 "stopProfiling();\n", 1688 "script_b"); 1689 script_b->Run(env).ToLocalChecked(); 1690 const v8::CpuProfile* profile = i::ProfilerExtension::last_profile; 1691 const v8::CpuProfileNode* current = profile->GetTopDownRoot(); 1692 reinterpret_cast<ProfileNode*>( 1693 const_cast<v8::CpuProfileNode*>(current))->Print(0); 1694 // The tree should look like this: 1695 // 0 (root) 0 #1 1696 // 0 "" 19 #2 no reason script_b:1 1697 // 0 baz 19 #3 TryCatchStatement script_b:3 1698 // 0 foo 18 #4 TryCatchStatement script_a:2 1699 // 1 bar 18 #5 no reason script_a:3 1700 const v8::CpuProfileNode* root = profile->GetTopDownRoot(); 1701 const v8::CpuProfileNode* script = GetChild(env, root, ""); 1702 CheckFunctionDetails(env->GetIsolate(), script, "", "script_b", 1703 script_b->GetUnboundScript()->GetId(), 1, 1); 1704 const v8::CpuProfileNode* baz = GetChild(env, script, "baz"); 1705 CheckFunctionDetails(env->GetIsolate(), baz, "baz", "script_b", 1706 script_b->GetUnboundScript()->GetId(), 3, 16); 1707 const v8::CpuProfileNode* foo = GetChild(env, baz, "foo"); 1708 CheckFunctionDetails(env->GetIsolate(), foo, "foo", "script_a", 1709 script_a->GetUnboundScript()->GetId(), 2, 1); 1710 const v8::CpuProfileNode* bar = GetChild(env, foo, "bar"); 1711 CheckFunctionDetails(env->GetIsolate(), bar, "bar", "script_a", 1712 script_a->GetUnboundScript()->GetId(), 3, 14); 1713 } 1714 1715 1716 TEST(DontStopOnFinishedProfileDelete) { 1717 v8::HandleScope scope(CcTest::isolate()); 1718 v8::Local<v8::Context> env = CcTest::NewContext(PROFILER_EXTENSION); 1719 v8::Context::Scope context_scope(env); 1720 1721 v8::CpuProfiler* profiler = env->GetIsolate()->GetCpuProfiler(); 1722 i::CpuProfiler* iprofiler = reinterpret_cast<i::CpuProfiler*>(profiler); 1723 1724 CHECK_EQ(0, iprofiler->GetProfilesCount()); 1725 v8::Local<v8::String> outer = v8_str("outer"); 1726 profiler->StartProfiling(outer); 1727 CHECK_EQ(0, iprofiler->GetProfilesCount()); 1728 1729 v8::Local<v8::String> inner = v8_str("inner"); 1730 profiler->StartProfiling(inner); 1731 CHECK_EQ(0, iprofiler->GetProfilesCount()); 1732 1733 v8::CpuProfile* inner_profile = profiler->StopProfiling(inner); 1734 CHECK(inner_profile); 1735 CHECK_EQ(1, iprofiler->GetProfilesCount()); 1736 inner_profile->Delete(); 1737 inner_profile = NULL; 1738 CHECK_EQ(0, iprofiler->GetProfilesCount()); 1739 1740 v8::CpuProfile* outer_profile = profiler->StopProfiling(outer); 1741 CHECK(outer_profile); 1742 CHECK_EQ(1, iprofiler->GetProfilesCount()); 1743 outer_profile->Delete(); 1744 outer_profile = NULL; 1745 CHECK_EQ(0, iprofiler->GetProfilesCount()); 1746 } 1747 1748 1749 const char* GetBranchDeoptReason(v8::Local<v8::Context> context, 1750 i::CpuProfile* iprofile, const char* branch[], 1751 int length) { 1752 v8::CpuProfile* profile = reinterpret_cast<v8::CpuProfile*>(iprofile); 1753 const ProfileNode* iopt_function = NULL; 1754 iopt_function = GetSimpleBranch(context, profile, branch, length); 1755 CHECK_EQ(1U, iopt_function->deopt_infos().size()); 1756 return iopt_function->deopt_infos()[0].deopt_reason; 1757 } 1758 1759 1760 // deopt at top function 1761 TEST(CollectDeoptEvents) { 1762 if (!CcTest::i_isolate()->use_crankshaft() || i::FLAG_always_opt) return; 1763 i::FLAG_allow_natives_syntax = true; 1764 v8::HandleScope scope(CcTest::isolate()); 1765 v8::Local<v8::Context> env = CcTest::NewContext(PROFILER_EXTENSION); 1766 v8::Context::Scope context_scope(env); 1767 v8::Isolate* isolate = env->GetIsolate(); 1768 v8::CpuProfiler* profiler = isolate->GetCpuProfiler(); 1769 i::CpuProfiler* iprofiler = reinterpret_cast<i::CpuProfiler*>(profiler); 1770 1771 const char opt_source[] = 1772 "function opt_function%d(value, depth) {\n" 1773 " if (depth) return opt_function%d(value, depth - 1);\n" 1774 "\n" 1775 " return 10 / value;\n" 1776 "}\n" 1777 "\n"; 1778 1779 for (int i = 0; i < 3; ++i) { 1780 i::EmbeddedVector<char, sizeof(opt_source) + 100> buffer; 1781 i::SNPrintF(buffer, opt_source, i, i); 1782 v8::Script::Compile(env, v8_str(buffer.start())) 1783 .ToLocalChecked() 1784 ->Run(env) 1785 .ToLocalChecked(); 1786 } 1787 1788 const char* source = 1789 "startProfiling();\n" 1790 "\n" 1791 "opt_function0(1, 1);\n" 1792 "\n" 1793 "%OptimizeFunctionOnNextCall(opt_function0)\n" 1794 "\n" 1795 "opt_function0(1, 1);\n" 1796 "\n" 1797 "opt_function0(undefined, 1);\n" 1798 "\n" 1799 "opt_function1(1, 1);\n" 1800 "\n" 1801 "%OptimizeFunctionOnNextCall(opt_function1)\n" 1802 "\n" 1803 "opt_function1(1, 1);\n" 1804 "\n" 1805 "opt_function1(NaN, 1);\n" 1806 "\n" 1807 "opt_function2(1, 1);\n" 1808 "\n" 1809 "%OptimizeFunctionOnNextCall(opt_function2)\n" 1810 "\n" 1811 "opt_function2(1, 1);\n" 1812 "\n" 1813 "opt_function2(0, 1);\n" 1814 "\n" 1815 "stopProfiling();\n" 1816 "\n"; 1817 1818 v8::Script::Compile(env, v8_str(source)) 1819 .ToLocalChecked() 1820 ->Run(env) 1821 .ToLocalChecked(); 1822 i::CpuProfile* iprofile = iprofiler->GetProfile(0); 1823 iprofile->Print(); 1824 /* The expected profile 1825 [Top down]: 1826 0 (root) 0 #1 1827 23 32 #2 1828 1 opt_function2 31 #7 1829 1 opt_function2 31 #8 1830 ;;; deopted at script_id: 31 position: 106 with reason 1831 'division by zero'. 1832 2 opt_function0 29 #3 1833 4 opt_function0 29 #4 1834 ;;; deopted at script_id: 29 position: 108 with reason 'not a 1835 heap number'. 1836 0 opt_function1 30 #5 1837 1 opt_function1 30 #6 1838 ;;; deopted at script_id: 30 position: 108 with reason 'lost 1839 precision or NaN'. 1840 */ 1841 1842 { 1843 const char* branch[] = {"", "opt_function0", "opt_function0"}; 1844 CHECK_EQ(reason(i::Deoptimizer::kNotAHeapNumber), 1845 GetBranchDeoptReason(env, iprofile, branch, arraysize(branch))); 1846 } 1847 { 1848 const char* branch[] = {"", "opt_function1", "opt_function1"}; 1849 const char* deopt_reason = 1850 GetBranchDeoptReason(env, iprofile, branch, arraysize(branch)); 1851 if (deopt_reason != reason(i::Deoptimizer::kNaN) && 1852 deopt_reason != reason(i::Deoptimizer::kLostPrecisionOrNaN)) { 1853 FATAL(deopt_reason); 1854 } 1855 } 1856 { 1857 const char* branch[] = {"", "opt_function2", "opt_function2"}; 1858 CHECK_EQ(reason(i::Deoptimizer::kDivisionByZero), 1859 GetBranchDeoptReason(env, iprofile, branch, arraysize(branch))); 1860 } 1861 iprofiler->DeleteProfile(iprofile); 1862 } 1863 1864 1865 TEST(SourceLocation) { 1866 i::FLAG_always_opt = true; 1867 i::FLAG_hydrogen_track_positions = true; 1868 LocalContext env; 1869 v8::HandleScope scope(CcTest::isolate()); 1870 1871 const char* source = 1872 "function CompareStatementWithThis() {\n" 1873 " if (this === 1) {}\n" 1874 "}\n" 1875 "CompareStatementWithThis();\n"; 1876 1877 v8::Script::Compile(env.local(), v8_str(source)) 1878 .ToLocalChecked() 1879 ->Run(env.local()) 1880 .ToLocalChecked(); 1881 } 1882 1883 1884 static const char* inlined_source = 1885 "function opt_function(left, right) { var k = left / 10; var r = 10 / " 1886 "right; return k + r; }\n"; 1887 // 0.........1.........2.........3.........4....*....5.........6......*..7 1888 1889 1890 // deopt at the first level inlined function 1891 TEST(DeoptAtFirstLevelInlinedSource) { 1892 if (!CcTest::i_isolate()->use_crankshaft() || i::FLAG_always_opt) return; 1893 i::FLAG_allow_natives_syntax = true; 1894 v8::HandleScope scope(CcTest::isolate()); 1895 v8::Local<v8::Context> env = CcTest::NewContext(PROFILER_EXTENSION); 1896 v8::Context::Scope context_scope(env); 1897 v8::Isolate* isolate = env->GetIsolate(); 1898 v8::CpuProfiler* profiler = isolate->GetCpuProfiler(); 1899 i::CpuProfiler* iprofiler = reinterpret_cast<i::CpuProfiler*>(profiler); 1900 1901 // 0.........1.........2.........3.........4.........5.........6.........7 1902 const char* source = 1903 "function test(left, right) { return opt_function(left, right); }\n" 1904 "\n" 1905 "startProfiling();\n" 1906 "\n" 1907 "test(10, 10);\n" 1908 "\n" 1909 "%OptimizeFunctionOnNextCall(test)\n" 1910 "\n" 1911 "test(10, 10);\n" 1912 "\n" 1913 "test(undefined, 10);\n" 1914 "\n" 1915 "stopProfiling();\n" 1916 "\n"; 1917 1918 v8::Local<v8::Script> inlined_script = v8_compile(inlined_source); 1919 inlined_script->Run(env).ToLocalChecked(); 1920 int inlined_script_id = inlined_script->GetUnboundScript()->GetId(); 1921 1922 v8::Local<v8::Script> script = v8_compile(source); 1923 script->Run(env).ToLocalChecked(); 1924 int script_id = script->GetUnboundScript()->GetId(); 1925 1926 i::CpuProfile* iprofile = iprofiler->GetProfile(0); 1927 iprofile->Print(); 1928 /* The expected profile output 1929 [Top down]: 1930 0 (root) 0 #1 1931 10 30 #2 1932 1 test 30 #3 1933 ;;; deopted at script_id: 29 position: 45 with reason 'not a 1934 heap number'. 1935 ;;; Inline point: script_id 30 position: 36. 1936 4 opt_function 29 #4 1937 */ 1938 v8::CpuProfile* profile = reinterpret_cast<v8::CpuProfile*>(iprofile); 1939 1940 const char* branch[] = {"", "test"}; 1941 const ProfileNode* itest_node = 1942 GetSimpleBranch(env, profile, branch, arraysize(branch)); 1943 const std::vector<v8::CpuProfileDeoptInfo>& deopt_infos = 1944 itest_node->deopt_infos(); 1945 CHECK_EQ(1U, deopt_infos.size()); 1946 1947 const v8::CpuProfileDeoptInfo& info = deopt_infos[0]; 1948 CHECK_EQ(reason(i::Deoptimizer::kNotAHeapNumber), info.deopt_reason); 1949 CHECK_EQ(2U, info.stack.size()); 1950 CHECK_EQ(inlined_script_id, info.stack[0].script_id); 1951 CHECK_EQ(offset(inlined_source, "left /"), info.stack[0].position); 1952 CHECK_EQ(script_id, info.stack[1].script_id); 1953 CHECK_EQ(offset(source, "opt_function(left,"), info.stack[1].position); 1954 1955 iprofiler->DeleteProfile(iprofile); 1956 } 1957 1958 1959 // deopt at the second level inlined function 1960 TEST(DeoptAtSecondLevelInlinedSource) { 1961 if (!CcTest::i_isolate()->use_crankshaft() || i::FLAG_always_opt) return; 1962 i::FLAG_allow_natives_syntax = true; 1963 v8::HandleScope scope(CcTest::isolate()); 1964 v8::Local<v8::Context> env = CcTest::NewContext(PROFILER_EXTENSION); 1965 v8::Context::Scope context_scope(env); 1966 v8::Isolate* isolate = env->GetIsolate(); 1967 v8::CpuProfiler* profiler = isolate->GetCpuProfiler(); 1968 i::CpuProfiler* iprofiler = reinterpret_cast<i::CpuProfiler*>(profiler); 1969 1970 // 0.........1.........2.........3.........4.........5.........6.........7 1971 const char* source = 1972 "function test2(left, right) { return opt_function(left, right); }\n" 1973 "function test1(left, right) { return test2(left, right); }\n" 1974 "\n" 1975 "startProfiling();\n" 1976 "\n" 1977 "test1(10, 10);\n" 1978 "\n" 1979 "%OptimizeFunctionOnNextCall(test1)\n" 1980 "\n" 1981 "test1(10, 10);\n" 1982 "\n" 1983 "test1(undefined, 10);\n" 1984 "\n" 1985 "stopProfiling();\n" 1986 "\n"; 1987 1988 v8::Local<v8::Script> inlined_script = v8_compile(inlined_source); 1989 inlined_script->Run(env).ToLocalChecked(); 1990 int inlined_script_id = inlined_script->GetUnboundScript()->GetId(); 1991 1992 v8::Local<v8::Script> script = v8_compile(source); 1993 script->Run(env).ToLocalChecked(); 1994 int script_id = script->GetUnboundScript()->GetId(); 1995 1996 i::CpuProfile* iprofile = iprofiler->GetProfile(0); 1997 iprofile->Print(); 1998 /* The expected profile output 1999 [Top down]: 2000 0 (root) 0 #1 2001 11 30 #2 2002 1 test1 30 #3 2003 ;;; deopted at script_id: 29 position: 45 with reason 'not a 2004 heap number'. 2005 ;;; Inline point: script_id 30 position: 37. 2006 ;;; Inline point: script_id 30 position: 103. 2007 1 test2 30 #4 2008 3 opt_function 29 #5 2009 */ 2010 2011 v8::CpuProfile* profile = reinterpret_cast<v8::CpuProfile*>(iprofile); 2012 2013 const char* branch[] = {"", "test1"}; 2014 const ProfileNode* itest_node = 2015 GetSimpleBranch(env, profile, branch, arraysize(branch)); 2016 const std::vector<v8::CpuProfileDeoptInfo>& deopt_infos = 2017 itest_node->deopt_infos(); 2018 CHECK_EQ(1U, deopt_infos.size()); 2019 2020 const v8::CpuProfileDeoptInfo info = deopt_infos[0]; 2021 CHECK_EQ(reason(i::Deoptimizer::kNotAHeapNumber), info.deopt_reason); 2022 CHECK_EQ(3U, info.stack.size()); 2023 CHECK_EQ(inlined_script_id, info.stack[0].script_id); 2024 CHECK_EQ(offset(inlined_source, "left /"), info.stack[0].position); 2025 CHECK_EQ(script_id, info.stack[1].script_id); 2026 CHECK_EQ(offset(source, "opt_function(left,"), info.stack[1].position); 2027 CHECK_EQ(offset(source, "test2(left, right);"), info.stack[2].position); 2028 2029 iprofiler->DeleteProfile(iprofile); 2030 } 2031 2032 2033 // deopt in untracked function 2034 TEST(DeoptUntrackedFunction) { 2035 if (!CcTest::i_isolate()->use_crankshaft() || i::FLAG_always_opt) return; 2036 i::FLAG_allow_natives_syntax = true; 2037 v8::HandleScope scope(CcTest::isolate()); 2038 v8::Local<v8::Context> env = CcTest::NewContext(PROFILER_EXTENSION); 2039 v8::Context::Scope context_scope(env); 2040 v8::Isolate* isolate = env->GetIsolate(); 2041 v8::CpuProfiler* profiler = isolate->GetCpuProfiler(); 2042 i::CpuProfiler* iprofiler = reinterpret_cast<i::CpuProfiler*>(profiler); 2043 2044 // 0.........1.........2.........3.........4.........5.........6.........7 2045 const char* source = 2046 "function test(left, right) { return opt_function(left, right); }\n" 2047 "\n" 2048 "test(10, 10);\n" 2049 "\n" 2050 "%OptimizeFunctionOnNextCall(test)\n" 2051 "\n" 2052 "test(10, 10);\n" 2053 "\n" 2054 "startProfiling();\n" // profiler started after compilation. 2055 "\n" 2056 "test(undefined, 10);\n" 2057 "\n" 2058 "stopProfiling();\n" 2059 "\n"; 2060 2061 v8::Local<v8::Script> inlined_script = v8_compile(inlined_source); 2062 inlined_script->Run(env).ToLocalChecked(); 2063 2064 v8::Local<v8::Script> script = v8_compile(source); 2065 script->Run(env).ToLocalChecked(); 2066 2067 i::CpuProfile* iprofile = iprofiler->GetProfile(0); 2068 iprofile->Print(); 2069 v8::CpuProfile* profile = reinterpret_cast<v8::CpuProfile*>(iprofile); 2070 2071 const char* branch[] = {"", "test"}; 2072 const ProfileNode* itest_node = 2073 GetSimpleBranch(env, profile, branch, arraysize(branch)); 2074 CHECK_EQ(0U, itest_node->deopt_infos().size()); 2075 2076 iprofiler->DeleteProfile(iprofile); 2077 } 2078
