2009-05-05 15:57:47 +00:00
|
|
|
// Copyright 2006-2009 the V8 project authors. All rights reserved.
|
|
|
|
//
|
|
|
|
// Tests of logging functions from log.h
|
|
|
|
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
|
2009-07-28 09:10:29 +00:00
|
|
|
#ifdef __linux__
|
|
|
|
#include <signal.h>
|
|
|
|
#include <unistd.h>
|
|
|
|
#endif
|
2009-05-05 15:57:47 +00:00
|
|
|
|
2009-07-28 09:10:29 +00:00
|
|
|
#include "v8.h"
|
2009-05-05 15:57:47 +00:00
|
|
|
#include "log.h"
|
|
|
|
#include "cctest.h"
|
|
|
|
|
2009-05-20 09:04:13 +00:00
|
|
|
using v8::internal::Address;
|
2009-05-25 08:25:36 +00:00
|
|
|
using v8::internal::EmbeddedVector;
|
2009-05-05 15:57:47 +00:00
|
|
|
using v8::internal::Logger;
|
|
|
|
|
2009-05-20 09:04:13 +00:00
|
|
|
namespace i = v8::internal;
|
|
|
|
|
2009-05-05 15:57:47 +00:00
|
|
|
static void SetUp() {
|
|
|
|
// Log to memory buffer.
|
2009-05-20 09:04:13 +00:00
|
|
|
i::FLAG_logfile = "*";
|
|
|
|
i::FLAG_log = true;
|
2009-05-05 15:57:47 +00:00
|
|
|
Logger::Setup();
|
|
|
|
}
|
|
|
|
|
|
|
|
static void TearDown() {
|
|
|
|
Logger::TearDown();
|
|
|
|
}
|
|
|
|
|
2009-05-08 10:06:38 +00:00
|
|
|
|
2009-05-05 15:57:47 +00:00
|
|
|
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));
|
|
|
|
// Requesting data size which is smaller than first log message length.
|
|
|
|
CHECK_EQ(0, Logger::GetLogLines(0, log_lines, 3));
|
|
|
|
// See Logger::StringEvent.
|
|
|
|
const char* line_1 = "aaa,\"bbb\"\n";
|
|
|
|
const int line_1_len = strlen(line_1);
|
|
|
|
// Still smaller than log message length.
|
|
|
|
CHECK_EQ(0, Logger::GetLogLines(0, log_lines, line_1_len - 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));
|
2009-05-28 07:08:09 +00:00
|
|
|
log_lines[line_1_len] = '\0';
|
2009-05-05 15:57:47 +00:00
|
|
|
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 = strlen(line_2);
|
|
|
|
// Now start with line_2 beginning.
|
|
|
|
CHECK_EQ(0, Logger::GetLogLines(line_1_len, log_lines, 0));
|
|
|
|
CHECK_EQ(0, Logger::GetLogLines(line_1_len, log_lines, 3));
|
|
|
|
CHECK_EQ(0, Logger::GetLogLines(line_1_len, log_lines, line_2_len - 1));
|
|
|
|
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 = strlen(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();
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-05-25 08:25:36 +00:00
|
|
|
static int GetLogLines(int start_pos, i::Vector<char>* buffer) {
|
|
|
|
return Logger::GetLogLines(start_pos, buffer->start(), buffer->length());
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-05-05 15:57:47 +00:00
|
|
|
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 = strlen(all_lines);
|
2009-05-25 08:25:36 +00:00
|
|
|
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));
|
2009-05-05 15:57:47 +00:00
|
|
|
TearDown();
|
|
|
|
}
|
|
|
|
|
2009-05-08 10:06:38 +00:00
|
|
|
|
|
|
|
TEST(MemoryLoggingTurnedOff) {
|
|
|
|
// Log to stdout
|
2009-05-20 09:04:13 +00:00
|
|
|
i::FLAG_logfile = "-";
|
|
|
|
i::FLAG_log = true;
|
2009-05-08 10:06:38 +00:00
|
|
|
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();
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-05-25 08:25:36 +00:00
|
|
|
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(); }
|
|
|
|
};
|
|
|
|
|
|
|
|
} // namespace v8::internal
|
|
|
|
} // namespace v8
|
|
|
|
|
|
|
|
using v8::internal::LoggerTestHelper;
|
|
|
|
|
|
|
|
|
2009-07-28 08:34:55 +00:00
|
|
|
// Under Linux, we need to check if signals were delivered to avoid false
|
|
|
|
// positives. Under other platforms profiling is done via a high-priority
|
|
|
|
// thread, so this case never happen.
|
|
|
|
static bool was_sigprof_received = true;
|
|
|
|
#ifdef __linux__
|
|
|
|
|
|
|
|
struct sigaction old_sigprof_handler;
|
|
|
|
|
|
|
|
static void SigProfSignalHandler(int signal, siginfo_t* info, void* context) {
|
|
|
|
if (signal != SIGPROF) return;
|
|
|
|
was_sigprof_received = true;
|
|
|
|
old_sigprof_handler.sa_sigaction(signal, info, context);
|
|
|
|
}
|
|
|
|
|
|
|
|
#endif // __linux__
|
|
|
|
|
|
|
|
|
2009-05-25 08:25:36 +00:00
|
|
|
static int CheckThatProfilerWorks(int log_pos) {
|
2009-08-04 14:14:01 +00:00
|
|
|
Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU);
|
2009-05-25 08:25:36 +00:00
|
|
|
CHECK(LoggerTestHelper::IsSamplerActive());
|
|
|
|
|
|
|
|
// Verify that the current map of compiled functions has been logged.
|
|
|
|
EmbeddedVector<char, 102400> buffer;
|
|
|
|
int map_log_size = GetLogLines(log_pos, &buffer);
|
|
|
|
printf("map_log_size: %d\n", map_log_size);
|
|
|
|
CHECK_GT(map_log_size, 0);
|
|
|
|
CHECK_GT(buffer.length(), map_log_size);
|
|
|
|
log_pos += map_log_size;
|
|
|
|
// Check buffer contents.
|
|
|
|
buffer[map_log_size] = '\0';
|
|
|
|
const char* code_creation = "\ncode-creation,"; // eq. to /^code-creation,/
|
|
|
|
CHECK_NE(NULL, strstr(buffer.start(), code_creation));
|
|
|
|
|
2009-07-28 08:34:55 +00:00
|
|
|
#ifdef __linux__
|
|
|
|
// Intercept SIGPROF handler to make sure that the test process
|
|
|
|
// had received it. Under load, system can defer it causing test failure.
|
|
|
|
// It is important to execute this after 'ResumeProfiler'.
|
|
|
|
was_sigprof_received = false;
|
|
|
|
struct sigaction sa;
|
|
|
|
sa.sa_sigaction = SigProfSignalHandler;
|
|
|
|
sigemptyset(&sa.sa_mask);
|
|
|
|
sa.sa_flags = SA_SIGINFO;
|
|
|
|
CHECK_EQ(0, sigaction(SIGPROF, &sa, &old_sigprof_handler));
|
|
|
|
#endif // __linux__
|
|
|
|
|
2009-05-25 08:25:36 +00:00
|
|
|
// Force compiler to generate new code by parametrizing source.
|
|
|
|
EmbeddedVector<char, 100> script_src;
|
|
|
|
i::OS::SNPrintF(script_src,
|
|
|
|
"for (var i = 0; i < 1000; ++i) { "
|
|
|
|
"(function(x) { return %d * x; })(i); }",
|
|
|
|
log_pos);
|
2009-05-29 15:33:02 +00:00
|
|
|
// Run code for 200 msecs to get some ticks.
|
|
|
|
const double end_time = i::OS::TimeCurrentMillis() + 200;
|
|
|
|
while (i::OS::TimeCurrentMillis() < end_time) {
|
2009-05-25 08:25:36 +00:00
|
|
|
CompileAndRunScript(script_src.start());
|
2009-07-28 08:34:55 +00:00
|
|
|
// Yield CPU to give Profiler thread a chance to process ticks.
|
|
|
|
i::OS::Sleep(1);
|
2009-05-25 08:25:36 +00:00
|
|
|
}
|
|
|
|
|
2009-08-04 14:14:01 +00:00
|
|
|
Logger::PauseProfiler(v8::PROFILER_MODULE_CPU);
|
2009-05-25 08:25:36 +00:00
|
|
|
CHECK(!LoggerTestHelper::IsSamplerActive());
|
|
|
|
|
2009-05-29 15:33:02 +00:00
|
|
|
// Wait 50 msecs to allow Profiler thread to process the last
|
|
|
|
// tick sample it has got.
|
|
|
|
i::OS::Sleep(50);
|
|
|
|
|
2009-05-25 08:25:36 +00:00
|
|
|
// Now we must have compiler and tick records.
|
|
|
|
int log_size = GetLogLines(log_pos, &buffer);
|
|
|
|
printf("log_size: %d\n", log_size);
|
|
|
|
CHECK_GT(log_size, 0);
|
|
|
|
CHECK_GT(buffer.length(), log_size);
|
|
|
|
log_pos += log_size;
|
|
|
|
// Check buffer contents.
|
|
|
|
buffer[log_size] = '\0';
|
|
|
|
const char* tick = "\ntick,";
|
|
|
|
CHECK_NE(NULL, strstr(buffer.start(), code_creation));
|
2009-07-28 08:34:55 +00:00
|
|
|
const bool ticks_found = strstr(buffer.start(), tick) != NULL;
|
|
|
|
CHECK_EQ(was_sigprof_received, ticks_found);
|
2009-05-25 08:25:36 +00:00
|
|
|
|
|
|
|
return log_pos;
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
TEST(ProfLazyMode) {
|
|
|
|
const bool saved_prof_lazy = i::FLAG_prof_lazy;
|
|
|
|
const bool saved_prof = i::FLAG_prof;
|
|
|
|
const bool saved_prof_auto = i::FLAG_prof_auto;
|
|
|
|
i::FLAG_prof = true;
|
|
|
|
i::FLAG_prof_lazy = true;
|
|
|
|
i::FLAG_prof_auto = false;
|
|
|
|
i::FLAG_logfile = "*";
|
|
|
|
|
|
|
|
// If tests are being run manually, V8 will be already initialized
|
|
|
|
// by the test below.
|
2009-05-25 19:39:52 +00:00
|
|
|
const bool need_to_set_up_logger = i::V8::IsRunning();
|
2009-05-25 08:25:36 +00:00
|
|
|
v8::HandleScope scope;
|
|
|
|
v8::Handle<v8::Context> env = v8::Context::New();
|
|
|
|
if (need_to_set_up_logger) Logger::Setup();
|
|
|
|
env->Enter();
|
|
|
|
|
|
|
|
// No sampling should happen prior to resuming profiler.
|
|
|
|
CHECK(!LoggerTestHelper::IsSamplerActive());
|
|
|
|
|
|
|
|
// Read initial logged data (static libs map).
|
|
|
|
EmbeddedVector<char, 102400> buffer;
|
|
|
|
int log_pos = GetLogLines(0, &buffer);
|
|
|
|
CHECK_GT(log_pos, 0);
|
|
|
|
CHECK_GT(buffer.length(), log_pos);
|
|
|
|
|
|
|
|
CompileAndRunScript("var a = (function(x) { return x + 1; })(10);");
|
|
|
|
|
|
|
|
// Nothing must be logged while profiling is suspended.
|
|
|
|
CHECK_EQ(0, GetLogLines(log_pos, &buffer));
|
|
|
|
|
|
|
|
log_pos = CheckThatProfilerWorks(log_pos);
|
|
|
|
|
|
|
|
CompileAndRunScript("var a = (function(x) { return x + 1; })(10);");
|
|
|
|
|
|
|
|
// No new data beyond last retrieved position.
|
|
|
|
CHECK_EQ(0, GetLogLines(log_pos, &buffer));
|
|
|
|
|
|
|
|
// Check that profiling can be resumed again.
|
|
|
|
CheckThatProfilerWorks(log_pos);
|
|
|
|
|
|
|
|
env->Exit();
|
|
|
|
Logger::TearDown();
|
|
|
|
i::FLAG_prof_lazy = saved_prof_lazy;
|
|
|
|
i::FLAG_prof = saved_prof;
|
|
|
|
i::FLAG_prof_auto = saved_prof_auto;
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-05-20 09:04:13 +00:00
|
|
|
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;
|
|
|
|
|
2009-05-20 16:43:46 +00:00
|
|
|
class Interval {
|
|
|
|
public:
|
|
|
|
Interval()
|
2009-05-25 10:27:18 +00:00
|
|
|
: min_addr_(reinterpret_cast<Address>(-1)),
|
|
|
|
max_addr_(reinterpret_cast<Address>(0)), next_(NULL) {}
|
2009-05-20 16:43:46 +00:00
|
|
|
|
2009-05-25 10:27:18 +00:00
|
|
|
~Interval() { delete next_; }
|
2009-05-20 16:43:46 +00:00
|
|
|
|
|
|
|
size_t Length() {
|
2009-05-25 10:27:18 +00:00
|
|
|
size_t result = max_addr_ - min_addr_ + 1;
|
|
|
|
if (next_ != NULL) result += next_->Length();
|
2009-05-20 16:43:46 +00:00
|
|
|
return result;
|
|
|
|
}
|
|
|
|
|
|
|
|
void CloneFrom(Interval* src) {
|
|
|
|
while (src != NULL) {
|
2009-05-25 10:27:18 +00:00
|
|
|
RegisterAddress(src->min_addr_);
|
|
|
|
RegisterAddress(src->max_addr_);
|
|
|
|
src = src->next_;
|
2009-05-20 16:43:46 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
bool Contains(Address addr) {
|
2009-05-25 10:27:18 +00:00
|
|
|
if (min_addr_ <= addr && addr <= max_addr_) {
|
2009-05-20 16:43:46 +00:00
|
|
|
return true;
|
|
|
|
}
|
2009-05-25 10:27:18 +00:00
|
|
|
if (next_ != NULL) {
|
|
|
|
return next_->Contains(addr);
|
|
|
|
} else {
|
|
|
|
return false;
|
|
|
|
}
|
2009-05-20 16:43:46 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
size_t GetIndex(Address addr) {
|
2009-05-25 10:27:18 +00:00
|
|
|
if (min_addr_ <= addr && addr <= max_addr_) {
|
|
|
|
return addr - min_addr_;
|
2009-05-20 16:43:46 +00:00
|
|
|
}
|
2009-05-25 10:27:18 +00:00
|
|
|
CHECK_NE(NULL, next_);
|
|
|
|
return (max_addr_ - min_addr_ + 1) + next_->GetIndex(addr);
|
2009-05-20 16:43:46 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
Address GetMinAddr() {
|
2009-05-25 10:27:18 +00:00
|
|
|
return next_ == NULL ? min_addr_ : i::Min(min_addr_, next_->GetMinAddr());
|
2009-05-20 16:43:46 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
Address GetMaxAddr() {
|
2009-05-25 10:27:18 +00:00
|
|
|
return next_ == NULL ? max_addr_ : i::Max(max_addr_, next_->GetMaxAddr());
|
2009-05-20 16:43:46 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
void RegisterAddress(Address addr) {
|
2009-05-25 10:27:18 +00:00
|
|
|
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;
|
2009-05-20 16:43:46 +00:00
|
|
|
} else {
|
2009-05-25 10:27:18 +00:00
|
|
|
if (next_ == NULL) next_ = new Interval();
|
|
|
|
next_->RegisterAddress(addr);
|
2009-05-20 16:43:46 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2009-05-25 10:27:18 +00:00
|
|
|
Address raw_min_addr() { return min_addr_; }
|
2009-05-20 16:43:46 +00:00
|
|
|
|
2009-05-25 10:27:18 +00:00
|
|
|
Address raw_max_addr() { return max_addr_; }
|
2009-05-20 16:43:46 +00:00
|
|
|
|
2009-05-25 10:27:18 +00:00
|
|
|
Interval* get_next() { return next_; }
|
2009-05-20 16:43:46 +00:00
|
|
|
|
|
|
|
private:
|
|
|
|
static const size_t MAX_DELTA = 0x100000;
|
2009-05-25 10:27:18 +00:00
|
|
|
Address min_addr_;
|
|
|
|
Address max_addr_;
|
|
|
|
Interval* next_;
|
2009-05-20 16:43:46 +00:00
|
|
|
};
|
|
|
|
|
|
|
|
|
2009-05-20 09:04:13 +00:00
|
|
|
// A structure used to return log parsing results.
|
|
|
|
class ParseLogResult {
|
|
|
|
public:
|
|
|
|
ParseLogResult()
|
2009-05-20 16:43:46 +00:00
|
|
|
: entities_map(NULL), entities(NULL),
|
2009-05-20 12:47:30 +00:00
|
|
|
max_entities(0) {}
|
2009-05-20 09:04:13 +00:00
|
|
|
|
|
|
|
~ParseLogResult() {
|
2009-05-20 16:43:46 +00:00
|
|
|
i::DeleteArray(entities_map);
|
2009-05-20 09:04:13 +00:00
|
|
|
i::DeleteArray(entities);
|
|
|
|
}
|
|
|
|
|
|
|
|
void AllocateEntities() {
|
|
|
|
// Make sure that the test doesn't operate on a bogus log.
|
|
|
|
CHECK_GT(max_entities, 0);
|
2009-05-20 16:43:46 +00:00
|
|
|
CHECK_GT(bounds.GetMinAddr(), 0);
|
|
|
|
CHECK_GT(bounds.GetMaxAddr(), bounds.GetMinAddr());
|
2009-05-20 09:04:13 +00:00
|
|
|
|
|
|
|
entities = i::NewArray<CodeEntityInfo>(max_entities);
|
|
|
|
for (int i = 0; i < max_entities; ++i) {
|
|
|
|
entities[i] = NULL;
|
|
|
|
}
|
2009-05-20 16:43:46 +00:00
|
|
|
const size_t map_length = bounds.Length();
|
2009-05-20 09:04:13 +00:00
|
|
|
entities_map = i::NewArray<int>(map_length);
|
2009-05-20 16:43:46 +00:00
|
|
|
for (size_t i = 0; i < map_length; ++i) {
|
2009-05-20 09:04:13 +00:00
|
|
|
entities_map[i] = -1;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2009-05-20 16:43:46 +00:00
|
|
|
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;
|
2009-05-25 10:27:18 +00:00
|
|
|
// Memory map of entities start addresses.
|
2009-05-20 09:04:13 +00:00
|
|
|
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;
|
|
|
|
};
|
|
|
|
|
2009-05-20 12:47:30 +00:00
|
|
|
} // namespace
|
2009-05-20 09:04:13 +00:00
|
|
|
|
|
|
|
|
|
|
|
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) {
|
2009-05-20 16:43:46 +00:00
|
|
|
result->ParseAddress(start);
|
2009-05-20 09:04:13 +00:00
|
|
|
++result->max_entities;
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
static void Pass1CodeDelete(char* start, char* end, ParseLogResult* result) {
|
2009-05-20 16:43:46 +00:00
|
|
|
result->ParseAddress(start);
|
2009-05-20 09:04:13 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
static void Pass1CodeMove(char* start, char* end, ParseLogResult* result) {
|
2009-05-20 16:43:46 +00:00
|
|
|
result->ParseAddress(start);
|
2009-05-20 09:04:13 +00:00
|
|
|
// Skip old address.
|
|
|
|
while (start < end && *start != ',') ++start;
|
|
|
|
CHECK_GT(end, start);
|
2009-05-20 12:47:30 +00:00
|
|
|
++start; // Skip ','.
|
2009-05-20 16:43:46 +00:00
|
|
|
result->ParseAddress(start);
|
2009-05-20 09:04:13 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
static void Pass2CodeCreation(char* start, char* end, ParseLogResult* result) {
|
2009-05-20 16:43:46 +00:00
|
|
|
Address addr = result->ConsumeAddress(&start);
|
2009-05-20 09:04:13 +00:00
|
|
|
CHECK_GT(end, start);
|
2009-05-20 12:47:30 +00:00
|
|
|
++start; // Skip ','.
|
2009-05-20 09:04:13 +00:00
|
|
|
|
2009-05-20 16:43:46 +00:00
|
|
|
size_t idx = result->GetIndexForAddress(addr);
|
2009-05-20 09:04:13 +00:00
|
|
|
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) {
|
2009-05-20 16:43:46 +00:00
|
|
|
Address addr = result->ConsumeAddress(&start);
|
|
|
|
size_t idx = result->GetIndexForAddress(addr);
|
2009-05-20 09:04:13 +00:00
|
|
|
// 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) {
|
2009-05-20 16:43:46 +00:00
|
|
|
Address from_addr = result->ConsumeAddress(&start);
|
2009-05-20 09:04:13 +00:00
|
|
|
CHECK_GT(end, start);
|
2009-05-20 12:47:30 +00:00
|
|
|
++start; // Skip ','.
|
2009-05-20 16:43:46 +00:00
|
|
|
Address to_addr = result->ConsumeAddress(&start);
|
2009-05-20 09:04:13 +00:00
|
|
|
CHECK_GT(end, start);
|
|
|
|
|
2009-05-20 16:43:46 +00:00
|
|
|
size_t from_idx = result->GetIndexForAddress(from_addr);
|
|
|
|
size_t to_idx = result->GetIndexForAddress(to_addr);
|
2009-05-20 09:04:13 +00:00
|
|
|
// 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",
|
2009-05-20 16:43:46 +00:00
|
|
|
result->bounds.GetMinAddr(), result->bounds.GetMaxAddr(),
|
|
|
|
result->max_entities);
|
2009-05-20 09:04:13 +00:00
|
|
|
|
|
|
|
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 = 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 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;
|
|
|
|
int ref_len = StrChrLen(ref_s, '\n');
|
|
|
|
int new_len = StrChrLen(new_s, '\n');
|
|
|
|
// If reference is anonymous (""), it's OK to have anything in new.
|
|
|
|
if (ref_len == 2) return true;
|
|
|
|
// 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;
|
|
|
|
}
|
2009-05-20 12:47:30 +00:00
|
|
|
// 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;
|
|
|
|
}
|
|
|
|
}
|
2009-05-20 09:04:13 +00:00
|
|
|
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) {
|
2009-05-25 08:25:36 +00:00
|
|
|
// This test needs to be run on a "clean" V8 to ensure that snapshot log
|
|
|
|
// is loaded. This is always true when running using tools/test.py because
|
|
|
|
// it launches a new cctest instance for every test. To be sure that launching
|
|
|
|
// cctest manually also works, please be sure that no tests below
|
|
|
|
// are using V8.
|
|
|
|
//
|
|
|
|
// P.S. No, V8 can't be re-initialized after disposal, see include/v8.h.
|
2009-05-25 19:39:52 +00:00
|
|
|
CHECK(!i::V8::IsRunning());
|
2009-05-25 08:25:36 +00:00
|
|
|
|
2009-05-20 09:04:13 +00:00
|
|
|
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;
|
2009-05-20 12:47:30 +00:00
|
|
|
v8::Handle<v8::Value> global_object = v8::Handle<v8::Value>();
|
2009-05-25 08:25:36 +00:00
|
|
|
v8::Handle<v8::Context> env = v8::Context::New(
|
2009-05-20 12:47:30 +00:00
|
|
|
0, v8::Handle<v8::ObjectTemplate>(), global_object);
|
2009-05-20 09:04:13 +00:00
|
|
|
env->Enter();
|
|
|
|
|
|
|
|
// Compile and run a function that creates other functions.
|
2009-05-25 08:25:36 +00:00
|
|
|
CompileAndRunScript(
|
2009-05-20 12:47:30 +00:00
|
|
|
"(function f(obj) {\n"
|
|
|
|
" obj.test =\n"
|
|
|
|
" (function a(j) { return function b() { return j; } })(100);\n"
|
2009-05-25 08:25:36 +00:00
|
|
|
"})(this);");
|
2009-05-20 09:04:13 +00:00
|
|
|
i::Heap::CollectAllGarbage();
|
|
|
|
|
2009-05-25 08:25:36 +00:00
|
|
|
EmbeddedVector<char, 204800> buffer;
|
2009-05-20 09:04:13 +00:00
|
|
|
int log_size;
|
|
|
|
ParseLogResult ref_result;
|
|
|
|
|
|
|
|
// Retrieve the log.
|
|
|
|
{
|
|
|
|
// Make sure that no GCs occur prior to LogCompiledFunctions call.
|
|
|
|
i::AssertNoAllocation no_alloc;
|
|
|
|
|
2009-05-25 08:25:36 +00:00
|
|
|
log_size = GetLogLines(0, &buffer);
|
2009-05-20 09:04:13 +00:00
|
|
|
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);
|
|
|
|
}
|
|
|
|
|
|
|
|
// Iterate heap to find compiled functions, will write to log.
|
|
|
|
i::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.
|
2009-05-20 16:43:46 +00:00
|
|
|
Interval combined;
|
|
|
|
combined.CloneFrom(&ref_result.bounds);
|
|
|
|
combined.CloneFrom(&new_result.bounds);
|
|
|
|
Interval* iter = &combined;
|
2009-05-20 09:04:13 +00:00
|
|
|
bool results_equal = true;
|
2009-05-20 16:43:46 +00:00
|
|
|
|
|
|
|
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);
|
|
|
|
}
|
2009-05-20 09:04:13 +00:00
|
|
|
}
|
2009-05-20 16:43:46 +00:00
|
|
|
iter = iter->get_next();
|
2009-05-20 09:04:13 +00:00
|
|
|
}
|
2009-05-20 12:47:30 +00:00
|
|
|
// Make sure that all log data is written prior crash due to CHECK failure.
|
|
|
|
fflush(stdout);
|
2009-05-20 09:04:13 +00:00
|
|
|
CHECK(results_equal);
|
|
|
|
|
|
|
|
env->Exit();
|
2009-05-25 08:25:36 +00:00
|
|
|
Logger::TearDown();
|
2009-05-20 09:04:13 +00:00
|
|
|
i::FLAG_always_compact = saved_always_compact;
|
|
|
|
}
|
|
|
|
|
2009-05-05 15:57:47 +00:00
|
|
|
#endif // ENABLE_LOGGING_AND_PROFILING
|