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