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