Chromium Code Reviews
chromiumcodereview-hr@appspot.gserviceaccount.com (chromiumcodereview-hr) | Please choose your nickname with Settings | Help | Chromium Project | Gerrit Changes | Sign out
(8)

Side by Side Diff: test/cctest/test-log.cc

Issue 7310025: Remove support for logging into a memory buffer. (Closed) Base URL: https://v8.googlecode.com/svn/branches/bleeding_edge
Patch Set: Created 9 years, 5 months ago
Use n/p to move between diff chunks; N/P to move between comments. Draft comments are only viewable by you.
Jump to:
View unified diff | Download patch | Annotate | Revision Log
OLDNEW
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
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
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
OLDNEW

Powered by Google App Engine
This is Rietveld 408576698