| OLD | NEW |
| 1 // Copyright 2006-2009 the V8 project authors. All rights reserved. | 1 // Copyright 2006-2009 the V8 project authors. All rights reserved. |
| 2 // | 2 // |
| 3 // Tests of logging functions from log.h | 3 // Tests of logging functions from log.h |
| 4 | 4 |
| 5 #ifdef ENABLE_LOGGING_AND_PROFILING | 5 #ifdef ENABLE_LOGGING_AND_PROFILING |
| 6 | 6 |
| 7 #ifdef __linux__ | 7 #ifdef __linux__ |
| 8 #include <math.h> | 8 #include <math.h> |
| 9 #include <pthread.h> | 9 #include <pthread.h> |
| 10 #include <signal.h> | 10 #include <signal.h> |
| 11 #include <unistd.h> | 11 #include <unistd.h> |
| 12 #endif // __linux__ | 12 #endif // __linux__ |
| 13 | 13 |
| 14 #include "v8.h" | 14 #include "v8.h" |
| 15 #include "log.h" | 15 #include "log.h" |
| 16 #include "cpu-profiler.h" | 16 #include "cpu-profiler.h" |
| 17 #include "v8threads.h" | 17 #include "v8threads.h" |
| 18 #include "cctest.h" | 18 #include "cctest.h" |
| 19 #include "vm-state-inl.h" | 19 #include "vm-state-inl.h" |
| 20 | 20 |
| 21 using v8::internal::Address; | 21 using v8::internal::Address; |
| 22 using v8::internal::EmbeddedVector; | 22 using v8::internal::EmbeddedVector; |
| 23 using v8::internal::Logger; | 23 using v8::internal::Logger; |
| 24 using v8::internal::StrLength; | 24 using v8::internal::StrLength; |
| 25 | 25 |
| 26 namespace i = v8::internal; | 26 namespace i = v8::internal; |
| 27 | 27 |
| 28 static void SetUp() { | |
| 29 // Log to memory buffer. | |
| 30 i::FLAG_logfile = "*"; | |
| 31 i::FLAG_log = true; | |
| 32 LOGGER->Setup(); | |
| 33 } | |
| 34 | |
| 35 static void TearDown() { | |
| 36 LOGGER->TearDown(); | |
| 37 } | |
| 38 | |
| 39 | |
| 40 TEST(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 | |
| 50 TEST(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 | |
| 93 static int GetLogLines(int start_pos, i::Vector<char>* buffer) { | |
| 94 return LOGGER->GetLogLines(start_pos, buffer->start(), buffer->length()); | |
| 95 } | |
| 96 | |
| 97 | |
| 98 TEST(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 | |
| 119 TEST(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 | |
| 132 static void CompileAndRunScript(const char *src) { | |
| 133 v8::Script::Compile(v8::String::New(src))->Run(); | |
| 134 } | |
| 135 | |
| 136 | |
| 137 namespace v8 { | |
| 138 namespace internal { | |
| 139 | |
| 140 class 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 | |
| 154 using v8::internal::LoggerTestHelper; | |
| 155 | |
| 156 | |
| 157 namespace { | 28 namespace { |
| 158 | 29 |
| 159 class ScopedLoggerInitializer { | 30 class ScopedLoggerInitializer { |
| 160 public: | 31 public: |
| 161 explicit ScopedLoggerInitializer(bool prof_lazy) | 32 explicit ScopedLoggerInitializer(bool prof_lazy) |
| 162 : saved_prof_lazy_(i::FLAG_prof_lazy), | 33 : saved_prof_lazy_(i::FLAG_prof_lazy), |
| 163 saved_prof_(i::FLAG_prof), | 34 saved_prof_(i::FLAG_prof), |
| 164 saved_prof_auto_(i::FLAG_prof_auto), | 35 saved_prof_auto_(i::FLAG_prof_auto), |
| 165 trick_to_run_init_flags_(init_flags_(prof_lazy)), | 36 trick_to_run_init_flags_(init_flags_(prof_lazy)), |
| 166 need_to_set_up_logger_(i::V8::IsRunning()), | 37 need_to_set_up_logger_(i::V8::IsRunning()), |
| (...skipping 26 matching lines...) Expand all Loading... |
| 193 const bool saved_prof_; | 64 const bool saved_prof_; |
| 194 const bool saved_prof_auto_; | 65 const bool saved_prof_auto_; |
| 195 const bool trick_to_run_init_flags_; | 66 const bool trick_to_run_init_flags_; |
| 196 const bool need_to_set_up_logger_; | 67 const bool need_to_set_up_logger_; |
| 197 v8::HandleScope scope_; | 68 v8::HandleScope scope_; |
| 198 v8::Handle<v8::Context> env_; | 69 v8::Handle<v8::Context> env_; |
| 199 | 70 |
| 200 DISALLOW_COPY_AND_ASSIGN(ScopedLoggerInitializer); | 71 DISALLOW_COPY_AND_ASSIGN(ScopedLoggerInitializer); |
| 201 }; | 72 }; |
| 202 | 73 |
| 203 | |
| 204 class 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 | 74 } // namespace |
| 247 | 75 |
| 248 | 76 |
| 249 static void CheckThatProfilerWorks(LogBufferMatcher* matcher) { | |
| 250 CHECK(i::RuntimeProfiler::IsEnabled() || | |
| 251 !LoggerTestHelper::IsSamplerActive()); | |
| 252 LoggerTestHelper::ResetSamplesTaken(); | |
| 253 | |
| 254 LOGGER->ResumeProfiler(); | |
| 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(); | |
| 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 | |
| 294 TEST(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. | 77 // BUG(913). Need to implement support for profiling multiple VM threads. |
| 326 #if 0 | 78 #if 0 |
| 327 | 79 |
| 328 namespace { | 80 namespace { |
| 329 | 81 |
| 330 class LoopingThread : public v8::internal::Thread { | 82 class LoopingThread : public v8::internal::Thread { |
| 331 public: | 83 public: |
| 332 explicit LoopingThread(v8::internal::Isolate* isolate) | 84 explicit LoopingThread(v8::internal::Isolate* isolate) |
| 333 : v8::internal::Thread(isolate), | 85 : v8::internal::Thread(isolate), |
| 334 semaphore_(v8::internal::OS::CreateSemaphore(0)), | 86 semaphore_(v8::internal::OS::CreateSemaphore(0)), |
| (...skipping 183 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 518 i::ExternalTwoByteString::cast(*v8::Utils::OpenHandle(*source))); | 270 i::ExternalTwoByteString::cast(*v8::Utils::OpenHandle(*source))); |
| 519 // This situation can happen if source was an external string disposed | 271 // This situation can happen if source was an external string disposed |
| 520 // by its owner. | 272 // by its owner. |
| 521 i_source->set_resource(NULL); | 273 i_source->set_resource(NULL); |
| 522 | 274 |
| 523 // Must not crash. | 275 // Must not crash. |
| 524 LOGGER->LogCompiledFunctions(); | 276 LOGGER->LogCompiledFunctions(); |
| 525 } | 277 } |
| 526 | 278 |
| 527 | 279 |
| 528 static v8::Handle<v8::Value> ObjMethod1(const v8::Arguments& args) { | |
| 529 return v8::Handle<v8::Value>(); | |
| 530 } | |
| 531 | |
| 532 TEST(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 | |
| 567 static v8::Handle<v8::Value> Prop1Getter(v8::Local<v8::String> property, | |
| 568 const v8::AccessorInfo& info) { | |
| 569 return v8::Handle<v8::Value>(); | |
| 570 } | |
| 571 | |
| 572 static void Prop1Setter(v8::Local<v8::String> property, | |
| 573 v8::Local<v8::Value> value, | |
| 574 const v8::AccessorInfo& info) { | |
| 575 } | |
| 576 | |
| 577 static v8::Handle<v8::Value> Prop2Getter(v8::Local<v8::String> property, | |
| 578 const v8::AccessorInfo& info) { | |
| 579 return v8::Handle<v8::Value>(); | |
| 580 } | |
| 581 | |
| 582 TEST(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 | |
| 617 TEST(IsLoggingPreserved) { | 280 TEST(IsLoggingPreserved) { |
| 618 ScopedLoggerInitializer initialize_logger(false); | 281 ScopedLoggerInitializer initialize_logger(false); |
| 619 | 282 |
| 620 CHECK(LOGGER->is_logging()); | 283 CHECK(LOGGER->is_logging()); |
| 621 LOGGER->ResumeProfiler(); | 284 LOGGER->ResumeProfiler(); |
| 622 CHECK(LOGGER->is_logging()); | 285 CHECK(LOGGER->is_logging()); |
| 623 LOGGER->PauseProfiler(); | 286 LOGGER->PauseProfiler(); |
| 624 CHECK(LOGGER->is_logging()); | 287 CHECK(LOGGER->is_logging()); |
| 625 } | 288 } |
| 626 | 289 |
| 627 | |
| 628 static inline bool IsStringEqualTo(const char* r, const char* s) { | |
| 629 return strncmp(r, s, strlen(r)) == 0; | |
| 630 } | |
| 631 | |
| 632 | |
| 633 static bool Consume(const char* str, char** buf) { | |
| 634 if (IsStringEqualTo(str, *buf)) { | |
| 635 *buf += strlen(str); | |
| 636 return true; | |
| 637 } | |
| 638 return false; | |
| 639 } | |
| 640 | |
| 641 | |
| 642 namespace { | |
| 643 | |
| 644 // A code entity is a pointer to a position of code-creation event in buffer log | |
| 645 // offset to a point where entity size begins, i.e.: '255,"func"\n'. This makes | |
| 646 // comparing code entities pretty easy. | |
| 647 typedef char* CodeEntityInfo; | |
| 648 | |
| 649 class Interval { | |
| 650 public: | |
| 651 Interval() | |
| 652 : min_addr_(reinterpret_cast<Address>(-1)), | |
| 653 max_addr_(reinterpret_cast<Address>(0)), next_(NULL) {} | |
| 654 | |
| 655 ~Interval() { delete next_; } | |
| 656 | |
| 657 size_t Length() { | |
| 658 size_t result = max_addr_ - min_addr_ + 1; | |
| 659 if (next_ != NULL) result += next_->Length(); | |
| 660 return result; | |
| 661 } | |
| 662 | |
| 663 void CloneFrom(Interval* src) { | |
| 664 while (src != NULL) { | |
| 665 RegisterAddress(src->min_addr_); | |
| 666 RegisterAddress(src->max_addr_); | |
| 667 src = src->next_; | |
| 668 } | |
| 669 } | |
| 670 | |
| 671 bool Contains(Address addr) { | |
| 672 if (min_addr_ <= addr && addr <= max_addr_) { | |
| 673 return true; | |
| 674 } | |
| 675 if (next_ != NULL) { | |
| 676 return next_->Contains(addr); | |
| 677 } else { | |
| 678 return false; | |
| 679 } | |
| 680 } | |
| 681 | |
| 682 size_t GetIndex(Address addr) { | |
| 683 if (min_addr_ <= addr && addr <= max_addr_) { | |
| 684 return addr - min_addr_; | |
| 685 } | |
| 686 CHECK_NE(NULL, next_); | |
| 687 return (max_addr_ - min_addr_ + 1) + next_->GetIndex(addr); | |
| 688 } | |
| 689 | |
| 690 Address GetMinAddr() { | |
| 691 return next_ == NULL ? min_addr_ : i::Min(min_addr_, next_->GetMinAddr()); | |
| 692 } | |
| 693 | |
| 694 Address GetMaxAddr() { | |
| 695 return next_ == NULL ? max_addr_ : i::Max(max_addr_, next_->GetMaxAddr()); | |
| 696 } | |
| 697 | |
| 698 void RegisterAddress(Address addr) { | |
| 699 if (min_addr_ == reinterpret_cast<Address>(-1) | |
| 700 || (size_t)(addr > min_addr_ ? | |
| 701 addr - min_addr_ : min_addr_ - addr) < MAX_DELTA) { | |
| 702 if (addr < min_addr_) min_addr_ = addr; | |
| 703 if (addr > max_addr_) max_addr_ = addr; | |
| 704 } else { | |
| 705 if (next_ == NULL) next_ = new Interval(); | |
| 706 next_->RegisterAddress(addr); | |
| 707 } | |
| 708 } | |
| 709 | |
| 710 Address raw_min_addr() { return min_addr_; } | |
| 711 | |
| 712 Address raw_max_addr() { return max_addr_; } | |
| 713 | |
| 714 Interval* get_next() { return next_; } | |
| 715 | |
| 716 private: | |
| 717 static const size_t MAX_DELTA = 0x100000; | |
| 718 Address min_addr_; | |
| 719 Address max_addr_; | |
| 720 Interval* next_; | |
| 721 }; | |
| 722 | |
| 723 | |
| 724 // A structure used to return log parsing results. | |
| 725 class ParseLogResult { | |
| 726 public: | |
| 727 ParseLogResult() | |
| 728 : entities_map(NULL), entities(NULL), | |
| 729 max_entities(0) {} | |
| 730 | |
| 731 ~ParseLogResult() { | |
| 732 i::DeleteArray(entities_map); | |
| 733 i::DeleteArray(entities); | |
| 734 } | |
| 735 | |
| 736 void AllocateEntities() { | |
| 737 // Make sure that the test doesn't operate on a bogus log. | |
| 738 CHECK_GT(max_entities, 0); | |
| 739 CHECK_GT(bounds.GetMinAddr(), 0); | |
| 740 CHECK_GT(bounds.GetMaxAddr(), bounds.GetMinAddr()); | |
| 741 | |
| 742 entities = i::NewArray<CodeEntityInfo>(max_entities); | |
| 743 for (int i = 0; i < max_entities; ++i) { | |
| 744 entities[i] = NULL; | |
| 745 } | |
| 746 const size_t map_length = bounds.Length(); | |
| 747 entities_map = i::NewArray<int>(static_cast<int>(map_length)); | |
| 748 for (size_t i = 0; i < map_length; ++i) { | |
| 749 entities_map[i] = -1; | |
| 750 } | |
| 751 } | |
| 752 | |
| 753 bool HasIndexForAddress(Address addr) { | |
| 754 return bounds.Contains(addr); | |
| 755 } | |
| 756 | |
| 757 size_t GetIndexForAddress(Address addr) { | |
| 758 CHECK(HasIndexForAddress(addr)); | |
| 759 return bounds.GetIndex(addr); | |
| 760 } | |
| 761 | |
| 762 CodeEntityInfo GetEntity(Address addr) { | |
| 763 if (HasIndexForAddress(addr)) { | |
| 764 size_t idx = GetIndexForAddress(addr); | |
| 765 int item = entities_map[idx]; | |
| 766 return item != -1 ? entities[item] : NULL; | |
| 767 } | |
| 768 return NULL; | |
| 769 } | |
| 770 | |
| 771 void ParseAddress(char* start) { | |
| 772 Address addr = | |
| 773 reinterpret_cast<Address>(strtoul(start, NULL, 16)); // NOLINT | |
| 774 bounds.RegisterAddress(addr); | |
| 775 } | |
| 776 | |
| 777 Address ConsumeAddress(char** start) { | |
| 778 char* end_ptr; | |
| 779 Address addr = | |
| 780 reinterpret_cast<Address>(strtoul(*start, &end_ptr, 16)); // NOLINT | |
| 781 CHECK(HasIndexForAddress(addr)); | |
| 782 *start = end_ptr; | |
| 783 return addr; | |
| 784 } | |
| 785 | |
| 786 Interval bounds; | |
| 787 // Memory map of entities start addresses. | |
| 788 int* entities_map; | |
| 789 // An array of code entities. | |
| 790 CodeEntityInfo* entities; | |
| 791 // Maximal entities count. Actual entities count can be lower, | |
| 792 // empty entity slots are pointing to NULL. | |
| 793 int max_entities; | |
| 794 }; | |
| 795 | |
| 796 } // namespace | |
| 797 | |
| 798 | |
| 799 typedef void (*ParserBlock)(char* start, char* end, ParseLogResult* result); | |
| 800 | |
| 801 static void ParserCycle( | |
| 802 char* start, char* end, ParseLogResult* result, | |
| 803 ParserBlock block_creation, ParserBlock block_delete, | |
| 804 ParserBlock block_move) { | |
| 805 | |
| 806 const char* code_creation = "code-creation,"; | |
| 807 const char* code_delete = "code-delete,"; | |
| 808 const char* code_move = "code-move,"; | |
| 809 | |
| 810 const char* lazy_compile = "LazyCompile,"; | |
| 811 const char* script = "Script,"; | |
| 812 const char* function = "Function,"; | |
| 813 | |
| 814 while (start < end) { | |
| 815 if (Consume(code_creation, &start)) { | |
| 816 if (Consume(lazy_compile, &start) | |
| 817 || Consume(script, &start) | |
| 818 || Consume(function, &start)) { | |
| 819 block_creation(start, end, result); | |
| 820 } | |
| 821 } else if (Consume(code_delete, &start)) { | |
| 822 block_delete(start, end, result); | |
| 823 } else if (Consume(code_move, &start)) { | |
| 824 block_move(start, end, result); | |
| 825 } | |
| 826 while (start < end && *start != '\n') ++start; | |
| 827 ++start; | |
| 828 } | |
| 829 } | |
| 830 | |
| 831 | |
| 832 static void Pass1CodeCreation(char* start, char* end, ParseLogResult* result) { | |
| 833 result->ParseAddress(start); | |
| 834 ++result->max_entities; | |
| 835 } | |
| 836 | |
| 837 | |
| 838 static void Pass1CodeDelete(char* start, char* end, ParseLogResult* result) { | |
| 839 result->ParseAddress(start); | |
| 840 } | |
| 841 | |
| 842 | |
| 843 static void Pass1CodeMove(char* start, char* end, ParseLogResult* result) { | |
| 844 result->ParseAddress(start); | |
| 845 // Skip old address. | |
| 846 while (start < end && *start != ',') ++start; | |
| 847 CHECK_GT(end, start); | |
| 848 ++start; // Skip ','. | |
| 849 result->ParseAddress(start); | |
| 850 } | |
| 851 | |
| 852 | |
| 853 static void Pass2CodeCreation(char* start, char* end, ParseLogResult* result) { | |
| 854 Address addr = result->ConsumeAddress(&start); | |
| 855 CHECK_GT(end, start); | |
| 856 ++start; // Skip ','. | |
| 857 | |
| 858 size_t idx = result->GetIndexForAddress(addr); | |
| 859 result->entities_map[idx] = -1; | |
| 860 for (int i = 0; i < result->max_entities; ++i) { | |
| 861 // Find an empty slot and fill it. | |
| 862 if (result->entities[i] == NULL) { | |
| 863 result->entities[i] = start; | |
| 864 result->entities_map[idx] = i; | |
| 865 break; | |
| 866 } | |
| 867 } | |
| 868 // Make sure that a slot was found. | |
| 869 CHECK_GE(result->entities_map[idx], 0); | |
| 870 } | |
| 871 | |
| 872 | |
| 873 static void Pass2CodeDelete(char* start, char* end, ParseLogResult* result) { | |
| 874 Address addr = result->ConsumeAddress(&start); | |
| 875 size_t idx = result->GetIndexForAddress(addr); | |
| 876 // There can be code deletes that are not related to JS code. | |
| 877 if (result->entities_map[idx] >= 0) { | |
| 878 result->entities[result->entities_map[idx]] = NULL; | |
| 879 result->entities_map[idx] = -1; | |
| 880 } | |
| 881 } | |
| 882 | |
| 883 | |
| 884 static void Pass2CodeMove(char* start, char* end, ParseLogResult* result) { | |
| 885 Address from_addr = result->ConsumeAddress(&start); | |
| 886 CHECK_GT(end, start); | |
| 887 ++start; // Skip ','. | |
| 888 Address to_addr = result->ConsumeAddress(&start); | |
| 889 CHECK_GT(end, start); | |
| 890 | |
| 891 size_t from_idx = result->GetIndexForAddress(from_addr); | |
| 892 size_t to_idx = result->GetIndexForAddress(to_addr); | |
| 893 // There can be code moves that are not related to JS code. | |
| 894 if (from_idx != to_idx && result->entities_map[from_idx] >= 0) { | |
| 895 CHECK_EQ(-1, result->entities_map[to_idx]); | |
| 896 result->entities_map[to_idx] = result->entities_map[from_idx]; | |
| 897 result->entities_map[from_idx] = -1; | |
| 898 }; | |
| 899 } | |
| 900 | |
| 901 | |
| 902 static void ParseLog(char* start, char* end, ParseLogResult* result) { | |
| 903 // Pass 1: Calculate boundaries of addresses and entities count. | |
| 904 ParserCycle(start, end, result, | |
| 905 Pass1CodeCreation, Pass1CodeDelete, Pass1CodeMove); | |
| 906 | |
| 907 printf("min_addr: %p, max_addr: %p, entities: %d\n", | |
| 908 result->bounds.GetMinAddr(), result->bounds.GetMaxAddr(), | |
| 909 result->max_entities); | |
| 910 | |
| 911 result->AllocateEntities(); | |
| 912 | |
| 913 // Pass 2: Fill in code entries data. | |
| 914 ParserCycle(start, end, result, | |
| 915 Pass2CodeCreation, Pass2CodeDelete, Pass2CodeMove); | |
| 916 } | |
| 917 | |
| 918 | |
| 919 static inline void PrintCodeEntityInfo(CodeEntityInfo entity) { | |
| 920 const int max_len = 50; | |
| 921 if (entity != NULL) { | |
| 922 char* eol = strchr(entity, '\n'); | |
| 923 int len = static_cast<int>(eol - entity); | |
| 924 len = len <= max_len ? len : max_len; | |
| 925 printf("%-*.*s ", max_len, len, entity); | |
| 926 } else { | |
| 927 printf("%*s", max_len + 1, ""); | |
| 928 } | |
| 929 } | |
| 930 | |
| 931 | |
| 932 static void PrintCodeEntitiesInfo( | |
| 933 bool is_equal, Address addr, | |
| 934 CodeEntityInfo l_entity, CodeEntityInfo r_entity) { | |
| 935 printf("%c %p ", is_equal ? ' ' : '*', addr); | |
| 936 PrintCodeEntityInfo(l_entity); | |
| 937 PrintCodeEntityInfo(r_entity); | |
| 938 printf("\n"); | |
| 939 } | |
| 940 | |
| 941 | |
| 942 static inline int StrChrLen(const char* s, char c) { | |
| 943 return static_cast<int>(strchr(s, c) - s); | |
| 944 } | |
| 945 | |
| 946 | |
| 947 static bool AreFuncSizesEqual(CodeEntityInfo ref_s, CodeEntityInfo new_s) { | |
| 948 int ref_len = StrChrLen(ref_s, ','); | |
| 949 int new_len = StrChrLen(new_s, ','); | |
| 950 return ref_len == new_len && strncmp(ref_s, new_s, ref_len) == 0; | |
| 951 } | |
| 952 | |
| 953 | |
| 954 static bool AreFuncNamesEqual(CodeEntityInfo ref_s, CodeEntityInfo new_s) { | |
| 955 // Skip size. | |
| 956 ref_s = strchr(ref_s, ',') + 1; | |
| 957 new_s = strchr(new_s, ',') + 1; | |
| 958 CHECK_EQ('"', ref_s[0]); | |
| 959 CHECK_EQ('"', new_s[0]); | |
| 960 int ref_len = StrChrLen(ref_s + 1, '\"'); | |
| 961 int new_len = StrChrLen(new_s + 1, '\"'); | |
| 962 // A special case for ErrorPrototype. Haven't yet figured out why they | |
| 963 // are different. | |
| 964 const char* error_prototype = "\"ErrorPrototype"; | |
| 965 if (IsStringEqualTo(error_prototype, ref_s) | |
| 966 && IsStringEqualTo(error_prototype, new_s)) { | |
| 967 return true; | |
| 968 } | |
| 969 // Built-in objects have problems too. | |
| 970 const char* built_ins[] = { | |
| 971 "\"Boolean\"", "\"Function\"", "\"Number\"", | |
| 972 "\"Object\"", "\"Script\"", "\"String\"" | |
| 973 }; | |
| 974 for (size_t i = 0; i < sizeof(built_ins) / sizeof(*built_ins); ++i) { | |
| 975 if (IsStringEqualTo(built_ins[i], new_s)) { | |
| 976 return true; | |
| 977 } | |
| 978 } | |
| 979 return ref_len == new_len && strncmp(ref_s, new_s, ref_len) == 0; | |
| 980 } | |
| 981 | |
| 982 | |
| 983 static bool AreEntitiesEqual(CodeEntityInfo ref_e, CodeEntityInfo new_e) { | |
| 984 if (ref_e == NULL && new_e != NULL) return true; | |
| 985 if (ref_e != NULL && new_e != NULL) { | |
| 986 return AreFuncSizesEqual(ref_e, new_e) && AreFuncNamesEqual(ref_e, new_e); | |
| 987 } | |
| 988 if (ref_e != NULL && new_e == NULL) { | |
| 989 // args_count entities (argument adapters) are not found by heap traversal, | |
| 990 // but they are not needed because they doesn't contain any code. | |
| 991 ref_e = strchr(ref_e, ',') + 1; | |
| 992 const char* args_count = "\"args_count:"; | |
| 993 return IsStringEqualTo(args_count, ref_e); | |
| 994 } | |
| 995 return false; | |
| 996 } | |
| 997 | |
| 998 | |
| 999 // Test that logging of code create / move / delete events | |
| 1000 // is equivalent to traversal of a resulting heap. | |
| 1001 TEST(EquivalenceOfLoggingAndTraversal) { | |
| 1002 // This test needs to be run on a "clean" V8 to ensure that snapshot log | |
| 1003 // is loaded. This is always true when running using tools/test.py because | |
| 1004 // it launches a new cctest instance for every test. To be sure that launching | |
| 1005 // cctest manually also works, please be sure that no tests below | |
| 1006 // are using V8. | |
| 1007 // | |
| 1008 // P.S. No, V8 can't be re-initialized after disposal, see include/v8.h. | |
| 1009 CHECK(!i::V8::IsRunning()); | |
| 1010 | |
| 1011 i::FLAG_logfile = "*"; | |
| 1012 i::FLAG_log = true; | |
| 1013 i::FLAG_log_code = true; | |
| 1014 | |
| 1015 // Make sure objects move. | |
| 1016 bool saved_always_compact = i::FLAG_always_compact; | |
| 1017 if (!i::FLAG_never_compact) { | |
| 1018 i::FLAG_always_compact = true; | |
| 1019 } | |
| 1020 | |
| 1021 v8::HandleScope scope; | |
| 1022 v8::Handle<v8::Value> global_object = v8::Handle<v8::Value>(); | |
| 1023 v8::Handle<v8::Context> env = v8::Context::New( | |
| 1024 0, v8::Handle<v8::ObjectTemplate>(), global_object); | |
| 1025 env->Enter(); | |
| 1026 | |
| 1027 // Compile and run a function that creates other functions. | |
| 1028 CompileAndRunScript( | |
| 1029 "(function f(obj) {\n" | |
| 1030 " obj.test =\n" | |
| 1031 " (function a(j) { return function b() { return j; } })(100);\n" | |
| 1032 "})(this);"); | |
| 1033 HEAP->CollectAllGarbage(false); | |
| 1034 | |
| 1035 EmbeddedVector<char, 204800> buffer; | |
| 1036 int log_size; | |
| 1037 ParseLogResult ref_result; | |
| 1038 | |
| 1039 // Retrieve the log. | |
| 1040 { | |
| 1041 // Make sure that no GCs occur prior to LogCompiledFunctions call. | |
| 1042 i::AssertNoAllocation no_alloc; | |
| 1043 | |
| 1044 log_size = GetLogLines(0, &buffer); | |
| 1045 CHECK_GT(log_size, 0); | |
| 1046 CHECK_GT(buffer.length(), log_size); | |
| 1047 | |
| 1048 // Fill a map of compiled code objects. | |
| 1049 ParseLog(buffer.start(), buffer.start() + log_size, &ref_result); | |
| 1050 } | |
| 1051 | |
| 1052 // Iterate heap to find compiled functions, will write to log. | |
| 1053 LOGGER->LogCompiledFunctions(); | |
| 1054 char* new_log_start = buffer.start() + log_size; | |
| 1055 const int new_log_size = LOGGER->GetLogLines( | |
| 1056 log_size, new_log_start, buffer.length() - log_size); | |
| 1057 CHECK_GT(new_log_size, 0); | |
| 1058 CHECK_GT(buffer.length(), log_size + new_log_size); | |
| 1059 | |
| 1060 // Fill an equivalent map of compiled code objects. | |
| 1061 ParseLogResult new_result; | |
| 1062 ParseLog(new_log_start, new_log_start + new_log_size, &new_result); | |
| 1063 | |
| 1064 // Test their actual equivalence. | |
| 1065 Interval combined; | |
| 1066 combined.CloneFrom(&ref_result.bounds); | |
| 1067 combined.CloneFrom(&new_result.bounds); | |
| 1068 Interval* iter = &combined; | |
| 1069 bool results_equal = true; | |
| 1070 | |
| 1071 while (iter != NULL) { | |
| 1072 for (Address addr = iter->raw_min_addr(); | |
| 1073 addr <= iter->raw_max_addr(); ++addr) { | |
| 1074 CodeEntityInfo ref_entity = ref_result.GetEntity(addr); | |
| 1075 CodeEntityInfo new_entity = new_result.GetEntity(addr); | |
| 1076 if (ref_entity != NULL || new_entity != NULL) { | |
| 1077 const bool equal = AreEntitiesEqual(ref_entity, new_entity); | |
| 1078 if (!equal) results_equal = false; | |
| 1079 PrintCodeEntitiesInfo(equal, addr, ref_entity, new_entity); | |
| 1080 } | |
| 1081 } | |
| 1082 iter = iter->get_next(); | |
| 1083 } | |
| 1084 // Make sure that all log data is written prior crash due to CHECK failure. | |
| 1085 fflush(stdout); | |
| 1086 CHECK(results_equal); | |
| 1087 | |
| 1088 env->Exit(); | |
| 1089 LOGGER->TearDown(); | |
| 1090 i::FLAG_always_compact = saved_always_compact; | |
| 1091 } | |
| 1092 | |
| 1093 #endif // ENABLE_LOGGING_AND_PROFILING | 290 #endif // ENABLE_LOGGING_AND_PROFILING |
| OLD | NEW |