1 // Copyright 2006-2009 the V8 project authors. All rights reserved. 2 // 3 // Tests of logging functions from log.h 4 5 #ifdef ENABLE_LOGGING_AND_PROFILING 6 7 #ifdef __linux__ 8 #include <math.h> 9 #include <pthread.h> 10 #include <signal.h> 11 #include <unistd.h> 12 #endif // __linux__ 13 14 #include "v8.h" 15 #include "log.h" 16 #include "cpu-profiler.h" 17 #include "v8threads.h" 18 #include "cctest.h" 19 #include "vm-state-inl.h" 20 21 using v8::internal::Address; 22 using v8::internal::EmbeddedVector; 23 using v8::internal::Logger; 24 using v8::internal::StrLength; 25 26 namespace i = v8::internal; 27 28 static void SetUp() { 29 // Log to memory buffer. 30 i::FLAG_logfile = "*"; 31 i::FLAG_log = true; 32 ISOLATE->InitializeLoggingAndCounters(); 33 LOGGER->Setup(); 34 } 35 36 static void TearDown() { 37 LOGGER->TearDown(); 38 } 39 40 41 TEST(EmptyLog) { 42 SetUp(); 43 CHECK_EQ(0, LOGGER->GetLogLines(0, NULL, 0)); 44 CHECK_EQ(0, LOGGER->GetLogLines(100, NULL, 0)); 45 CHECK_EQ(0, LOGGER->GetLogLines(0, NULL, 100)); 46 CHECK_EQ(0, LOGGER->GetLogLines(100, NULL, 100)); 47 TearDown(); 48 } 49 50 51 TEST(GetMessages) { 52 SetUp(); 53 LOGGER->StringEvent("aaa", "bbb"); 54 LOGGER->StringEvent("cccc", "dddd"); 55 CHECK_EQ(0, LOGGER->GetLogLines(0, NULL, 0)); 56 char log_lines[100]; 57 memset(log_lines, 0, sizeof(log_lines)); 58 // See Logger::StringEvent. 59 const char* line_1 = "aaa,\"bbb\"\n"; 60 const int line_1_len = StrLength(line_1); 61 // The exact size. 62 CHECK_EQ(line_1_len, LOGGER->GetLogLines(0, log_lines, line_1_len)); 63 CHECK_EQ(line_1, log_lines); 64 memset(log_lines, 0, sizeof(log_lines)); 65 // A bit more than the first line length. 66 CHECK_EQ(line_1_len, LOGGER->GetLogLines(0, log_lines, line_1_len + 3)); 67 log_lines[line_1_len] = '\0'; 68 CHECK_EQ(line_1, log_lines); 69 memset(log_lines, 0, sizeof(log_lines)); 70 const char* line_2 = "cccc,\"dddd\"\n"; 71 const int line_2_len = StrLength(line_2); 72 // Now start with line_2 beginning. 73 CHECK_EQ(0, LOGGER->GetLogLines(line_1_len, log_lines, 0)); 74 CHECK_EQ(line_2_len, LOGGER->GetLogLines(line_1_len, log_lines, line_2_len)); 75 CHECK_EQ(line_2, log_lines); 76 memset(log_lines, 0, sizeof(log_lines)); 77 CHECK_EQ(line_2_len, 78 LOGGER->GetLogLines(line_1_len, log_lines, line_2_len + 3)); 79 CHECK_EQ(line_2, log_lines); 80 memset(log_lines, 0, sizeof(log_lines)); 81 // Now get entire buffer contents. 82 const char* all_lines = "aaa,\"bbb\"\ncccc,\"dddd\"\n"; 83 const int all_lines_len = StrLength(all_lines); 84 CHECK_EQ(all_lines_len, LOGGER->GetLogLines(0, log_lines, all_lines_len)); 85 CHECK_EQ(all_lines, log_lines); 86 memset(log_lines, 0, sizeof(log_lines)); 87 CHECK_EQ(all_lines_len, LOGGER->GetLogLines(0, log_lines, all_lines_len + 3)); 88 CHECK_EQ(all_lines, log_lines); 89 memset(log_lines, 0, sizeof(log_lines)); 90 TearDown(); 91 } 92 93 94 static int GetLogLines(int start_pos, i::Vector<char>* buffer) { 95 return LOGGER->GetLogLines(start_pos, buffer->start(), buffer->length()); 96 } 97 98 99 TEST(BeyondWritePosition) { 100 SetUp(); 101 LOGGER->StringEvent("aaa", "bbb"); 102 LOGGER->StringEvent("cccc", "dddd"); 103 // See Logger::StringEvent. 104 const char* all_lines = "aaa,\"bbb\"\ncccc,\"dddd\"\n"; 105 const int all_lines_len = StrLength(all_lines); 106 EmbeddedVector<char, 100> buffer; 107 const int beyond_write_pos = all_lines_len; 108 CHECK_EQ(0, LOGGER->GetLogLines(beyond_write_pos, buffer.start(), 1)); 109 CHECK_EQ(0, GetLogLines(beyond_write_pos, &buffer)); 110 CHECK_EQ(0, LOGGER->GetLogLines(beyond_write_pos + 1, buffer.start(), 1)); 111 CHECK_EQ(0, GetLogLines(beyond_write_pos + 1, &buffer)); 112 CHECK_EQ(0, LOGGER->GetLogLines(beyond_write_pos + 100, buffer.start(), 1)); 113 CHECK_EQ(0, GetLogLines(beyond_write_pos + 100, &buffer)); 114 CHECK_EQ(0, LOGGER->GetLogLines(10 * 1024 * 1024, buffer.start(), 1)); 115 CHECK_EQ(0, GetLogLines(10 * 1024 * 1024, &buffer)); 116 TearDown(); 117 } 118 119 120 TEST(MemoryLoggingTurnedOff) { 121 // Log to stdout 122 i::FLAG_logfile = "-"; 123 i::FLAG_log = true; 124 ISOLATE->InitializeLoggingAndCounters(); 125 LOGGER->Setup(); 126 CHECK_EQ(0, LOGGER->GetLogLines(0, NULL, 0)); 127 CHECK_EQ(0, LOGGER->GetLogLines(100, NULL, 0)); 128 CHECK_EQ(0, LOGGER->GetLogLines(0, NULL, 100)); 129 CHECK_EQ(0, LOGGER->GetLogLines(100, NULL, 100)); 130 LOGGER->TearDown(); 131 } 132 133 134 static void CompileAndRunScript(const char *src) { 135 v8::Script::Compile(v8::String::New(src))->Run(); 136 } 137 138 139 namespace v8 { 140 namespace internal { 141 142 class LoggerTestHelper : public AllStatic { 143 public: 144 static bool IsSamplerActive() { return LOGGER->IsProfilerSamplerActive(); } 145 static void ResetSamplesTaken() { 146 reinterpret_cast<Sampler*>(LOGGER->ticker_)->ResetSamplesTaken(); 147 } 148 static bool has_samples_taken() { 149 return reinterpret_cast<Sampler*>(LOGGER->ticker_)->samples_taken() > 0; 150 } 151 }; 152 153 } // namespace v8::internal 154 } // namespace v8 155 156 using v8::internal::LoggerTestHelper; 157 158 159 namespace { 160 161 class ScopedLoggerInitializer { 162 public: 163 explicit ScopedLoggerInitializer(bool prof_lazy) 164 : saved_prof_lazy_(i::FLAG_prof_lazy), 165 saved_prof_(i::FLAG_prof), 166 saved_prof_auto_(i::FLAG_prof_auto), 167 trick_to_run_init_flags_(init_flags_(prof_lazy)), 168 need_to_set_up_logger_(i::V8::IsRunning()), 169 scope_(), 170 env_(v8::Context::New()) { 171 if (need_to_set_up_logger_) LOGGER->Setup(); 172 env_->Enter(); 173 } 174 175 ~ScopedLoggerInitializer() { 176 env_->Exit(); 177 LOGGER->TearDown(); 178 i::FLAG_prof_lazy = saved_prof_lazy_; 179 i::FLAG_prof = saved_prof_; 180 i::FLAG_prof_auto = saved_prof_auto_; 181 } 182 183 v8::Handle<v8::Context>& env() { return env_; } 184 185 private: 186 static bool init_flags_(bool prof_lazy) { 187 i::FLAG_prof = true; 188 i::FLAG_prof_lazy = prof_lazy; 189 i::FLAG_prof_auto = false; 190 i::FLAG_logfile = "*"; 191 return prof_lazy; 192 } 193 194 const bool saved_prof_lazy_; 195 const bool saved_prof_; 196 const bool saved_prof_auto_; 197 const bool trick_to_run_init_flags_; 198 const bool need_to_set_up_logger_; 199 v8::HandleScope scope_; 200 v8::Handle<v8::Context> env_; 201 202 DISALLOW_COPY_AND_ASSIGN(ScopedLoggerInitializer); 203 }; 204 205 206 class LogBufferMatcher { 207 public: 208 LogBufferMatcher() { 209 // Skip all initially logged stuff. 210 log_pos_ = GetLogLines(0, &buffer_); 211 } 212 213 int log_pos() { return log_pos_; } 214 215 int GetNextChunk() { 216 int chunk_size = GetLogLines(log_pos_, &buffer_); 217 CHECK_GT(buffer_.length(), chunk_size); 218 buffer_[chunk_size] = '\0'; 219 log_pos_ += chunk_size; 220 return chunk_size; 221 } 222 223 const char* Find(const char* substr) { 224 return strstr(buffer_.start(), substr); 225 } 226 227 const char* Find(const i::Vector<char>& substr) { 228 return Find(substr.start()); 229 } 230 231 bool IsInSequence(const char* s1, const char* s2) { 232 const char* s1_pos = Find(s1); 233 const char* s2_pos = Find(s2); 234 CHECK_NE(NULL, s1_pos); 235 CHECK_NE(NULL, s2_pos); 236 return s1_pos < s2_pos; 237 } 238 239 void PrintBuffer() { 240 puts(buffer_.start()); 241 } 242 243 private: 244 EmbeddedVector<char, 102400> buffer_; 245 int log_pos_; 246 }; 247 248 } // namespace 249 250 251 static void CheckThatProfilerWorks(LogBufferMatcher* matcher) { 252 CHECK(i::RuntimeProfiler::IsEnabled() || 253 !LoggerTestHelper::IsSamplerActive()); 254 LoggerTestHelper::ResetSamplesTaken(); 255 256 LOGGER->ResumeProfiler(v8::PROFILER_MODULE_CPU, 0); 257 CHECK(LoggerTestHelper::IsSamplerActive()); 258 259 // Verify that the current map of compiled functions has been logged. 260 CHECK_GT(matcher->GetNextChunk(), 0); 261 const char* code_creation = "\ncode-creation,"; // eq. to /^code-creation,/ 262 CHECK_NE(NULL, matcher->Find(code_creation)); 263 264 // Force compiler to generate new code by parametrizing source. 265 EmbeddedVector<char, 100> script_src; 266 i::OS::SNPrintF(script_src, 267 "function f%d(x) { return %d * x; }" 268 "for (var i = 0; i < 10000; ++i) { f%d(i); }", 269 matcher->log_pos(), matcher->log_pos(), matcher->log_pos()); 270 // Run code for 200 msecs to get some ticks. 271 const double end_time = i::OS::TimeCurrentMillis() + 200; 272 while (i::OS::TimeCurrentMillis() < end_time) { 273 CompileAndRunScript(script_src.start()); 274 // Yield CPU to give Profiler thread a chance to process ticks. 275 i::OS::Sleep(1); 276 } 277 278 LOGGER->PauseProfiler(v8::PROFILER_MODULE_CPU, 0); 279 CHECK(i::RuntimeProfiler::IsEnabled() || 280 !LoggerTestHelper::IsSamplerActive()); 281 282 // Wait 50 msecs to allow Profiler thread to process the last 283 // tick sample it has got. 284 i::OS::Sleep(50); 285 286 // Now we must have compiler and tick records. 287 CHECK_GT(matcher->GetNextChunk(), 0); 288 matcher->PrintBuffer(); 289 CHECK_NE(NULL, matcher->Find(code_creation)); 290 const char* tick = "\ntick,"; 291 const bool ticks_found = matcher->Find(tick) != NULL; 292 CHECK_EQ(LoggerTestHelper::has_samples_taken(), ticks_found); 293 } 294 295 296 TEST(ProfLazyMode) { 297 ScopedLoggerInitializer initialize_logger(true); 298 299 if (!i::V8::UseCrankshaft()) return; 300 301 // No sampling should happen prior to resuming profiler unless we 302 // are runtime profiling. 303 CHECK(i::RuntimeProfiler::IsEnabled() || 304 !LoggerTestHelper::IsSamplerActive()); 305 306 LogBufferMatcher matcher; 307 // Nothing must be logged until profiling is resumed. 308 CHECK_EQ(0, matcher.log_pos()); 309 310 CompileAndRunScript("var a = (function(x) { return x + 1; })(10);"); 311 312 // Nothing must be logged while profiling is suspended. 313 CHECK_EQ(0, matcher.GetNextChunk()); 314 315 CheckThatProfilerWorks(&matcher); 316 317 CompileAndRunScript("var a = (function(x) { return x + 1; })(10);"); 318 319 // No new data beyond last retrieved position. 320 CHECK_EQ(0, matcher.GetNextChunk()); 321 322 // Check that profiling can be resumed again. 323 CheckThatProfilerWorks(&matcher); 324 } 325 326 327 // BUG(913). Need to implement support for profiling multiple VM threads. 328 #if 0 329 330 namespace { 331 332 class LoopingThread : public v8::internal::Thread { 333 public: 334 explicit LoopingThread(v8::internal::Isolate* isolate) 335 : v8::internal::Thread(isolate), 336 semaphore_(v8::internal::OS::CreateSemaphore(0)), 337 run_(true) { 338 } 339 340 virtual ~LoopingThread() { delete semaphore_; } 341 342 void Run() { 343 self_ = pthread_self(); 344 RunLoop(); 345 } 346 347 void SendSigProf() { pthread_kill(self_, SIGPROF); } 348 349 void Stop() { run_ = false; } 350 351 bool WaitForRunning() { return semaphore_->Wait(1000000); } 352 353 protected: 354 bool IsRunning() { return run_; } 355 356 virtual void RunLoop() = 0; 357 358 void SetV8ThreadId() { 359 v8_thread_id_ = v8::V8::GetCurrentThreadId(); 360 } 361 362 void SignalRunning() { semaphore_->Signal(); } 363 364 private: 365 v8::internal::Semaphore* semaphore_; 366 bool run_; 367 pthread_t self_; 368 int v8_thread_id_; 369 }; 370 371 372 class LoopingJsThread : public LoopingThread { 373 public: 374 explicit LoopingJsThread(v8::internal::Isolate* isolate) 375 : LoopingThread(isolate) { } 376 void RunLoop() { 377 v8::Locker locker; 378 CHECK(i::Isolate::Current() != NULL); 379 CHECK_GT(i::Isolate::Current()->thread_manager()->CurrentId(), 0); 380 SetV8ThreadId(); 381 while (IsRunning()) { 382 v8::HandleScope scope; 383 v8::Persistent<v8::Context> context = v8::Context::New(); 384 CHECK(!context.IsEmpty()); 385 { 386 v8::Context::Scope context_scope(context); 387 SignalRunning(); 388 CompileAndRunScript( 389 "var j; for (var i=0; i<10000; ++i) { j = Math.sin(i); }"); 390 } 391 context.Dispose(); 392 i::OS::Sleep(1); 393 } 394 } 395 }; 396 397 398 class LoopingNonJsThread : public LoopingThread { 399 public: 400 explicit LoopingNonJsThread(v8::internal::Isolate* isolate) 401 : LoopingThread(isolate) { } 402 void RunLoop() { 403 v8::Locker locker; 404 v8::Unlocker unlocker; 405 // Now thread has V8's id, but will not run VM code. 406 CHECK(i::Isolate::Current() != NULL); 407 CHECK_GT(i::Isolate::Current()->thread_manager()->CurrentId(), 0); 408 double i = 10; 409 SignalRunning(); 410 while (IsRunning()) { 411 i = sin(i); 412 i::OS::Sleep(1); 413 } 414 } 415 }; 416 417 418 class TestSampler : public v8::internal::Sampler { 419 public: 420 explicit TestSampler(v8::internal::Isolate* isolate) 421 : Sampler(isolate, 0, true, true), 422 semaphore_(v8::internal::OS::CreateSemaphore(0)), 423 was_sample_stack_called_(false) { 424 } 425 426 ~TestSampler() { delete semaphore_; } 427 428 void SampleStack(v8::internal::TickSample*) { 429 was_sample_stack_called_ = true; 430 } 431 432 void Tick(v8::internal::TickSample*) { semaphore_->Signal(); } 433 434 bool WaitForTick() { return semaphore_->Wait(1000000); } 435 436 void Reset() { was_sample_stack_called_ = false; } 437 438 bool WasSampleStackCalled() { return was_sample_stack_called_; } 439 440 private: 441 v8::internal::Semaphore* semaphore_; 442 bool was_sample_stack_called_; 443 }; 444 445 446 } // namespace 447 448 TEST(ProfMultipleThreads) { 449 TestSampler* sampler = NULL; 450 { 451 v8::Locker locker; 452 sampler = new TestSampler(v8::internal::Isolate::Current()); 453 sampler->Start(); 454 CHECK(sampler->IsActive()); 455 } 456 457 LoopingJsThread jsThread(v8::internal::Isolate::Current()); 458 jsThread.Start(); 459 LoopingNonJsThread nonJsThread(v8::internal::Isolate::Current()); 460 nonJsThread.Start(); 461 462 CHECK(!sampler->WasSampleStackCalled()); 463 jsThread.WaitForRunning(); 464 jsThread.SendSigProf(); 465 CHECK(sampler->WaitForTick()); 466 CHECK(sampler->WasSampleStackCalled()); 467 sampler->Reset(); 468 CHECK(!sampler->WasSampleStackCalled()); 469 nonJsThread.WaitForRunning(); 470 nonJsThread.SendSigProf(); 471 CHECK(!sampler->WaitForTick()); 472 CHECK(!sampler->WasSampleStackCalled()); 473 sampler->Stop(); 474 475 jsThread.Stop(); 476 nonJsThread.Stop(); 477 jsThread.Join(); 478 nonJsThread.Join(); 479 480 delete sampler; 481 } 482 483 #endif // __linux__ 484 485 486 // Test for issue http://crbug.com/23768 in Chromium. 487 // Heap can contain scripts with already disposed external sources. 488 // We need to verify that LogCompiledFunctions doesn't crash on them. 489 namespace { 490 491 class SimpleExternalString : public v8::String::ExternalStringResource { 492 public: 493 explicit SimpleExternalString(const char* source) 494 : utf_source_(StrLength(source)) { 495 for (int i = 0; i < utf_source_.length(); ++i) 496 utf_source_[i] = source[i]; 497 } 498 virtual ~SimpleExternalString() {} 499 virtual size_t length() const { return utf_source_.length(); } 500 virtual const uint16_t* data() const { return utf_source_.start(); } 501 private: 502 i::ScopedVector<uint16_t> utf_source_; 503 }; 504 505 } // namespace 506 507 TEST(Issue23768) { 508 v8::HandleScope scope; 509 v8::Handle<v8::Context> env = v8::Context::New(); 510 env->Enter(); 511 512 SimpleExternalString source_ext_str("(function ext() {})();"); 513 v8::Local<v8::String> source = v8::String::NewExternal(&source_ext_str); 514 // Script needs to have a name in order to trigger InitLineEnds execution. 515 v8::Handle<v8::String> origin = v8::String::New("issue-23768-test"); 516 v8::Handle<v8::Script> evil_script = v8::Script::Compile(source, origin); 517 CHECK(!evil_script.IsEmpty()); 518 CHECK(!evil_script->Run().IsEmpty()); 519 i::Handle<i::ExternalTwoByteString> i_source( 520 i::ExternalTwoByteString::cast(*v8::Utils::OpenHandle(*source))); 521 // This situation can happen if source was an external string disposed 522 // by its owner. 523 i_source->set_resource(NULL); 524 525 // Must not crash. 526 LOGGER->LogCompiledFunctions(); 527 } 528 529 530 static v8::Handle<v8::Value> ObjMethod1(const v8::Arguments& args) { 531 return v8::Handle<v8::Value>(); 532 } 533 534 TEST(LogCallbacks) { 535 ScopedLoggerInitializer initialize_logger(false); 536 LogBufferMatcher matcher; 537 538 v8::Persistent<v8::FunctionTemplate> obj = 539 v8::Persistent<v8::FunctionTemplate>::New(v8::FunctionTemplate::New()); 540 obj->SetClassName(v8::String::New("Obj")); 541 v8::Handle<v8::ObjectTemplate> proto = obj->PrototypeTemplate(); 542 v8::Local<v8::Signature> signature = v8::Signature::New(obj); 543 proto->Set(v8::String::New("method1"), 544 v8::FunctionTemplate::New(ObjMethod1, 545 v8::Handle<v8::Value>(), 546 signature), 547 static_cast<v8::PropertyAttribute>(v8::DontDelete)); 548 549 initialize_logger.env()->Global()->Set(v8_str("Obj"), obj->GetFunction()); 550 CompileAndRunScript("Obj.prototype.method1.toString();"); 551 552 LOGGER->LogCompiledFunctions(); 553 CHECK_GT(matcher.GetNextChunk(), 0); 554 555 const char* callback_rec = "code-creation,Callback,"; 556 char* pos = const_cast<char*>(matcher.Find(callback_rec)); 557 CHECK_NE(NULL, pos); 558 pos += strlen(callback_rec); 559 EmbeddedVector<char, 100> ref_data; 560 i::OS::SNPrintF(ref_data, 561 "0x%" V8PRIxPTR ",1,\"method1\"", ObjMethod1); 562 *(pos + strlen(ref_data.start())) = '\0'; 563 CHECK_EQ(ref_data.start(), pos); 564 565 obj.Dispose(); 566 } 567 568 569 static v8::Handle<v8::Value> Prop1Getter(v8::Local<v8::String> property, 570 const v8::AccessorInfo& info) { 571 return v8::Handle<v8::Value>(); 572 } 573 574 static void Prop1Setter(v8::Local<v8::String> property, 575 v8::Local<v8::Value> value, 576 const v8::AccessorInfo& info) { 577 } 578 579 static v8::Handle<v8::Value> Prop2Getter(v8::Local<v8::String> property, 580 const v8::AccessorInfo& info) { 581 return v8::Handle<v8::Value>(); 582 } 583 584 TEST(LogAccessorCallbacks) { 585 ScopedLoggerInitializer initialize_logger(false); 586 LogBufferMatcher matcher; 587 588 v8::Persistent<v8::FunctionTemplate> obj = 589 v8::Persistent<v8::FunctionTemplate>::New(v8::FunctionTemplate::New()); 590 obj->SetClassName(v8::String::New("Obj")); 591 v8::Handle<v8::ObjectTemplate> inst = obj->InstanceTemplate(); 592 inst->SetAccessor(v8::String::New("prop1"), Prop1Getter, Prop1Setter); 593 inst->SetAccessor(v8::String::New("prop2"), Prop2Getter); 594 595 LOGGER->LogAccessorCallbacks(); 596 CHECK_GT(matcher.GetNextChunk(), 0); 597 matcher.PrintBuffer(); 598 599 EmbeddedVector<char, 100> prop1_getter_record; 600 i::OS::SNPrintF(prop1_getter_record, 601 "code-creation,Callback,0x%" V8PRIxPTR ",1,\"get prop1\"", 602 Prop1Getter); 603 CHECK_NE(NULL, matcher.Find(prop1_getter_record)); 604 EmbeddedVector<char, 100> prop1_setter_record; 605 i::OS::SNPrintF(prop1_setter_record, 606 "code-creation,Callback,0x%" V8PRIxPTR ",1,\"set prop1\"", 607 Prop1Setter); 608 CHECK_NE(NULL, matcher.Find(prop1_setter_record)); 609 EmbeddedVector<char, 100> prop2_getter_record; 610 i::OS::SNPrintF(prop2_getter_record, 611 "code-creation,Callback,0x%" V8PRIxPTR ",1,\"get prop2\"", 612 Prop2Getter); 613 CHECK_NE(NULL, matcher.Find(prop2_getter_record)); 614 615 obj.Dispose(); 616 } 617 618 619 TEST(LogTags) { 620 ScopedLoggerInitializer initialize_logger(false); 621 LogBufferMatcher matcher; 622 623 const char* open_tag = "open-tag,"; 624 const char* close_tag = "close-tag,"; 625 626 // Check compatibility with the old style behavior. 627 CHECK_EQ(v8::PROFILER_MODULE_NONE, LOGGER->GetActiveProfilerModules()); 628 LOGGER->ResumeProfiler(v8::PROFILER_MODULE_CPU, 0); 629 CHECK_EQ(v8::PROFILER_MODULE_CPU, LOGGER->GetActiveProfilerModules()); 630 LOGGER->PauseProfiler(v8::PROFILER_MODULE_CPU, 0); 631 CHECK_EQ(v8::PROFILER_MODULE_NONE, LOGGER->GetActiveProfilerModules()); 632 CHECK_EQ(NULL, matcher.Find(open_tag)); 633 CHECK_EQ(NULL, matcher.Find(close_tag)); 634 635 const char* open_tag1 = "open-tag,1\n"; 636 const char* close_tag1 = "close-tag,1\n"; 637 638 // Check non-nested tag case. 639 CHECK_EQ(v8::PROFILER_MODULE_NONE, LOGGER->GetActiveProfilerModules()); 640 LOGGER->ResumeProfiler(v8::PROFILER_MODULE_CPU, 1); 641 CHECK_EQ(v8::PROFILER_MODULE_CPU, LOGGER->GetActiveProfilerModules()); 642 LOGGER->PauseProfiler(v8::PROFILER_MODULE_CPU, 1); 643 CHECK_EQ(v8::PROFILER_MODULE_NONE, LOGGER->GetActiveProfilerModules()); 644 CHECK_GT(matcher.GetNextChunk(), 0); 645 CHECK(matcher.IsInSequence(open_tag1, close_tag1)); 646 647 const char* open_tag2 = "open-tag,2\n"; 648 const char* close_tag2 = "close-tag,2\n"; 649 650 // Check nested tags case. 651 CHECK_EQ(v8::PROFILER_MODULE_NONE, LOGGER->GetActiveProfilerModules()); 652 LOGGER->ResumeProfiler(v8::PROFILER_MODULE_CPU, 1); 653 CHECK_EQ(v8::PROFILER_MODULE_CPU, LOGGER->GetActiveProfilerModules()); 654 LOGGER->ResumeProfiler(v8::PROFILER_MODULE_CPU, 2); 655 CHECK_EQ(v8::PROFILER_MODULE_CPU, LOGGER->GetActiveProfilerModules()); 656 LOGGER->PauseProfiler(v8::PROFILER_MODULE_CPU, 2); 657 CHECK_EQ(v8::PROFILER_MODULE_CPU, LOGGER->GetActiveProfilerModules()); 658 LOGGER->PauseProfiler(v8::PROFILER_MODULE_CPU, 1); 659 CHECK_EQ(v8::PROFILER_MODULE_NONE, LOGGER->GetActiveProfilerModules()); 660 CHECK_GT(matcher.GetNextChunk(), 0); 661 // open_tag1 < open_tag2 < close_tag2 < close_tag1 662 CHECK(matcher.IsInSequence(open_tag1, open_tag2)); 663 CHECK(matcher.IsInSequence(open_tag2, close_tag2)); 664 CHECK(matcher.IsInSequence(close_tag2, close_tag1)); 665 666 // Check overlapped tags case. 667 CHECK_EQ(v8::PROFILER_MODULE_NONE, LOGGER->GetActiveProfilerModules()); 668 LOGGER->ResumeProfiler(v8::PROFILER_MODULE_CPU, 1); 669 CHECK_EQ(v8::PROFILER_MODULE_CPU, LOGGER->GetActiveProfilerModules()); 670 LOGGER->ResumeProfiler(v8::PROFILER_MODULE_CPU, 2); 671 CHECK_EQ(v8::PROFILER_MODULE_CPU, LOGGER->GetActiveProfilerModules()); 672 LOGGER->PauseProfiler(v8::PROFILER_MODULE_CPU, 1); 673 CHECK_EQ(v8::PROFILER_MODULE_CPU, LOGGER->GetActiveProfilerModules()); 674 LOGGER->PauseProfiler(v8::PROFILER_MODULE_CPU, 2); 675 CHECK_EQ(v8::PROFILER_MODULE_NONE, LOGGER->GetActiveProfilerModules()); 676 CHECK_GT(matcher.GetNextChunk(), 0); 677 // open_tag1 < open_tag2 < close_tag1 < close_tag2 678 CHECK(matcher.IsInSequence(open_tag1, open_tag2)); 679 CHECK(matcher.IsInSequence(open_tag2, close_tag1)); 680 CHECK(matcher.IsInSequence(close_tag1, close_tag2)); 681 682 const char* open_tag3 = "open-tag,3\n"; 683 const char* close_tag3 = "close-tag,3\n"; 684 685 // Check pausing overflow case. 686 CHECK_EQ(v8::PROFILER_MODULE_NONE, LOGGER->GetActiveProfilerModules()); 687 LOGGER->ResumeProfiler(v8::PROFILER_MODULE_CPU, 1); 688 CHECK_EQ(v8::PROFILER_MODULE_CPU, LOGGER->GetActiveProfilerModules()); 689 LOGGER->ResumeProfiler(v8::PROFILER_MODULE_CPU, 2); 690 CHECK_EQ(v8::PROFILER_MODULE_CPU, LOGGER->GetActiveProfilerModules()); 691 LOGGER->PauseProfiler(v8::PROFILER_MODULE_CPU, 2); 692 CHECK_EQ(v8::PROFILER_MODULE_CPU, LOGGER->GetActiveProfilerModules()); 693 LOGGER->PauseProfiler(v8::PROFILER_MODULE_CPU, 1); 694 CHECK_EQ(v8::PROFILER_MODULE_NONE, LOGGER->GetActiveProfilerModules()); 695 LOGGER->PauseProfiler(v8::PROFILER_MODULE_CPU, 3); 696 CHECK_EQ(v8::PROFILER_MODULE_NONE, LOGGER->GetActiveProfilerModules()); 697 LOGGER->ResumeProfiler(v8::PROFILER_MODULE_CPU, 3); 698 CHECK_EQ(v8::PROFILER_MODULE_NONE, LOGGER->GetActiveProfilerModules()); 699 // Must be no tags, because logging must be disabled. 700 CHECK_EQ(NULL, matcher.Find(open_tag3)); 701 CHECK_EQ(NULL, matcher.Find(close_tag3)); 702 } 703 704 705 TEST(IsLoggingPreserved) { 706 ScopedLoggerInitializer initialize_logger(false); 707 708 CHECK(LOGGER->is_logging()); 709 LOGGER->ResumeProfiler(v8::PROFILER_MODULE_CPU, 1); 710 CHECK(LOGGER->is_logging()); 711 LOGGER->PauseProfiler(v8::PROFILER_MODULE_CPU, 1); 712 CHECK(LOGGER->is_logging()); 713 714 CHECK(LOGGER->is_logging()); 715 LOGGER->ResumeProfiler( 716 v8::PROFILER_MODULE_HEAP_STATS | v8::PROFILER_MODULE_JS_CONSTRUCTORS, 1); 717 CHECK(LOGGER->is_logging()); 718 LOGGER->PauseProfiler( 719 v8::PROFILER_MODULE_HEAP_STATS | v8::PROFILER_MODULE_JS_CONSTRUCTORS, 1); 720 CHECK(LOGGER->is_logging()); 721 722 CHECK(LOGGER->is_logging()); 723 LOGGER->ResumeProfiler( 724 v8::PROFILER_MODULE_CPU | 725 v8::PROFILER_MODULE_HEAP_STATS | v8::PROFILER_MODULE_JS_CONSTRUCTORS, 1); 726 CHECK(LOGGER->is_logging()); 727 LOGGER->PauseProfiler( 728 v8::PROFILER_MODULE_CPU | 729 v8::PROFILER_MODULE_HEAP_STATS | v8::PROFILER_MODULE_JS_CONSTRUCTORS, 1); 730 CHECK(LOGGER->is_logging()); 731 } 732 733 734 static inline bool IsStringEqualTo(const char* r, const char* s) { 735 return strncmp(r, s, strlen(r)) == 0; 736 } 737 738 739 static bool Consume(const char* str, char** buf) { 740 if (IsStringEqualTo(str, *buf)) { 741 *buf += strlen(str); 742 return true; 743 } 744 return false; 745 } 746 747 748 namespace { 749 750 // A code entity is a pointer to a position of code-creation event in buffer log 751 // offset to a point where entity size begins, i.e.: '255,"func"\n'. This makes 752 // comparing code entities pretty easy. 753 typedef char* CodeEntityInfo; 754 755 class Interval { 756 public: 757 Interval() 758 : min_addr_(reinterpret_cast<Address>(-1)), 759 max_addr_(reinterpret_cast<Address>(0)), next_(NULL) {} 760 761 ~Interval() { delete next_; } 762 763 size_t Length() { 764 size_t result = max_addr_ - min_addr_ + 1; 765 if (next_ != NULL) result += next_->Length(); 766 return result; 767 } 768 769 void CloneFrom(Interval* src) { 770 while (src != NULL) { 771 RegisterAddress(src->min_addr_); 772 RegisterAddress(src->max_addr_); 773 src = src->next_; 774 } 775 } 776 777 bool Contains(Address addr) { 778 if (min_addr_ <= addr && addr <= max_addr_) { 779 return true; 780 } 781 if (next_ != NULL) { 782 return next_->Contains(addr); 783 } else { 784 return false; 785 } 786 } 787 788 size_t GetIndex(Address addr) { 789 if (min_addr_ <= addr && addr <= max_addr_) { 790 return addr - min_addr_; 791 } 792 CHECK_NE(NULL, next_); 793 return (max_addr_ - min_addr_ + 1) + next_->GetIndex(addr); 794 } 795 796 Address GetMinAddr() { 797 return next_ == NULL ? min_addr_ : i::Min(min_addr_, next_->GetMinAddr()); 798 } 799 800 Address GetMaxAddr() { 801 return next_ == NULL ? max_addr_ : i::Max(max_addr_, next_->GetMaxAddr()); 802 } 803 804 void RegisterAddress(Address addr) { 805 if (min_addr_ == reinterpret_cast<Address>(-1) 806 || (size_t)(addr > min_addr_ ? 807 addr - min_addr_ : min_addr_ - addr) < MAX_DELTA) { 808 if (addr < min_addr_) min_addr_ = addr; 809 if (addr > max_addr_) max_addr_ = addr; 810 } else { 811 if (next_ == NULL) next_ = new Interval(); 812 next_->RegisterAddress(addr); 813 } 814 } 815 816 Address raw_min_addr() { return min_addr_; } 817 818 Address raw_max_addr() { return max_addr_; } 819 820 Interval* get_next() { return next_; } 821 822 private: 823 static const size_t MAX_DELTA = 0x100000; 824 Address min_addr_; 825 Address max_addr_; 826 Interval* next_; 827 }; 828 829 830 // A structure used to return log parsing results. 831 class ParseLogResult { 832 public: 833 ParseLogResult() 834 : entities_map(NULL), entities(NULL), 835 max_entities(0) {} 836 837 ~ParseLogResult() { 838 i::DeleteArray(entities_map); 839 i::DeleteArray(entities); 840 } 841 842 void AllocateEntities() { 843 // Make sure that the test doesn't operate on a bogus log. 844 CHECK_GT(max_entities, 0); 845 CHECK_GT(bounds.GetMinAddr(), 0); 846 CHECK_GT(bounds.GetMaxAddr(), bounds.GetMinAddr()); 847 848 entities = i::NewArray<CodeEntityInfo>(max_entities); 849 for (int i = 0; i < max_entities; ++i) { 850 entities[i] = NULL; 851 } 852 const size_t map_length = bounds.Length(); 853 entities_map = i::NewArray<int>(static_cast<int>(map_length)); 854 for (size_t i = 0; i < map_length; ++i) { 855 entities_map[i] = -1; 856 } 857 } 858 859 bool HasIndexForAddress(Address addr) { 860 return bounds.Contains(addr); 861 } 862 863 size_t GetIndexForAddress(Address addr) { 864 CHECK(HasIndexForAddress(addr)); 865 return bounds.GetIndex(addr); 866 } 867 868 CodeEntityInfo GetEntity(Address addr) { 869 if (HasIndexForAddress(addr)) { 870 size_t idx = GetIndexForAddress(addr); 871 int item = entities_map[idx]; 872 return item != -1 ? entities[item] : NULL; 873 } 874 return NULL; 875 } 876 877 void ParseAddress(char* start) { 878 Address addr = 879 reinterpret_cast<Address>(strtoul(start, NULL, 16)); // NOLINT 880 bounds.RegisterAddress(addr); 881 } 882 883 Address ConsumeAddress(char** start) { 884 char* end_ptr; 885 Address addr = 886 reinterpret_cast<Address>(strtoul(*start, &end_ptr, 16)); // NOLINT 887 CHECK(HasIndexForAddress(addr)); 888 *start = end_ptr; 889 return addr; 890 } 891 892 Interval bounds; 893 // Memory map of entities start addresses. 894 int* entities_map; 895 // An array of code entities. 896 CodeEntityInfo* entities; 897 // Maximal entities count. Actual entities count can be lower, 898 // empty entity slots are pointing to NULL. 899 int max_entities; 900 }; 901 902 } // namespace 903 904 905 typedef void (*ParserBlock)(char* start, char* end, ParseLogResult* result); 906 907 static void ParserCycle( 908 char* start, char* end, ParseLogResult* result, 909 ParserBlock block_creation, ParserBlock block_delete, 910 ParserBlock block_move) { 911 912 const char* code_creation = "code-creation,"; 913 const char* code_delete = "code-delete,"; 914 const char* code_move = "code-move,"; 915 916 const char* lazy_compile = "LazyCompile,"; 917 const char* script = "Script,"; 918 const char* function = "Function,"; 919 920 while (start < end) { 921 if (Consume(code_creation, &start)) { 922 if (Consume(lazy_compile, &start) 923 || Consume(script, &start) 924 || Consume(function, &start)) { 925 block_creation(start, end, result); 926 } 927 } else if (Consume(code_delete, &start)) { 928 block_delete(start, end, result); 929 } else if (Consume(code_move, &start)) { 930 block_move(start, end, result); 931 } 932 while (start < end && *start != '\n') ++start; 933 ++start; 934 } 935 } 936 937 938 static void Pass1CodeCreation(char* start, char* end, ParseLogResult* result) { 939 result->ParseAddress(start); 940 ++result->max_entities; 941 } 942 943 944 static void Pass1CodeDelete(char* start, char* end, ParseLogResult* result) { 945 result->ParseAddress(start); 946 } 947 948 949 static void Pass1CodeMove(char* start, char* end, ParseLogResult* result) { 950 result->ParseAddress(start); 951 // Skip old address. 952 while (start < end && *start != ',') ++start; 953 CHECK_GT(end, start); 954 ++start; // Skip ','. 955 result->ParseAddress(start); 956 } 957 958 959 static void Pass2CodeCreation(char* start, char* end, ParseLogResult* result) { 960 Address addr = result->ConsumeAddress(&start); 961 CHECK_GT(end, start); 962 ++start; // Skip ','. 963 964 size_t idx = result->GetIndexForAddress(addr); 965 result->entities_map[idx] = -1; 966 for (int i = 0; i < result->max_entities; ++i) { 967 // Find an empty slot and fill it. 968 if (result->entities[i] == NULL) { 969 result->entities[i] = start; 970 result->entities_map[idx] = i; 971 break; 972 } 973 } 974 // Make sure that a slot was found. 975 CHECK_GE(result->entities_map[idx], 0); 976 } 977 978 979 static void Pass2CodeDelete(char* start, char* end, ParseLogResult* result) { 980 Address addr = result->ConsumeAddress(&start); 981 size_t idx = result->GetIndexForAddress(addr); 982 // There can be code deletes that are not related to JS code. 983 if (result->entities_map[idx] >= 0) { 984 result->entities[result->entities_map[idx]] = NULL; 985 result->entities_map[idx] = -1; 986 } 987 } 988 989 990 static void Pass2CodeMove(char* start, char* end, ParseLogResult* result) { 991 Address from_addr = result->ConsumeAddress(&start); 992 CHECK_GT(end, start); 993 ++start; // Skip ','. 994 Address to_addr = result->ConsumeAddress(&start); 995 CHECK_GT(end, start); 996 997 size_t from_idx = result->GetIndexForAddress(from_addr); 998 size_t to_idx = result->GetIndexForAddress(to_addr); 999 // There can be code moves that are not related to JS code. 1000 if (from_idx != to_idx && result->entities_map[from_idx] >= 0) { 1001 CHECK_EQ(-1, result->entities_map[to_idx]); 1002 result->entities_map[to_idx] = result->entities_map[from_idx]; 1003 result->entities_map[from_idx] = -1; 1004 }; 1005 } 1006 1007 1008 static void ParseLog(char* start, char* end, ParseLogResult* result) { 1009 // Pass 1: Calculate boundaries of addresses and entities count. 1010 ParserCycle(start, end, result, 1011 Pass1CodeCreation, Pass1CodeDelete, Pass1CodeMove); 1012 1013 printf("min_addr: %p, max_addr: %p, entities: %d\n", 1014 result->bounds.GetMinAddr(), result->bounds.GetMaxAddr(), 1015 result->max_entities); 1016 1017 result->AllocateEntities(); 1018 1019 // Pass 2: Fill in code entries data. 1020 ParserCycle(start, end, result, 1021 Pass2CodeCreation, Pass2CodeDelete, Pass2CodeMove); 1022 } 1023 1024 1025 static inline void PrintCodeEntityInfo(CodeEntityInfo entity) { 1026 const int max_len = 50; 1027 if (entity != NULL) { 1028 char* eol = strchr(entity, '\n'); 1029 int len = static_cast<int>(eol - entity); 1030 len = len <= max_len ? len : max_len; 1031 printf("%-*.*s ", max_len, len, entity); 1032 } else { 1033 printf("%*s", max_len + 1, ""); 1034 } 1035 } 1036 1037 1038 static void PrintCodeEntitiesInfo( 1039 bool is_equal, Address addr, 1040 CodeEntityInfo l_entity, CodeEntityInfo r_entity) { 1041 printf("%c %p ", is_equal ? ' ' : '*', addr); 1042 PrintCodeEntityInfo(l_entity); 1043 PrintCodeEntityInfo(r_entity); 1044 printf("\n"); 1045 } 1046 1047 1048 static inline int StrChrLen(const char* s, char c) { 1049 return static_cast<int>(strchr(s, c) - s); 1050 } 1051 1052 1053 static bool AreFuncSizesEqual(CodeEntityInfo ref_s, CodeEntityInfo new_s) { 1054 int ref_len = StrChrLen(ref_s, ','); 1055 int new_len = StrChrLen(new_s, ','); 1056 return ref_len == new_len && strncmp(ref_s, new_s, ref_len) == 0; 1057 } 1058 1059 1060 static bool AreFuncNamesEqual(CodeEntityInfo ref_s, CodeEntityInfo new_s) { 1061 // Skip size. 1062 ref_s = strchr(ref_s, ',') + 1; 1063 new_s = strchr(new_s, ',') + 1; 1064 CHECK_EQ('"', ref_s[0]); 1065 CHECK_EQ('"', new_s[0]); 1066 int ref_len = StrChrLen(ref_s + 1, '\"'); 1067 int new_len = StrChrLen(new_s + 1, '\"'); 1068 // A special case for ErrorPrototype. Haven't yet figured out why they 1069 // are different. 1070 const char* error_prototype = "\"ErrorPrototype"; 1071 if (IsStringEqualTo(error_prototype, ref_s) 1072 && IsStringEqualTo(error_prototype, new_s)) { 1073 return true; 1074 } 1075 // Built-in objects have problems too. 1076 const char* built_ins[] = { 1077 "\"Boolean\"", "\"Function\"", "\"Number\"", 1078 "\"Object\"", "\"Script\"", "\"String\"" 1079 }; 1080 for (size_t i = 0; i < sizeof(built_ins) / sizeof(*built_ins); ++i) { 1081 if (IsStringEqualTo(built_ins[i], new_s)) { 1082 return true; 1083 } 1084 } 1085 return ref_len == new_len && strncmp(ref_s, new_s, ref_len) == 0; 1086 } 1087 1088 1089 static bool AreEntitiesEqual(CodeEntityInfo ref_e, CodeEntityInfo new_e) { 1090 if (ref_e == NULL && new_e != NULL) return true; 1091 if (ref_e != NULL && new_e != NULL) { 1092 return AreFuncSizesEqual(ref_e, new_e) && AreFuncNamesEqual(ref_e, new_e); 1093 } 1094 if (ref_e != NULL && new_e == NULL) { 1095 // args_count entities (argument adapters) are not found by heap traversal, 1096 // but they are not needed because they doesn't contain any code. 1097 ref_e = strchr(ref_e, ',') + 1; 1098 const char* args_count = "\"args_count:"; 1099 return IsStringEqualTo(args_count, ref_e); 1100 } 1101 return false; 1102 } 1103 1104 1105 // Test that logging of code create / move / delete events 1106 // is equivalent to traversal of a resulting heap. 1107 TEST(EquivalenceOfLoggingAndTraversal) { 1108 // This test needs to be run on a "clean" V8 to ensure that snapshot log 1109 // is loaded. This is always true when running using tools/test.py because 1110 // it launches a new cctest instance for every test. To be sure that launching 1111 // cctest manually also works, please be sure that no tests below 1112 // are using V8. 1113 // 1114 // P.S. No, V8 can't be re-initialized after disposal, see include/v8.h. 1115 CHECK(!i::V8::IsRunning()); 1116 1117 i::FLAG_logfile = "*"; 1118 i::FLAG_log = true; 1119 i::FLAG_log_code = true; 1120 1121 // Make sure objects move. 1122 bool saved_always_compact = i::FLAG_always_compact; 1123 if (!i::FLAG_never_compact) { 1124 i::FLAG_always_compact = true; 1125 } 1126 1127 v8::HandleScope scope; 1128 v8::Handle<v8::Value> global_object = v8::Handle<v8::Value>(); 1129 v8::Handle<v8::Context> env = v8::Context::New( 1130 0, v8::Handle<v8::ObjectTemplate>(), global_object); 1131 env->Enter(); 1132 1133 // Compile and run a function that creates other functions. 1134 CompileAndRunScript( 1135 "(function f(obj) {\n" 1136 " obj.test =\n" 1137 " (function a(j) { return function b() { return j; } })(100);\n" 1138 "})(this);"); 1139 HEAP->CollectAllGarbage(false); 1140 1141 EmbeddedVector<char, 204800> buffer; 1142 int log_size; 1143 ParseLogResult ref_result; 1144 1145 // Retrieve the log. 1146 { 1147 // Make sure that no GCs occur prior to LogCompiledFunctions call. 1148 i::AssertNoAllocation no_alloc; 1149 1150 log_size = GetLogLines(0, &buffer); 1151 CHECK_GT(log_size, 0); 1152 CHECK_GT(buffer.length(), log_size); 1153 1154 // Fill a map of compiled code objects. 1155 ParseLog(buffer.start(), buffer.start() + log_size, &ref_result); 1156 } 1157 1158 // Iterate heap to find compiled functions, will write to log. 1159 LOGGER->LogCompiledFunctions(); 1160 char* new_log_start = buffer.start() + log_size; 1161 const int new_log_size = LOGGER->GetLogLines( 1162 log_size, new_log_start, buffer.length() - log_size); 1163 CHECK_GT(new_log_size, 0); 1164 CHECK_GT(buffer.length(), log_size + new_log_size); 1165 1166 // Fill an equivalent map of compiled code objects. 1167 ParseLogResult new_result; 1168 ParseLog(new_log_start, new_log_start + new_log_size, &new_result); 1169 1170 // Test their actual equivalence. 1171 Interval combined; 1172 combined.CloneFrom(&ref_result.bounds); 1173 combined.CloneFrom(&new_result.bounds); 1174 Interval* iter = &combined; 1175 bool results_equal = true; 1176 1177 while (iter != NULL) { 1178 for (Address addr = iter->raw_min_addr(); 1179 addr <= iter->raw_max_addr(); ++addr) { 1180 CodeEntityInfo ref_entity = ref_result.GetEntity(addr); 1181 CodeEntityInfo new_entity = new_result.GetEntity(addr); 1182 if (ref_entity != NULL || new_entity != NULL) { 1183 const bool equal = AreEntitiesEqual(ref_entity, new_entity); 1184 if (!equal) results_equal = false; 1185 PrintCodeEntitiesInfo(equal, addr, ref_entity, new_entity); 1186 } 1187 } 1188 iter = iter->get_next(); 1189 } 1190 // Make sure that all log data is written prior crash due to CHECK failure. 1191 fflush(stdout); 1192 CHECK(results_equal); 1193 1194 env->Exit(); 1195 LOGGER->TearDown(); 1196 i::FLAG_always_compact = saved_always_compact; 1197 } 1198 1199 #endif // ENABLE_LOGGING_AND_PROFILING 1200