Remove support for logging into a memory buffer.

The only usage of it was in logging tests, I've switched them for
using a file.

I've left out support for "--logfile=*" for now, as Chromium uses it.
Will be removed after the next V8 roll.

R=sgjesse@chromium.org
BUG=859
TEST=mjsunit/log-*

Review URL: http://codereview.chromium.org/7310025

git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@8629 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
parent b2e8d72b
......@@ -2983,31 +2983,6 @@ class V8EXPORT V8 {
*/
static bool IsProfilerPaused();
/**
* If logging is performed into a memory buffer (via --logfile=*), allows to
* retrieve previously written messages. This can be used for retrieving
* profiler log data in the application. This function is thread-safe.
*
* Caller provides a destination buffer that must exist during GetLogLines
* call. Only whole log lines are copied into the buffer.
*
* \param from_pos specified a point in a buffer to read from, 0 is the
* beginning of a buffer. It is assumed that caller updates its current
* position using returned size value from the previous call.
* \param dest_buf destination buffer for log data.
* \param max_size size of the destination buffer.
* \returns actual size of log data copied into buffer.
*/
static int GetLogLines(int from_pos, char* dest_buf, int max_size);
/**
* The minimum allowed size for a log lines buffer. If the size of
* the buffer given will not be enough to hold a line of the maximum
* length, an attempt to find a log line end in GetLogLines will
* fail, and an empty result will be returned.
*/
static const int kMinimumSizeForLogLinesBuffer = 2048;
/**
* Retrieve the V8 thread id of the calling thread.
*
......
......@@ -4842,12 +4842,6 @@ bool V8::IsProfilerPaused() {
}
int V8::GetLogLines(int from_pos, char* dest_buf, int max_size) {
ASSERT(max_size >= kMinimumSizeForLogLinesBuffer);
return LOGGER->GetLogLines(from_pos, dest_buf, max_size);
}
int V8::GetCurrentThreadId() {
i::Isolate* isolate = i::Isolate::Current();
EnsureInitializedForIsolate(isolate, "V8::GetCurrentThreadId()");
......
......@@ -33,99 +33,14 @@
namespace v8 {
namespace internal {
LogDynamicBuffer::LogDynamicBuffer(
int block_size, int max_size, const char* seal, int seal_size)
: block_size_(block_size),
max_size_(max_size - (max_size % block_size_)),
seal_(seal),
seal_size_(seal_size),
blocks_(max_size_ / block_size_ + 1),
write_pos_(0), block_index_(0), block_write_pos_(0), is_sealed_(false) {
ASSERT(BlocksCount() > 0);
AllocateBlock(0);
for (int i = 1; i < BlocksCount(); ++i) {
blocks_[i] = NULL;
}
}
LogDynamicBuffer::~LogDynamicBuffer() {
for (int i = 0; i < BlocksCount(); ++i) {
DeleteArray(blocks_[i]);
}
}
int LogDynamicBuffer::Read(int from_pos, char* dest_buf, int buf_size) {
if (buf_size == 0) return 0;
int read_pos = from_pos;
int block_read_index = BlockIndex(from_pos);
int block_read_pos = PosInBlock(from_pos);
int dest_buf_pos = 0;
// Read until dest_buf is filled, or write_pos_ encountered.
while (read_pos < write_pos_ && dest_buf_pos < buf_size) {
const int read_size = Min(write_pos_ - read_pos,
Min(buf_size - dest_buf_pos, block_size_ - block_read_pos));
memcpy(dest_buf + dest_buf_pos,
blocks_[block_read_index] + block_read_pos, read_size);
block_read_pos += read_size;
dest_buf_pos += read_size;
read_pos += read_size;
if (block_read_pos == block_size_) {
block_read_pos = 0;
++block_read_index;
}
}
return dest_buf_pos;
}
int LogDynamicBuffer::Seal() {
WriteInternal(seal_, seal_size_);
is_sealed_ = true;
return 0;
}
int LogDynamicBuffer::Write(const char* data, int data_size) {
if (is_sealed_) {
return 0;
}
if ((write_pos_ + data_size) <= (max_size_ - seal_size_)) {
return WriteInternal(data, data_size);
} else {
return Seal();
}
}
const char* Log::kLogToTemporaryFile = "&";
int LogDynamicBuffer::WriteInternal(const char* data, int data_size) {
int data_pos = 0;
while (data_pos < data_size) {
const int write_size =
Min(data_size - data_pos, block_size_ - block_write_pos_);
memcpy(blocks_[block_index_] + block_write_pos_, data + data_pos,
write_size);
block_write_pos_ += write_size;
data_pos += write_size;
if (block_write_pos_ == block_size_) {
block_write_pos_ = 0;
AllocateBlock(++block_index_);
}
}
write_pos_ += data_size;
return data_size;
}
// Must be the same message as in Logger::PauseProfiler.
const char* const Log::kDynamicBufferSeal = "profiler,\"pause\"\n";
Log::Log(Logger* logger)
: write_to_file_(false),
is_stopped_(false),
: is_stopped_(false),
output_handle_(NULL),
ll_output_handle_(NULL),
output_buffer_(NULL),
mutex_(NULL),
message_buffer_(NULL),
logger_(logger) {
......@@ -163,19 +78,19 @@ void Log::Initialize() {
FLAG_prof_auto = false;
}
bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api
bool open_log_file = FLAG_log || FLAG_log_runtime || FLAG_log_api
|| FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
|| FLAG_log_regexp || FLAG_log_state_changes || FLAG_ll_prof;
bool open_log_file = start_logging || FLAG_prof_lazy;
// If we're logging anything, we need to open the log file.
if (open_log_file) {
if (strcmp(FLAG_logfile, "-") == 0) {
OpenStdout();
} else if (strcmp(FLAG_logfile, "*") == 0) {
OpenMemoryBuffer();
} else {
// Does nothing for now. Will be removed.
} else if (strcmp(FLAG_logfile, kLogToTemporaryFile) == 0) {
OpenTemporaryFile();
} else {
if (strchr(FLAG_logfile, '%') != NULL ||
!Isolate::Current()->IsDefaultIsolate()) {
// If there's a '%' in the log file name we have to expand
......@@ -225,7 +140,12 @@ void Log::Initialize() {
void Log::OpenStdout() {
ASSERT(!IsEnabled());
output_handle_ = stdout;
write_to_file_ = true;
}
void Log::OpenTemporaryFile() {
ASSERT(!IsEnabled());
output_handle_ = i::OS::OpenTemporaryFile();
}
......@@ -240,7 +160,6 @@ static const int kLowLevelLogBufferSize = 2 * MB;
void Log::OpenFile(const char* name) {
ASSERT(!IsEnabled());
output_handle_ = OS::FOpen(name, OS::LogFileOpenMode);
write_to_file_ = true;
if (FLAG_ll_prof) {
// Open the low-level log file.
size_t len = strlen(name);
......@@ -253,25 +172,18 @@ void Log::OpenFile(const char* name) {
}
void Log::OpenMemoryBuffer() {
ASSERT(!IsEnabled());
output_buffer_ = new LogDynamicBuffer(
kDynamicBufferBlockSize, kMaxDynamicBufferSize,
kDynamicBufferSeal, StrLength(kDynamicBufferSeal));
write_to_file_ = false;
}
void Log::Close() {
if (write_to_file_) {
if (output_handle_ != NULL) fclose(output_handle_);
output_handle_ = NULL;
if (ll_output_handle_ != NULL) fclose(ll_output_handle_);
ll_output_handle_ = NULL;
} else {
delete output_buffer_;
output_buffer_ = NULL;
FILE* Log::Close() {
FILE* result = NULL;
if (output_handle_ != NULL) {
if (strcmp(FLAG_logfile, kLogToTemporaryFile) != 0) {
fclose(output_handle_);
} else {
result = output_handle_;
}
}
output_handle_ = NULL;
if (ll_output_handle_ != NULL) fclose(ll_output_handle_);
ll_output_handle_ = NULL;
DeleteArray(message_buffer_);
message_buffer_ = NULL;
......@@ -280,27 +192,7 @@ void Log::Close() {
mutex_ = NULL;
is_stopped_ = false;
}
int Log::GetLogLines(int from_pos, char* dest_buf, int max_size) {
if (write_to_file_) return 0;
ASSERT(output_buffer_ != NULL);
ASSERT(from_pos >= 0);
ASSERT(max_size >= 0);
int actual_size = output_buffer_->Read(from_pos, dest_buf, max_size);
ASSERT(actual_size <= max_size);
if (actual_size == 0) return 0;
// Find previous log line boundary.
char* end_pos = dest_buf + actual_size - 1;
while (end_pos >= dest_buf && *end_pos != '\n') --end_pos;
actual_size = static_cast<int>(end_pos - dest_buf + 1);
// If the assertion below is hit, it means that there was no line end
// found --- something wrong has happened.
ASSERT(actual_size > 0);
ASSERT(actual_size <= max_size);
return actual_size;
return result;
}
......@@ -409,9 +301,7 @@ void LogMessageBuilder::AppendStringPart(const char* str, int len) {
void LogMessageBuilder::WriteToLogFile() {
ASSERT(pos_ <= Log::kMessageBufferSize);
const int written = log_->write_to_file_ ?
log_->WriteToFile(log_->message_buffer_, pos_) :
log_->WriteToMemory(log_->message_buffer_, pos_);
const int written = log_->WriteToFile(log_->message_buffer_, pos_);
if (written != pos_) {
log_->stop();
log_->logger_->LogFailure();
......
......@@ -35,65 +35,9 @@ namespace internal {
class Logger;
// A memory buffer that increments its size as you write in it. Size
// is incremented with 'block_size' steps, never exceeding 'max_size'.
// During growth, memory contents are never copied. At the end of the
// buffer an amount of memory specified in 'seal_size' is reserved.
// When writing position reaches max_size - seal_size, buffer auto-seals
// itself with 'seal' and allows no further writes. Data pointed by
// 'seal' must be available during entire LogDynamicBuffer lifetime.
//
// An instance of this class is created dynamically by Log.
class LogDynamicBuffer {
public:
LogDynamicBuffer(
int block_size, int max_size, const char* seal, int seal_size);
~LogDynamicBuffer();
// Reads contents of the buffer starting from 'from_pos'. Upon
// return, 'dest_buf' is filled with the data. Actual amount of data
// filled is returned, it is <= 'buf_size'.
int Read(int from_pos, char* dest_buf, int buf_size);
// Writes 'data' to the buffer, making it larger if necessary. If
// data is too big to fit in the buffer, it doesn't get written at
// all. In that case, buffer auto-seals itself and stops to accept
// any incoming writes. Returns amount of data written (it is either
// 'data_size', or 0, if 'data' is too big).
int Write(const char* data, int data_size);
private:
void AllocateBlock(int index) {
blocks_[index] = NewArray<char>(block_size_);
}
int BlockIndex(int pos) const { return pos / block_size_; }
int BlocksCount() const { return BlockIndex(max_size_) + 1; }
int PosInBlock(int pos) const { return pos % block_size_; }
int Seal();
int WriteInternal(const char* data, int data_size);
const int block_size_;
const int max_size_;
const char* seal_;
const int seal_size_;
ScopedVector<char*> blocks_;
int write_pos_;
int block_index_;
int block_write_pos_;
bool is_sealed_;
};
// Functions and data for performing output of log messages.
class Log {
public:
// Performs process-wide initialization.
void Initialize();
......@@ -101,18 +45,21 @@ class Log {
void stop() { is_stopped_ = true; }
// Frees all resources acquired in Initialize and Open... functions.
void Close();
// See description in include/v8.h.
int GetLogLines(int from_pos, char* dest_buf, int max_size);
// When a temporary file is used for the log, returns its stream descriptor,
// leaving the file open.
FILE* Close();
// Returns whether logging is enabled.
bool IsEnabled() {
return !is_stopped_ && (output_handle_ != NULL || output_buffer_ != NULL);
return !is_stopped_ && output_handle_ != NULL;
}
// Size of buffer used for formatting log messages.
static const int kMessageBufferSize = v8::V8::kMinimumSizeForLogLinesBuffer;
static const int kMessageBufferSize = 2048;
// This mode is only used in tests, as temporary files are automatically
// deleted on close and thus can't be accessed afterwards.
static const char* kLogToTemporaryFile;
private:
explicit Log(Logger* logger);
......@@ -123,8 +70,8 @@ class Log {
// Opens file for logging.
void OpenFile(const char* name);
// Opens memory buffer for logging.
void OpenMemoryBuffer();
// Opens a temporary file for logging.
void OpenTemporaryFile();
// Implementation of writing to a log file.
int WriteToFile(const char* msg, int length) {
......@@ -136,38 +83,16 @@ class Log {
return length;
}
// Implementation of writing to a memory buffer.
int WriteToMemory(const char* msg, int length) {
ASSERT(output_buffer_ != NULL);
return output_buffer_->Write(msg, length);
}
bool write_to_file_;
// Whether logging is stopped (e.g. due to insufficient resources).
bool is_stopped_;
// When logging is active, either output_handle_ or output_buffer_ is used
// to store a pointer to log destination. If logging was opened via OpenStdout
// or OpenFile, then output_handle_ is used. If logging was opened
// via OpenMemoryBuffer, then output_buffer_ is used.
// mutex_ should be acquired before using output_handle_ or output_buffer_.
// When logging is active output_handle_ is used to store a pointer to log
// destination. mutex_ should be acquired before using output_handle_.
FILE* output_handle_;
// Used when low-level profiling is active.
FILE* ll_output_handle_;
LogDynamicBuffer* output_buffer_;
// Size of dynamic buffer block (and dynamic buffer initial size).
static const int kDynamicBufferBlockSize = 65536;
// Maximum size of dynamic buffer.
static const int kMaxDynamicBufferSize = 50 * 1024 * 1024;
// Message to "seal" dynamic buffer with.
static const char* const kDynamicBufferSeal;
// mutex_ is a Mutex used for enforcing exclusive
// access to the formatting buffer and the log file or log memory buffer.
Mutex* mutex_;
......
......@@ -1281,7 +1281,6 @@ void Logger::PauseProfiler() {
ticker_->Stop();
}
FLAG_log_code = false;
// Must be the same message as Log::kDynamicBufferSeal.
LOG(ISOLATE, UncheckedStringEvent("profiler", "pause"));
}
--logging_nesting_;
......@@ -1323,11 +1322,6 @@ bool Logger::IsProfilerSamplerActive() {
}
int Logger::GetLogLines(int from_pos, char* dest_buf, int max_size) {
return log_->GetLogLines(from_pos, dest_buf, max_size);
}
class EnumerateOptimizedFunctionsVisitor: public OptimizedFunctionVisitor {
public:
EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo>* sfis,
......@@ -1683,8 +1677,8 @@ void Logger::EnsureTickerStopped() {
}
void Logger::TearDown() {
if (!is_initialized_) return;
FILE* Logger::TearDown() {
if (!is_initialized_) return NULL;
is_initialized_ = false;
// Stop the profiler before closing the file.
......@@ -1700,7 +1694,7 @@ void Logger::TearDown() {
delete ticker_;
ticker_ = NULL;
log_->Close();
return log_->Close();
}
......
......@@ -157,7 +157,9 @@ class Logger {
Sampler* sampler();
// Frees resources acquired in Setup.
void TearDown();
// When a temporary file is used for the log, returns its stream descriptor,
// leaving the file open.
FILE* TearDown();
// Enable the computation of a sliding window of states.
void EnableSlidingStateWindow();
......@@ -279,10 +281,6 @@ class Logger {
void ResumeProfiler();
bool IsProfilerPaused();
// If logging is performed into a memory buffer, allows to
// retrieve previously written messages. See v8.h.
int GetLogLines(int from_pos, char* dest_buf, int max_size);
// Logs all compiled functions found in the heap.
void LogCompiledFunctions();
// Logs all accessor callbacks found in the heap.
......
......@@ -147,6 +147,11 @@ bool OS::Remove(const char* path) {
}
FILE* OS::OpenTemporaryFile() {
return tmpfile();
}
const char* const OS::LogFileOpenMode = "w";
......
......@@ -740,6 +740,24 @@ bool OS::Remove(const char* path) {
}
FILE* OS::OpenTemporaryFile() {
// tmpfile_s tries to use the root dir, don't use it.
char tempPathBuffer[MAX_PATH];
DWORD path_result = 0;
path_result = GetTempPath(MAX_PATH, tempPathBuffer);
if (path_result > MAX_PATH || path_result == 0) return NULL;
UINT name_result = 0;
char tempNameBuffer[MAX_PATH];
name_result = GetTempFileName(tempPathBuffer, "", 0, tempNameBuffer);
if (name_result == 0) return NULL;
FILE* result = FOpen(tempNameBuffer, "w+"); // Same mode as tmpfile uses.
if (result != NULL) {
Remove(tempNameBuffer); // Delete on close.
}
return result;
}
// Open log file in binary mode to avoid /n -> /r/n conversion.
const char* const OS::LogFileOpenMode = "wb";
......
......@@ -177,6 +177,9 @@ class OS {
static FILE* FOpen(const char* path, const char* mode);
static bool Remove(const char* path);
// Opens a temporary file, the file is auto removed on close.
static FILE* OpenTemporaryFile();
// Log file open mode is platform-dependent due to line ends issues.
static const char* const LogFileOpenMode;
......
......@@ -110,11 +110,11 @@ char* ReadLine(const char* prompt) {
}
char* ReadCharsFromFile(const char* filename,
char* ReadCharsFromFile(FILE* file,
int* size,
int extra_space,
bool verbose) {
FILE* file = OS::FOpen(filename, "rb");
bool verbose,
const char* filename) {
if (file == NULL || fseek(file, 0, SEEK_END) != 0) {
if (verbose) {
OS::PrintError("Cannot read from file %s.\n", filename);
......@@ -127,16 +127,26 @@ char* ReadCharsFromFile(const char* filename,
rewind(file);
char* result = NewArray<char>(*size + extra_space);
for (int i = 0; i < *size;) {
for (int i = 0; i < *size && feof(file) == 0;) {
int read = static_cast<int>(fread(&result[i], 1, *size - i, file));
if (read <= 0) {
if (read != (*size - i) && ferror(file) != 0) {
fclose(file);
DeleteArray(result);
return NULL;
}
i += read;
}
fclose(file);
return result;
}
char* ReadCharsFromFile(const char* filename,
int* size,
int extra_space,
bool verbose) {
FILE* file = OS::FOpen(filename, "rb");
char* result = ReadCharsFromFile(file, size, extra_space, verbose, filename);
if (file != NULL) fclose(file);
return result;
}
......@@ -147,18 +157,34 @@ byte* ReadBytes(const char* filename, int* size, bool verbose) {
}
static Vector<const char> SetVectorContents(char* chars,
int size,
bool* exists) {
if (!chars) {
*exists = false;
return Vector<const char>::empty();
}
chars[size] = '\0';
*exists = true;
return Vector<const char>(chars, size);
}
Vector<const char> ReadFile(const char* filename,
bool* exists,
bool verbose) {
int size;
char* result = ReadCharsFromFile(filename, &size, 1, verbose);
if (!result) {
*exists = false;
return Vector<const char>::empty();
}
result[size] = '\0';
*exists = true;
return Vector<const char>(result, size);
return SetVectorContents(result, size, exists);
}
Vector<const char> ReadFile(FILE* file,
bool* exists,
bool verbose) {
int size;
char* result = ReadCharsFromFile(file, &size, 1, verbose, "");
return SetVectorContents(result, size, exists);
}
......
......@@ -188,6 +188,9 @@ class AsciiStringAdapter: public v8::String::ExternalAsciiStringResource {
Vector<const char> ReadFile(const char* filename,
bool* exists,
bool verbose = true);
Vector<const char> ReadFile(FILE* file,
bool* exists,
bool verbose = true);
......
......@@ -65,7 +65,6 @@ SOURCES = {
'test-liveedit.cc',
'test-lock.cc',
'test-lockers.cc',
'test-log-utils.cc',
'test-log.cc',
'test-mark-compact.cc',
'test-parsing.cc',
......
......@@ -71,7 +71,6 @@
'test-lock.cc',
'test-lockers.cc',
'test-log.cc',
'test-log-utils.cc',
'test-mark-compact.cc',
'test-parsing.cc',
'test-profile-generator.cc',
......
// Copyright 2011 the V8 project authors. All rights reserved.
// Redistribution and use in source and binary forms, with or without
// modification, are permitted provided that the following conditions are
// met:
//
// * Redistributions of source code must retain the above copyright
// notice, this list of conditions and the following disclaimer.
// * Redistributions in binary form must reproduce the above
// copyright notice, this list of conditions and the following
// disclaimer in the documentation and/or other materials provided
// with the distribution.
// * Neither the name of Google Inc. nor the names of its
// contributors may be used to endorse or promote products derived
// from this software without specific prior written permission.
//
// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
// This is a supplementary file for test-log/EquivalenceOfLoggingAndTraversal.
function parseState(s) {
switch (s) {
case "": return Profile.CodeState.COMPILED;
case "~": return Profile.CodeState.OPTIMIZABLE;
case "*": return Profile.CodeState.OPTIMIZED;
}
throw new Error("unknown code state: " + s);
}
function LogProcessor() {
LogReader.call(this, {
'code-creation': {
parsers: [null, parseInt, parseInt, null, 'var-args'],
processor: this.processCodeCreation },
'code-move': { parsers: [parseInt, parseInt],
processor: this.processCodeMove },
'code-delete': { parsers: [parseInt],
processor: this.processCodeDelete },
'sfi-move': { parsers: [parseInt, parseInt],
processor: this.processFunctionMove },
'shared-library': null,
'profiler': null,
'tick': null });
this.profile = new Profile();
}
LogProcessor.prototype.__proto__ = LogReader.prototype;
LogProcessor.prototype.processCodeCreation = function(
type, start, size, name, maybe_func) {
if (type != "LazyCompile" && type != "Script" && type != "Function") return;
// Discard types to avoid discrepancies in "LazyCompile" vs. "Function".
type = "";
if (maybe_func.length) {
var funcAddr = parseInt(maybe_func[0]);
var state = parseState(maybe_func[1]);
this.profile.addFuncCode(type, name, start, size, funcAddr, state);
} else {
this.profile.addCode(type, name, start, size);
}
};
LogProcessor.prototype.processCodeMove = function(from, to) {
this.profile.moveCode(from, to);
};
LogProcessor.prototype.processCodeDelete = function(start) {
this.profile.deleteCode(start);
};
LogProcessor.prototype.processFunctionMove = function(from, to) {
this.profile.moveFunc(from, to);
};
function RunTest() {
// _log must be provided externally.
var log_lines = _log.split("\n");
var line, pos = 0, log_lines_length = log_lines.length;
if (log_lines_length < 2)
return "log_lines_length < 2";
var logging_processor = new LogProcessor();
for ( ; pos < log_lines_length; ++pos) {
line = log_lines[pos];
if (line === "test-logging-done,\"\"") {
++pos;
break;
}
logging_processor.processLogLine(line);
}
logging_processor.profile.cleanUpFuncEntries();
var logging_entries =
logging_processor.profile.codeMap_.getAllDynamicEntriesWithAddresses();
if (logging_entries.length === 0)
return "logging_entries.length === 0";
var traversal_processor = new LogProcessor();
for ( ; pos < log_lines_length; ++pos) {
line = log_lines[pos];
if (line === "test-traversal-done,\"\"") break;
traversal_processor.processLogLine(line);
}
var traversal_entries =
traversal_processor.profile.codeMap_.getAllDynamicEntriesWithAddresses();
if (traversal_entries.length === 0)
return "traversal_entries.length === 0";
function addressComparator(entryA, entryB) {
return entryA[0] < entryB[0] ? -1 : (entryA[0] > entryB[0] ? 1 : 0);
}
logging_entries.sort(addressComparator);
traversal_entries.sort(addressComparator);
function entityNamesEqual(entityA, entityB) {
if ("getRawName" in entityB &&
entityNamesEqual.builtins.indexOf(entityB.getRawName()) !== -1) {
return true;
}
if (entityNamesEqual.builtins.indexOf(entityB.getName()) !== -1) return true;
return entityA.getName() === entityB.getName();
}
entityNamesEqual.builtins =
["Boolean", "Function", "Number", "Object",
"Script", "String", "RegExp", "Date", "Error"];
function entitiesEqual(entityA, entityB) {
if (entityA === null && entityB !== null) return true;
if (entityA !== null && entityB === null) return false;
return entityA.size === entityB.size && entityNamesEqual(entityA, entityB);
}
var i = 0, j = 0, k = logging_entries.length, l = traversal_entries.length;
var comparison = [];
var equal = true;
// Do a merge-like comparison of entries. At the same address we expect to
// find the same entries. We skip builtins during log parsing, but compiled
// functions traversal may erroneously recognize them as functions, so we are
// expecting more functions in traversal vs. logging.
while (i < k && j < l) {
var entryA = logging_entries[i], entryB = traversal_entries[j];
var cmp = addressComparator(entryA, entryB);
var entityA = entryA[1], entityB = entryB[1];
var address = entryA[0];
if (cmp < 0) {
++i;
entityB = null;
} else if (cmp > 0) {
++j;
entityA = null;
address = entryB[0];
} else {
++i;
++j;
}
var entities_equal = entitiesEqual(entityA, entityB);
if (!entities_equal) equal = false;
comparison.push([entities_equal, address, entityA, entityB]);
}
if (i < k) equal = false;
while (i < k) {
var entryA = logging_entries[i++];
comparison.push([false, entryA[0], entryA[1], null]);
}
return [equal, comparison];
}
var result = RunTest();
if (typeof result !== "string") {
var out = [];
if (!result[0]) {
var comparison = result[1];
for (var i = 0, l = comparison.length; i < l; ++i) {
var c = comparison[i];
out.push((c[0] ? " " : "* ") +
c[1].toString(16) + " " +
(c[2] ? c[2] : "---") + " " +
(c[3] ? c[3] : "---"));
}
}
result[0] ? true : out.join("\n");
} else {
result;
}
// Copyright 2006-2009 the V8 project authors. All rights reserved.
//
// Tests of logging utilities from log-utils.h
#include "v8.h"
#include "log-utils.h"
#include "cctest.h"
using v8::internal::CStrVector;
using v8::internal::EmbeddedVector;
using v8::internal::LogDynamicBuffer;
using v8::internal::MutableCStrVector;
using v8::internal::ScopedVector;
using v8::internal::Vector;
using v8::internal::StrLength;
// Fills 'ref_buffer' with test data: a sequence of two-digit
// hex numbers: '0001020304...'. Then writes 'ref_buffer' contents to 'dynabuf'.
static void WriteData(LogDynamicBuffer* dynabuf, Vector<char>* ref_buffer) {
static const char kHex[] = "0123456789ABCDEF";
CHECK_GT(ref_buffer->length(), 0);
CHECK_GT(513, ref_buffer->length());
for (int i = 0, half_len = ref_buffer->length() >> 1; i < half_len; ++i) {
(*ref_buffer)[i << 1] = kHex[i >> 4];
(*ref_buffer)[(i << 1) + 1] = kHex[i & 15];
}
if (ref_buffer->length() & 1) {
ref_buffer->last() = kHex[ref_buffer->length() >> 5];
}
CHECK_EQ(ref_buffer->length(),
dynabuf->Write(ref_buffer->start(), ref_buffer->length()));
}
static int ReadData(
LogDynamicBuffer* dynabuf, int start_pos, i::Vector<char>* buffer) {
return dynabuf->Read(start_pos, buffer->start(), buffer->length());
}
// Helper function used by CHECK_EQ to compare Vectors. Templatized to
// accept both "char" and "const char" vector contents.
template <typename E, typename V>
static inline void CheckEqualsHelper(const char* file, int line,
const char* expected_source,
const Vector<E>& expected,
const char* value_source,
const Vector<V>& value) {
if (expected.length() != value.length()) {
V8_Fatal(file, line, "CHECK_EQ(%s, %s) failed\n"
"# Vectors lengths differ: %d expected, %d found\n"
"# Expected: %.*s\n"
"# Found: %.*s",
expected_source, value_source,
expected.length(), value.length(),
expected.length(), expected.start(),
value.length(), value.start());
}
if (strncmp(expected.start(), value.start(), expected.length()) != 0) {
V8_Fatal(file, line, "CHECK_EQ(%s, %s) failed\n"
"# Vectors contents differ:\n"
"# Expected: %.*s\n"
"# Found: %.*s",
expected_source, value_source,
expected.length(), expected.start(),
value.length(), value.start());
}
}
TEST(DynaBufSingleBlock) {
LogDynamicBuffer dynabuf(32, 32, "", 0);
EmbeddedVector<char, 32> ref_buf;
WriteData(&dynabuf, &ref_buf);
EmbeddedVector<char, 32> buf;
CHECK_EQ(32, dynabuf.Read(0, buf.start(), buf.length()));
CHECK_EQ(32, ReadData(&dynabuf, 0, &buf));
CHECK_EQ(ref_buf, buf);
// Verify that we can't read and write past the end.
CHECK_EQ(0, dynabuf.Read(32, buf.start(), buf.length()));
CHECK_EQ(0, dynabuf.Write(buf.start(), buf.length()));
}
TEST(DynaBufCrossBlocks) {
LogDynamicBuffer dynabuf(32, 128, "", 0);
EmbeddedVector<char, 48> ref_buf;
WriteData(&dynabuf, &ref_buf);
CHECK_EQ(48, dynabuf.Write(ref_buf.start(), ref_buf.length()));
// Verify that we can't write data when remaining buffer space isn't enough.
CHECK_EQ(0, dynabuf.Write(ref_buf.start(), ref_buf.length()));
EmbeddedVector<char, 48> buf;
CHECK_EQ(48, ReadData(&dynabuf, 0, &buf));
CHECK_EQ(ref_buf, buf);
CHECK_EQ(48, ReadData(&dynabuf, 48, &buf));
CHECK_EQ(ref_buf, buf);
CHECK_EQ(0, ReadData(&dynabuf, 48 * 2, &buf));
}
TEST(DynaBufReadTruncation) {
LogDynamicBuffer dynabuf(32, 128, "", 0);
EmbeddedVector<char, 128> ref_buf;
WriteData(&dynabuf, &ref_buf);
EmbeddedVector<char, 128> buf;
CHECK_EQ(128, ReadData(&dynabuf, 0, &buf));
CHECK_EQ(ref_buf, buf);
// Try to read near the end with a buffer larger than remaining data size.
EmbeddedVector<char, 48> tail_buf;
CHECK_EQ(32, ReadData(&dynabuf, 128 - 32, &tail_buf));
CHECK_EQ(ref_buf.SubVector(128 - 32, 128), tail_buf.SubVector(0, 32));
}
TEST(DynaBufSealing) {
const char* seal = "Sealed";
const int seal_size = StrLength(seal);
LogDynamicBuffer dynabuf(32, 128, seal, seal_size);
EmbeddedVector<char, 100> ref_buf;
WriteData(&dynabuf, &ref_buf);
// Try to write data that will not fit in the buffer.
CHECK_EQ(0, dynabuf.Write(ref_buf.start(), 128 - 100 - seal_size + 1));
// Now the buffer is sealed, writing of any amount of data is forbidden.
CHECK_EQ(0, dynabuf.Write(ref_buf.start(), 1));
EmbeddedVector<char, 100> buf;
CHECK_EQ(100, ReadData(&dynabuf, 0, &buf));
CHECK_EQ(ref_buf, buf);
// Check the seal.
EmbeddedVector<char, 50> seal_buf;
CHECK_EQ(seal_size, ReadData(&dynabuf, 100, &seal_buf));
CHECK_EQ(CStrVector(seal), seal_buf.SubVector(0, seal_size));
// Verify that there's no data beyond the seal.
CHECK_EQ(0, ReadData(&dynabuf, 100 + seal_size, &buf));
}
......@@ -13,6 +13,7 @@
#include "log.h"
#include "cpu-profiler.h"
#include "v8threads.h"
#include "v8utils.h"
#include "cctest.h"
#include "vm-state-inl.h"
......@@ -23,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;
}
......@@ -294,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)));
}
......@@ -381,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();
......@@ -529,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();
}
......@@ -579,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();
}
......@@ -623,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) {
......@@ -1006,84 +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);
}
}
......@@ -26,7 +26,8 @@
// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
// Load source code files from <project root>/tools.
// Files: tools/consarray.js tools/profile.js tools/profile_view.js
// Files: tools/codemap.js tools/consarray.js tools/profile.js
// Files: tools/profile_view.js
function createNode(name, time, opt_parent) {
......
......@@ -210,6 +210,14 @@ CodeMap.prototype.getAllDynamicEntries = function() {
};
/**
* Returns an array of pairs of all dynamic code entries and their addresses.
*/
CodeMap.prototype.getAllDynamicEntriesWithAddresses = function() {
return this.dynamics_.exportKeysAndValues();
};
/**
* Returns an array of all static code entries.
*/
......
......@@ -162,8 +162,16 @@ Profile.prototype.addFuncCode = function(
// Function object has been overwritten with a new one.
func.name = name;
}
var entry = new Profile.DynamicFuncCodeEntry(size, type, func, state);
this.codeMap_.addCode(start, entry);
var entry = this.codeMap_.findDynamicEntryByStartAddress(start);
if (entry) {
if (entry.size === size && entry.func === func) {
// Entry state has changed.
entry.state = state;
}
} else {
entry = new Profile.DynamicFuncCodeEntry(size, type, func, state);
this.codeMap_.addCode(start, entry);
}
return entry;
};
......@@ -373,6 +381,31 @@ Profile.prototype.getFlatProfile = function(opt_label) {
};
/**
* Cleans up function entries that are not referenced by code entries.
*/
Profile.prototype.cleanUpFuncEntries = function() {
var referencedFuncEntries = [];
var entries = this.codeMap_.getAllDynamicEntriesWithAddresses();
for (var i = 0, l = entries.length; i < l; ++i) {
if (entries[i][1].constructor === Profile.FunctionEntry) {
entries[i][1].used = false;
}
}
for (var i = 0, l = entries.length; i < l; ++i) {
if ("func" in entries[i][1]) {
entries[i][1].func.used = true;
}
}
for (var i = 0, l = entries.length; i < l; ++i) {
if (entries[i][1].constructor === Profile.FunctionEntry &&
!entries[i][1].used) {
this.codeMap_.deleteCode(entries[i][0]);
}
}
};
/**
* Creates a dynamic code entry.
*
......@@ -408,6 +441,11 @@ Profile.DynamicCodeEntry.prototype.isJSFunction = function() {
};
Profile.DynamicCodeEntry.prototype.toString = function() {
return this.getName() + ': ' + this.size.toString(16);
};
/**
* Creates a dynamic code entry.
*
......@@ -448,6 +486,11 @@ Profile.DynamicFuncCodeEntry.prototype.isJSFunction = function() {
};
Profile.DynamicFuncCodeEntry.prototype.toString = function() {
return this.getName() + ': ' + this.size.toString(16);
};
/**
* Creates a shared function object entry.
*
......@@ -473,6 +516,7 @@ Profile.FunctionEntry.prototype.getName = function() {
return name;
};
Profile.FunctionEntry.prototype.toString = CodeMap.CodeEntry.prototype.toString;
/**
* Constructs a call graph.
......
......@@ -190,6 +190,17 @@ SplayTree.prototype.findGreatestLessThan = function(key) {
};
/**
* @return {Array<*>} An array containing all the values of tree's nodes paired
* with keys.
*/
SplayTree.prototype.exportKeysAndValues = function() {
var result = [];
this.traverse_(function(node) { result.push([node.key, node.value]); });
return result;
};
/**
* @return {Array<*>} An array containing all the values of tree's nodes.
*/
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment