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 |