diff options
Diffstat (limited to 'deps/v8/test/cctest/test-log.cc')
| -rw-r--r-- | deps/v8/test/cctest/test-log.cc | 867 |
1 files changed, 161 insertions, 706 deletions
diff --git a/deps/v8/test/cctest/test-log.cc b/deps/v8/test/cctest/test-log.cc index 10a90bcf17..5704b07ace 100644 --- a/deps/v8/test/cctest/test-log.cc +++ b/deps/v8/test/cctest/test-log.cc @@ -2,8 +2,6 @@ // // Tests of logging functions from log.h -#ifdef ENABLE_LOGGING_AND_PROFILING - #ifdef __linux__ #include <math.h> #include <pthread.h> @@ -15,6 +13,7 @@ #include "log.h" #include "cpu-profiler.h" #include "v8threads.h" +#include "v8utils.h" #include "cctest.h" #include "vm-state-inl.h" @@ -25,269 +24,75 @@ using v8::internal::StrLength; namespace i = v8::internal; -static void SetUp() { - // Log to memory buffer. - i::FLAG_logfile = "*"; - i::FLAG_log = true; - LOGGER->Setup(); -} - -static void TearDown() { - LOGGER->TearDown(); -} - - -TEST(EmptyLog) { - SetUp(); - CHECK_EQ(0, LOGGER->GetLogLines(0, NULL, 0)); - CHECK_EQ(0, LOGGER->GetLogLines(100, NULL, 0)); - CHECK_EQ(0, LOGGER->GetLogLines(0, NULL, 100)); - CHECK_EQ(0, LOGGER->GetLogLines(100, NULL, 100)); - TearDown(); -} - - -TEST(GetMessages) { - SetUp(); - LOGGER->StringEvent("aaa", "bbb"); - LOGGER->StringEvent("cccc", "dddd"); - CHECK_EQ(0, LOGGER->GetLogLines(0, NULL, 0)); - char log_lines[100]; - memset(log_lines, 0, sizeof(log_lines)); - // See Logger::StringEvent. - const char* line_1 = "aaa,\"bbb\"\n"; - const int line_1_len = StrLength(line_1); - // The exact size. - CHECK_EQ(line_1_len, LOGGER->GetLogLines(0, log_lines, line_1_len)); - CHECK_EQ(line_1, log_lines); - memset(log_lines, 0, sizeof(log_lines)); - // A bit more than the first line length. - CHECK_EQ(line_1_len, LOGGER->GetLogLines(0, log_lines, line_1_len + 3)); - log_lines[line_1_len] = '\0'; - CHECK_EQ(line_1, log_lines); - memset(log_lines, 0, sizeof(log_lines)); - const char* line_2 = "cccc,\"dddd\"\n"; - const int line_2_len = StrLength(line_2); - // Now start with line_2 beginning. - CHECK_EQ(0, LOGGER->GetLogLines(line_1_len, log_lines, 0)); - CHECK_EQ(line_2_len, LOGGER->GetLogLines(line_1_len, log_lines, line_2_len)); - CHECK_EQ(line_2, log_lines); - memset(log_lines, 0, sizeof(log_lines)); - CHECK_EQ(line_2_len, - LOGGER->GetLogLines(line_1_len, log_lines, line_2_len + 3)); - CHECK_EQ(line_2, log_lines); - memset(log_lines, 0, sizeof(log_lines)); - // Now get entire buffer contents. - const char* all_lines = "aaa,\"bbb\"\ncccc,\"dddd\"\n"; - const int all_lines_len = StrLength(all_lines); - CHECK_EQ(all_lines_len, LOGGER->GetLogLines(0, log_lines, all_lines_len)); - CHECK_EQ(all_lines, log_lines); - memset(log_lines, 0, sizeof(log_lines)); - CHECK_EQ(all_lines_len, LOGGER->GetLogLines(0, log_lines, all_lines_len + 3)); - CHECK_EQ(all_lines, log_lines); - memset(log_lines, 0, sizeof(log_lines)); - TearDown(); -} - - -static int GetLogLines(int start_pos, i::Vector<char>* buffer) { - return LOGGER->GetLogLines(start_pos, buffer->start(), buffer->length()); -} - - -TEST(BeyondWritePosition) { - SetUp(); - LOGGER->StringEvent("aaa", "bbb"); - LOGGER->StringEvent("cccc", "dddd"); - // See Logger::StringEvent. - const char* all_lines = "aaa,\"bbb\"\ncccc,\"dddd\"\n"; - const int all_lines_len = StrLength(all_lines); - EmbeddedVector<char, 100> buffer; - const int beyond_write_pos = all_lines_len; - CHECK_EQ(0, LOGGER->GetLogLines(beyond_write_pos, buffer.start(), 1)); - CHECK_EQ(0, GetLogLines(beyond_write_pos, &buffer)); - CHECK_EQ(0, LOGGER->GetLogLines(beyond_write_pos + 1, buffer.start(), 1)); - CHECK_EQ(0, GetLogLines(beyond_write_pos + 1, &buffer)); - CHECK_EQ(0, LOGGER->GetLogLines(beyond_write_pos + 100, buffer.start(), 1)); - CHECK_EQ(0, GetLogLines(beyond_write_pos + 100, &buffer)); - CHECK_EQ(0, LOGGER->GetLogLines(10 * 1024 * 1024, buffer.start(), 1)); - CHECK_EQ(0, GetLogLines(10 * 1024 * 1024, &buffer)); - TearDown(); -} - - -TEST(MemoryLoggingTurnedOff) { - // Log to stdout - i::FLAG_logfile = "-"; - i::FLAG_log = true; - LOGGER->Setup(); - CHECK_EQ(0, LOGGER->GetLogLines(0, NULL, 0)); - CHECK_EQ(0, LOGGER->GetLogLines(100, NULL, 0)); - CHECK_EQ(0, LOGGER->GetLogLines(0, NULL, 100)); - CHECK_EQ(0, LOGGER->GetLogLines(100, NULL, 100)); - LOGGER->TearDown(); -} - - -static void CompileAndRunScript(const char *src) { - v8::Script::Compile(v8::String::New(src))->Run(); -} - - -namespace v8 { -namespace internal { - -class LoggerTestHelper : public AllStatic { - public: - static bool IsSamplerActive() { return LOGGER->IsProfilerSamplerActive(); } - static void ResetSamplesTaken() { - reinterpret_cast<Sampler*>(LOGGER->ticker_)->ResetSamplesTaken(); - } - static bool has_samples_taken() { - return reinterpret_cast<Sampler*>(LOGGER->ticker_)->samples_taken() > 0; - } -}; - -} // namespace v8::internal -} // namespace v8 - -using v8::internal::LoggerTestHelper; - - namespace { class ScopedLoggerInitializer { public: explicit ScopedLoggerInitializer(bool prof_lazy) - : saved_prof_lazy_(i::FLAG_prof_lazy), + : saved_log_(i::FLAG_log), + saved_prof_lazy_(i::FLAG_prof_lazy), saved_prof_(i::FLAG_prof), saved_prof_auto_(i::FLAG_prof_auto), + temp_file_(NULL), + // Need to run this prior to creating the scope. trick_to_run_init_flags_(init_flags_(prof_lazy)), - need_to_set_up_logger_(i::V8::IsRunning()), scope_(), env_(v8::Context::New()) { - if (need_to_set_up_logger_) LOGGER->Setup(); env_->Enter(); } ~ScopedLoggerInitializer() { env_->Exit(); LOGGER->TearDown(); + if (temp_file_ != NULL) fclose(temp_file_); i::FLAG_prof_lazy = saved_prof_lazy_; i::FLAG_prof = saved_prof_; i::FLAG_prof_auto = saved_prof_auto_; + i::FLAG_log = saved_log_; } v8::Handle<v8::Context>& env() { return env_; } + FILE* StopLoggingGetTempFile() { + temp_file_ = LOGGER->TearDown(); + CHECK_NE(NULL, temp_file_); + fflush(temp_file_); + rewind(temp_file_); + return temp_file_; + } + private: static bool init_flags_(bool prof_lazy) { + i::FLAG_log = true; i::FLAG_prof = true; i::FLAG_prof_lazy = prof_lazy; i::FLAG_prof_auto = false; - i::FLAG_logfile = "*"; + i::FLAG_logfile = i::Log::kLogToTemporaryFile; return prof_lazy; } + const bool saved_log_; const bool saved_prof_lazy_; const bool saved_prof_; const bool saved_prof_auto_; + FILE* temp_file_; const bool trick_to_run_init_flags_; - const bool need_to_set_up_logger_; v8::HandleScope scope_; v8::Handle<v8::Context> env_; DISALLOW_COPY_AND_ASSIGN(ScopedLoggerInitializer); }; - -class LogBufferMatcher { - public: - LogBufferMatcher() { - // Skip all initially logged stuff. - log_pos_ = GetLogLines(0, &buffer_); - } - - int log_pos() { return log_pos_; } - - int GetNextChunk() { - int chunk_size = GetLogLines(log_pos_, &buffer_); - CHECK_GT(buffer_.length(), chunk_size); - buffer_[chunk_size] = '\0'; - log_pos_ += chunk_size; - return chunk_size; - } - - const char* Find(const char* substr) { - return strstr(buffer_.start(), substr); - } - - const char* Find(const i::Vector<char>& substr) { - return Find(substr.start()); - } - - bool IsInSequence(const char* s1, const char* s2) { - const char* s1_pos = Find(s1); - const char* s2_pos = Find(s2); - CHECK_NE(NULL, s1_pos); - CHECK_NE(NULL, s2_pos); - return s1_pos < s2_pos; - } - - void PrintBuffer() { - puts(buffer_.start()); - } - - private: - EmbeddedVector<char, 102400> buffer_; - int log_pos_; -}; - } // namespace -static void CheckThatProfilerWorks(LogBufferMatcher* matcher) { - CHECK(i::RuntimeProfiler::IsEnabled() || - !LoggerTestHelper::IsSamplerActive()); - LoggerTestHelper::ResetSamplesTaken(); - - LOGGER->ResumeProfiler(); - CHECK(LoggerTestHelper::IsSamplerActive()); - - // Verify that the current map of compiled functions has been logged. - CHECK_GT(matcher->GetNextChunk(), 0); - const char* code_creation = "\ncode-creation,"; // eq. to /^code-creation,/ - CHECK_NE(NULL, matcher->Find(code_creation)); - - // Force compiler to generate new code by parametrizing source. - EmbeddedVector<char, 100> script_src; - i::OS::SNPrintF(script_src, - "function f%d(x) { return %d * x; }" - "for (var i = 0; i < 10000; ++i) { f%d(i); }", - matcher->log_pos(), matcher->log_pos(), matcher->log_pos()); - // Run code for 200 msecs to get some ticks. - const double end_time = i::OS::TimeCurrentMillis() + 200; - while (i::OS::TimeCurrentMillis() < end_time) { - CompileAndRunScript(script_src.start()); - // Yield CPU to give Profiler thread a chance to process ticks. - i::OS::Sleep(1); - } - - LOGGER->PauseProfiler(); - CHECK(i::RuntimeProfiler::IsEnabled() || - !LoggerTestHelper::IsSamplerActive()); - - // Wait 50 msecs to allow Profiler thread to process the last - // tick sample it has got. - i::OS::Sleep(50); - - // Now we must have compiler and tick records. - CHECK_GT(matcher->GetNextChunk(), 0); - matcher->PrintBuffer(); - CHECK_NE(NULL, matcher->Find(code_creation)); - const char* tick = "\ntick,"; - const bool ticks_found = matcher->Find(tick) != NULL; - CHECK_EQ(LoggerTestHelper::has_samples_taken(), ticks_found); +static const char* StrNStr(const char* s1, const char* s2, int n) { + if (s1[n] == '\0') return strstr(s1, s2); + i::ScopedVector<char> str(n + 1); + i::OS::StrNCpy(str, s1, static_cast<size_t>(n)); + str[n] = '\0'; + char* found = strstr(str.start(), s2); + return found != NULL ? s1 + (found - str.start()) : NULL; } @@ -296,29 +101,61 @@ TEST(ProfLazyMode) { if (!i::V8::UseCrankshaft()) return; - // No sampling should happen prior to resuming profiler unless we - // are runtime profiling. - CHECK(i::RuntimeProfiler::IsEnabled() || - !LoggerTestHelper::IsSamplerActive()); + LOGGER->StringEvent("test-start", ""); + CompileRun("var a = (function(x) { return x + 1; })(10);"); + LOGGER->StringEvent("test-profiler-start", ""); + v8::V8::ResumeProfiler(); + CompileRun( + "var b = (function(x) { return x + 2; })(10);\n" + "var c = (function(x) { return x + 3; })(10);\n" + "var d = (function(x) { return x + 4; })(10);\n" + "var e = (function(x) { return x + 5; })(10);"); + v8::V8::PauseProfiler(); + LOGGER->StringEvent("test-profiler-stop", ""); + CompileRun("var f = (function(x) { return x + 6; })(10);"); + // Check that profiling can be resumed again. + LOGGER->StringEvent("test-profiler-start-2", ""); + v8::V8::ResumeProfiler(); + CompileRun( + "var g = (function(x) { return x + 7; })(10);\n" + "var h = (function(x) { return x + 8; })(10);\n" + "var i = (function(x) { return x + 9; })(10);\n" + "var j = (function(x) { return x + 10; })(10);"); + v8::V8::PauseProfiler(); + LOGGER->StringEvent("test-profiler-stop-2", ""); + LOGGER->StringEvent("test-stop", ""); + + bool exists = false; + i::Vector<const char> log( + i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); + CHECK(exists); + + const char* test_start_position = + StrNStr(log.start(), "test-start,", log.length()); + CHECK_NE(NULL, test_start_position); + const char* test_profiler_start_position = + StrNStr(log.start(), "test-profiler-start,", log.length()); + CHECK_NE(NULL, test_profiler_start_position); + CHECK_GT(test_profiler_start_position, test_start_position); + const char* test_profiler_stop_position = + StrNStr(log.start(), "test-profiler-stop,", log.length()); + CHECK_NE(NULL, test_profiler_stop_position); + CHECK_GT(test_profiler_stop_position, test_profiler_start_position); + const char* test_profiler_start_2_position = + StrNStr(log.start(), "test-profiler-start-2,", log.length()); + CHECK_NE(NULL, test_profiler_start_2_position); + CHECK_GT(test_profiler_start_2_position, test_profiler_stop_position); - LogBufferMatcher matcher; // Nothing must be logged until profiling is resumed. - CHECK_EQ(0, matcher.log_pos()); - - CompileAndRunScript("var a = (function(x) { return x + 1; })(10);"); - + CHECK_EQ(NULL, StrNStr(test_start_position, + "code-creation,", + static_cast<int>(test_profiler_start_position - + test_start_position))); // Nothing must be logged while profiling is suspended. - CHECK_EQ(0, matcher.GetNextChunk()); - - CheckThatProfilerWorks(&matcher); - - CompileAndRunScript("var a = (function(x) { return x + 1; })(10);"); - - // No new data beyond last retrieved position. - CHECK_EQ(0, matcher.GetNextChunk()); - - // Check that profiling can be resumed again. - CheckThatProfilerWorks(&matcher); + CHECK_EQ(NULL, StrNStr(test_profiler_stop_position, + "code-creation,", + static_cast<int>(test_profiler_start_2_position - + test_profiler_stop_position))); } @@ -383,7 +220,7 @@ class LoopingJsThread : public LoopingThread { { v8::Context::Scope context_scope(context); SignalRunning(); - CompileAndRunScript( + CompileRun( "var j; for (var i=0; i<10000; ++i) { j = Math.sin(i); }"); } context.Dispose(); @@ -531,34 +368,34 @@ static v8::Handle<v8::Value> ObjMethod1(const v8::Arguments& args) { TEST(LogCallbacks) { ScopedLoggerInitializer initialize_logger(false); - LogBufferMatcher matcher; v8::Persistent<v8::FunctionTemplate> obj = v8::Persistent<v8::FunctionTemplate>::New(v8::FunctionTemplate::New()); - obj->SetClassName(v8::String::New("Obj")); + obj->SetClassName(v8_str("Obj")); v8::Handle<v8::ObjectTemplate> proto = obj->PrototypeTemplate(); v8::Local<v8::Signature> signature = v8::Signature::New(obj); - proto->Set(v8::String::New("method1"), + proto->Set(v8_str("method1"), v8::FunctionTemplate::New(ObjMethod1, v8::Handle<v8::Value>(), signature), static_cast<v8::PropertyAttribute>(v8::DontDelete)); initialize_logger.env()->Global()->Set(v8_str("Obj"), obj->GetFunction()); - CompileAndRunScript("Obj.prototype.method1.toString();"); + CompileRun("Obj.prototype.method1.toString();"); LOGGER->LogCompiledFunctions(); - CHECK_GT(matcher.GetNextChunk(), 0); - const char* callback_rec = "code-creation,Callback,"; - char* pos = const_cast<char*>(matcher.Find(callback_rec)); - CHECK_NE(NULL, pos); - pos += strlen(callback_rec); - EmbeddedVector<char, 100> ref_data; + bool exists = false; + i::Vector<const char> log( + i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); + CHECK(exists); + + i::EmbeddedVector<char, 100> ref_data; i::OS::SNPrintF(ref_data, - "0x%" V8PRIxPTR ",1,\"method1\"", ObjMethod1); - *(pos + strlen(ref_data.start())) = '\0'; - CHECK_EQ(ref_data.start(), pos); + "code-creation,Callback,0x%" V8PRIxPTR ",1,\"method1\"\0", + ObjMethod1); + + CHECK_NE(NULL, StrNStr(log.start(), ref_data.start(), log.length())); obj.Dispose(); } @@ -581,34 +418,41 @@ static v8::Handle<v8::Value> Prop2Getter(v8::Local<v8::String> property, TEST(LogAccessorCallbacks) { ScopedLoggerInitializer initialize_logger(false); - LogBufferMatcher matcher; v8::Persistent<v8::FunctionTemplate> obj = v8::Persistent<v8::FunctionTemplate>::New(v8::FunctionTemplate::New()); - obj->SetClassName(v8::String::New("Obj")); + obj->SetClassName(v8_str("Obj")); v8::Handle<v8::ObjectTemplate> inst = obj->InstanceTemplate(); - inst->SetAccessor(v8::String::New("prop1"), Prop1Getter, Prop1Setter); - inst->SetAccessor(v8::String::New("prop2"), Prop2Getter); + inst->SetAccessor(v8_str("prop1"), Prop1Getter, Prop1Setter); + inst->SetAccessor(v8_str("prop2"), Prop2Getter); LOGGER->LogAccessorCallbacks(); - CHECK_GT(matcher.GetNextChunk(), 0); - matcher.PrintBuffer(); + + bool exists = false; + i::Vector<const char> log( + i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); + CHECK(exists); EmbeddedVector<char, 100> prop1_getter_record; i::OS::SNPrintF(prop1_getter_record, "code-creation,Callback,0x%" V8PRIxPTR ",1,\"get prop1\"", Prop1Getter); - CHECK_NE(NULL, matcher.Find(prop1_getter_record)); + CHECK_NE(NULL, + StrNStr(log.start(), prop1_getter_record.start(), log.length())); + EmbeddedVector<char, 100> prop1_setter_record; i::OS::SNPrintF(prop1_setter_record, "code-creation,Callback,0x%" V8PRIxPTR ",1,\"set prop1\"", Prop1Setter); - CHECK_NE(NULL, matcher.Find(prop1_setter_record)); + CHECK_NE(NULL, + StrNStr(log.start(), prop1_setter_record.start(), log.length())); + EmbeddedVector<char, 100> prop2_getter_record; i::OS::SNPrintF(prop2_getter_record, "code-creation,Callback,0x%" V8PRIxPTR ",1,\"get prop2\"", Prop2Getter); - CHECK_NE(NULL, matcher.Find(prop2_getter_record)); + CHECK_NE(NULL, + StrNStr(log.start(), prop2_getter_record.start(), log.length())); obj.Dispose(); } @@ -625,377 +469,6 @@ TEST(IsLoggingPreserved) { } -static inline bool IsStringEqualTo(const char* r, const char* s) { - return strncmp(r, s, strlen(r)) == 0; -} - - -static bool Consume(const char* str, char** buf) { - if (IsStringEqualTo(str, *buf)) { - *buf += strlen(str); - return true; - } - return false; -} - - -namespace { - -// A code entity is a pointer to a position of code-creation event in buffer log -// offset to a point where entity size begins, i.e.: '255,"func"\n'. This makes -// comparing code entities pretty easy. -typedef char* CodeEntityInfo; - -class Interval { - public: - Interval() - : min_addr_(reinterpret_cast<Address>(-1)), - max_addr_(reinterpret_cast<Address>(0)), next_(NULL) {} - - ~Interval() { delete next_; } - - size_t Length() { - size_t result = max_addr_ - min_addr_ + 1; - if (next_ != NULL) result += next_->Length(); - return result; - } - - void CloneFrom(Interval* src) { - while (src != NULL) { - RegisterAddress(src->min_addr_); - RegisterAddress(src->max_addr_); - src = src->next_; - } - } - - bool Contains(Address addr) { - if (min_addr_ <= addr && addr <= max_addr_) { - return true; - } - if (next_ != NULL) { - return next_->Contains(addr); - } else { - return false; - } - } - - size_t GetIndex(Address addr) { - if (min_addr_ <= addr && addr <= max_addr_) { - return addr - min_addr_; - } - CHECK_NE(NULL, next_); - return (max_addr_ - min_addr_ + 1) + next_->GetIndex(addr); - } - - Address GetMinAddr() { - return next_ == NULL ? min_addr_ : i::Min(min_addr_, next_->GetMinAddr()); - } - - Address GetMaxAddr() { - return next_ == NULL ? max_addr_ : i::Max(max_addr_, next_->GetMaxAddr()); - } - - void RegisterAddress(Address addr) { - if (min_addr_ == reinterpret_cast<Address>(-1) - || (size_t)(addr > min_addr_ ? - addr - min_addr_ : min_addr_ - addr) < MAX_DELTA) { - if (addr < min_addr_) min_addr_ = addr; - if (addr > max_addr_) max_addr_ = addr; - } else { - if (next_ == NULL) next_ = new Interval(); - next_->RegisterAddress(addr); - } - } - - Address raw_min_addr() { return min_addr_; } - - Address raw_max_addr() { return max_addr_; } - - Interval* get_next() { return next_; } - - private: - static const size_t MAX_DELTA = 0x100000; - Address min_addr_; - Address max_addr_; - Interval* next_; -}; - - -// A structure used to return log parsing results. -class ParseLogResult { - public: - ParseLogResult() - : entities_map(NULL), entities(NULL), - max_entities(0) {} - - ~ParseLogResult() { - i::DeleteArray(entities_map); - i::DeleteArray(entities); - } - - void AllocateEntities() { - // Make sure that the test doesn't operate on a bogus log. - CHECK_GT(max_entities, 0); - CHECK_GT(bounds.GetMinAddr(), 0); - CHECK_GT(bounds.GetMaxAddr(), bounds.GetMinAddr()); - - entities = i::NewArray<CodeEntityInfo>(max_entities); - for (int i = 0; i < max_entities; ++i) { - entities[i] = NULL; - } - const size_t map_length = bounds.Length(); - entities_map = i::NewArray<int>(static_cast<int>(map_length)); - for (size_t i = 0; i < map_length; ++i) { - entities_map[i] = -1; - } - } - - bool HasIndexForAddress(Address addr) { - return bounds.Contains(addr); - } - - size_t GetIndexForAddress(Address addr) { - CHECK(HasIndexForAddress(addr)); - return bounds.GetIndex(addr); - } - - CodeEntityInfo GetEntity(Address addr) { - if (HasIndexForAddress(addr)) { - size_t idx = GetIndexForAddress(addr); - int item = entities_map[idx]; - return item != -1 ? entities[item] : NULL; - } - return NULL; - } - - void ParseAddress(char* start) { - Address addr = - reinterpret_cast<Address>(strtoul(start, NULL, 16)); // NOLINT - bounds.RegisterAddress(addr); - } - - Address ConsumeAddress(char** start) { - char* end_ptr; - Address addr = - reinterpret_cast<Address>(strtoul(*start, &end_ptr, 16)); // NOLINT - CHECK(HasIndexForAddress(addr)); - *start = end_ptr; - return addr; - } - - Interval bounds; - // Memory map of entities start addresses. - int* entities_map; - // An array of code entities. - CodeEntityInfo* entities; - // Maximal entities count. Actual entities count can be lower, - // empty entity slots are pointing to NULL. - int max_entities; -}; - -} // namespace - - -typedef void (*ParserBlock)(char* start, char* end, ParseLogResult* result); - -static void ParserCycle( - char* start, char* end, ParseLogResult* result, - ParserBlock block_creation, ParserBlock block_delete, - ParserBlock block_move) { - - const char* code_creation = "code-creation,"; - const char* code_delete = "code-delete,"; - const char* code_move = "code-move,"; - - const char* lazy_compile = "LazyCompile,"; - const char* script = "Script,"; - const char* function = "Function,"; - - while (start < end) { - if (Consume(code_creation, &start)) { - if (Consume(lazy_compile, &start) - || Consume(script, &start) - || Consume(function, &start)) { - block_creation(start, end, result); - } - } else if (Consume(code_delete, &start)) { - block_delete(start, end, result); - } else if (Consume(code_move, &start)) { - block_move(start, end, result); - } - while (start < end && *start != '\n') ++start; - ++start; - } -} - - -static void Pass1CodeCreation(char* start, char* end, ParseLogResult* result) { - result->ParseAddress(start); - ++result->max_entities; -} - - -static void Pass1CodeDelete(char* start, char* end, ParseLogResult* result) { - result->ParseAddress(start); -} - - -static void Pass1CodeMove(char* start, char* end, ParseLogResult* result) { - result->ParseAddress(start); - // Skip old address. - while (start < end && *start != ',') ++start; - CHECK_GT(end, start); - ++start; // Skip ','. - result->ParseAddress(start); -} - - -static void Pass2CodeCreation(char* start, char* end, ParseLogResult* result) { - Address addr = result->ConsumeAddress(&start); - CHECK_GT(end, start); - ++start; // Skip ','. - - size_t idx = result->GetIndexForAddress(addr); - result->entities_map[idx] = -1; - for (int i = 0; i < result->max_entities; ++i) { - // Find an empty slot and fill it. - if (result->entities[i] == NULL) { - result->entities[i] = start; - result->entities_map[idx] = i; - break; - } - } - // Make sure that a slot was found. - CHECK_GE(result->entities_map[idx], 0); -} - - -static void Pass2CodeDelete(char* start, char* end, ParseLogResult* result) { - Address addr = result->ConsumeAddress(&start); - size_t idx = result->GetIndexForAddress(addr); - // There can be code deletes that are not related to JS code. - if (result->entities_map[idx] >= 0) { - result->entities[result->entities_map[idx]] = NULL; - result->entities_map[idx] = -1; - } -} - - -static void Pass2CodeMove(char* start, char* end, ParseLogResult* result) { - Address from_addr = result->ConsumeAddress(&start); - CHECK_GT(end, start); - ++start; // Skip ','. - Address to_addr = result->ConsumeAddress(&start); - CHECK_GT(end, start); - - size_t from_idx = result->GetIndexForAddress(from_addr); - size_t to_idx = result->GetIndexForAddress(to_addr); - // There can be code moves that are not related to JS code. - if (from_idx != to_idx && result->entities_map[from_idx] >= 0) { - CHECK_EQ(-1, result->entities_map[to_idx]); - result->entities_map[to_idx] = result->entities_map[from_idx]; - result->entities_map[from_idx] = -1; - }; -} - - -static void ParseLog(char* start, char* end, ParseLogResult* result) { - // Pass 1: Calculate boundaries of addresses and entities count. - ParserCycle(start, end, result, - Pass1CodeCreation, Pass1CodeDelete, Pass1CodeMove); - - printf("min_addr: %p, max_addr: %p, entities: %d\n", - result->bounds.GetMinAddr(), result->bounds.GetMaxAddr(), - result->max_entities); - - result->AllocateEntities(); - - // Pass 2: Fill in code entries data. - ParserCycle(start, end, result, - Pass2CodeCreation, Pass2CodeDelete, Pass2CodeMove); -} - - -static inline void PrintCodeEntityInfo(CodeEntityInfo entity) { - const int max_len = 50; - if (entity != NULL) { - char* eol = strchr(entity, '\n'); - int len = static_cast<int>(eol - entity); - len = len <= max_len ? len : max_len; - printf("%-*.*s ", max_len, len, entity); - } else { - printf("%*s", max_len + 1, ""); - } -} - - -static void PrintCodeEntitiesInfo( - bool is_equal, Address addr, - CodeEntityInfo l_entity, CodeEntityInfo r_entity) { - printf("%c %p ", is_equal ? ' ' : '*', addr); - PrintCodeEntityInfo(l_entity); - PrintCodeEntityInfo(r_entity); - printf("\n"); -} - - -static inline int StrChrLen(const char* s, char c) { - return static_cast<int>(strchr(s, c) - s); -} - - -static bool AreFuncSizesEqual(CodeEntityInfo ref_s, CodeEntityInfo new_s) { - int ref_len = StrChrLen(ref_s, ','); - int new_len = StrChrLen(new_s, ','); - return ref_len == new_len && strncmp(ref_s, new_s, ref_len) == 0; -} - - -static bool AreFuncNamesEqual(CodeEntityInfo ref_s, CodeEntityInfo new_s) { - // Skip size. - ref_s = strchr(ref_s, ',') + 1; - new_s = strchr(new_s, ',') + 1; - CHECK_EQ('"', ref_s[0]); - CHECK_EQ('"', new_s[0]); - int ref_len = StrChrLen(ref_s + 1, '\"'); - int new_len = StrChrLen(new_s + 1, '\"'); - // A special case for ErrorPrototype. Haven't yet figured out why they - // are different. - const char* error_prototype = "\"ErrorPrototype"; - if (IsStringEqualTo(error_prototype, ref_s) - && IsStringEqualTo(error_prototype, new_s)) { - return true; - } - // Built-in objects have problems too. - const char* built_ins[] = { - "\"Boolean\"", "\"Function\"", "\"Number\"", - "\"Object\"", "\"Script\"", "\"String\"" - }; - for (size_t i = 0; i < sizeof(built_ins) / sizeof(*built_ins); ++i) { - if (IsStringEqualTo(built_ins[i], new_s)) { - return true; - } - } - return ref_len == new_len && strncmp(ref_s, new_s, ref_len) == 0; -} - - -static bool AreEntitiesEqual(CodeEntityInfo ref_e, CodeEntityInfo new_e) { - if (ref_e == NULL && new_e != NULL) return true; - if (ref_e != NULL && new_e != NULL) { - return AreFuncSizesEqual(ref_e, new_e) && AreFuncNamesEqual(ref_e, new_e); - } - if (ref_e != NULL && new_e == NULL) { - // args_count entities (argument adapters) are not found by heap traversal, - // but they are not needed because they doesn't contain any code. - ref_e = strchr(ref_e, ',') + 1; - const char* args_count = "\"args_count:"; - return IsStringEqualTo(args_count, ref_e); - } - return false; -} - - // Test that logging of code create / move / delete events // is equivalent to traversal of a resulting heap. TEST(EquivalenceOfLoggingAndTraversal) { @@ -1008,86 +481,68 @@ TEST(EquivalenceOfLoggingAndTraversal) { // P.S. No, V8 can't be re-initialized after disposal, see include/v8.h. CHECK(!i::V8::IsRunning()); - i::FLAG_logfile = "*"; - i::FLAG_log = true; - i::FLAG_log_code = true; - - // Make sure objects move. - bool saved_always_compact = i::FLAG_always_compact; - if (!i::FLAG_never_compact) { - i::FLAG_always_compact = true; - } - - v8::HandleScope scope; - v8::Handle<v8::Value> global_object = v8::Handle<v8::Value>(); - v8::Handle<v8::Context> env = v8::Context::New( - 0, v8::Handle<v8::ObjectTemplate>(), global_object); - env->Enter(); + // Start with profiling to capture all code events from the beginning. + ScopedLoggerInitializer initialize_logger(false); // Compile and run a function that creates other functions. - CompileAndRunScript( + CompileRun( "(function f(obj) {\n" " obj.test =\n" " (function a(j) { return function b() { return j; } })(100);\n" "})(this);"); - HEAP->CollectAllGarbage(false); - - EmbeddedVector<char, 204800> buffer; - int log_size; - ParseLogResult ref_result; - - // Retrieve the log. - { - // Make sure that no GCs occur prior to LogCompiledFunctions call. - i::AssertNoAllocation no_alloc; - - log_size = GetLogLines(0, &buffer); - CHECK_GT(log_size, 0); - CHECK_GT(buffer.length(), log_size); - - // Fill a map of compiled code objects. - ParseLog(buffer.start(), buffer.start() + log_size, &ref_result); - } + v8::V8::PauseProfiler(); + HEAP->CollectAllGarbage(true); + LOGGER->StringEvent("test-logging-done", ""); // Iterate heap to find compiled functions, will write to log. LOGGER->LogCompiledFunctions(); - char* new_log_start = buffer.start() + log_size; - const int new_log_size = LOGGER->GetLogLines( - log_size, new_log_start, buffer.length() - log_size); - CHECK_GT(new_log_size, 0); - CHECK_GT(buffer.length(), log_size + new_log_size); - - // Fill an equivalent map of compiled code objects. - ParseLogResult new_result; - ParseLog(new_log_start, new_log_start + new_log_size, &new_result); - - // Test their actual equivalence. - Interval combined; - combined.CloneFrom(&ref_result.bounds); - combined.CloneFrom(&new_result.bounds); - Interval* iter = &combined; - bool results_equal = true; - - while (iter != NULL) { - for (Address addr = iter->raw_min_addr(); - addr <= iter->raw_max_addr(); ++addr) { - CodeEntityInfo ref_entity = ref_result.GetEntity(addr); - CodeEntityInfo new_entity = new_result.GetEntity(addr); - if (ref_entity != NULL || new_entity != NULL) { - const bool equal = AreEntitiesEqual(ref_entity, new_entity); - if (!equal) results_equal = false; - PrintCodeEntitiesInfo(equal, addr, ref_entity, new_entity); - } + LOGGER->StringEvent("test-traversal-done", ""); + + bool exists = false; + i::Vector<const char> log( + i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); + CHECK(exists); + v8::Handle<v8::String> log_str = v8::String::New(log.start(), log.length()); + initialize_logger.env()->Global()->Set(v8_str("_log"), log_str); + + const char* scripts[] = { + "tools/splaytree.js", "tools/codemap.js", "tools/csvparser.js", + "tools/consarray.js", "tools/profile.js", "tools/profile_view.js", + "tools/logreader.js", "test/cctest/log-eq-of-logging-and-traversal.js" + }; + int scripts_count = sizeof(scripts) / sizeof(scripts[0]); + v8::Handle<v8::Value> last_result; + for (int i = 0; i < scripts_count; ++i) { + bool exists = true; + i::Vector<const char> source(i::ReadFile(scripts[i], &exists, true)); + CHECK(exists); + CHECK_GT(source.length(), 0); + v8::Handle<v8::String> source_str = + v8::String::New(source.start(), source.length()); + v8::TryCatch try_catch; + v8::Handle<v8::Script> script = + v8::Script::Compile(source_str, v8_str(scripts[i])); + if (script.IsEmpty()) { + v8::String::Utf8Value exception(try_catch.Exception()); + printf("compile %s: %s\n", scripts[i], *exception); + CHECK(false); + } + last_result = script->Run(); + if (last_result.IsEmpty()) { + v8::String::Utf8Value exception(try_catch.Exception()); + printf("run %s: %s\n", scripts[i], *exception); + CHECK(false); } - iter = iter->get_next(); } - // Make sure that all log data is written prior crash due to CHECK failure. - fflush(stdout); - CHECK(results_equal); - - env->Exit(); - LOGGER->TearDown(); - i::FLAG_always_compact = saved_always_compact; + // The result either be a "true" literal or problem description. + if (!last_result->IsTrue()) { + v8::Local<v8::String> s = last_result->ToString(); + i::ScopedVector<char> data(s->Length() + 1); + CHECK_NE(NULL, data.start()); + s->WriteAscii(data.start()); + printf("%s\n", data.start()); + // Make sure that our output is written prior crash due to CHECK failure. + fflush(stdout); + CHECK(false); + } } - -#endif // ENABLE_LOGGING_AND_PROFILING |