Revision: 7729
Author: [email protected]
Date: Fri Apr 29 09:06:25 2011
Log: ll_prof: Reduce profiling hooks overhead from >400% to 25%.
Switched to using binary low-level log instead of the textual log used
by the ticks processor. The binary log contains code-related events,
code object names, and their bodies. When writing to the log we ask
glibc to use a larger buffer. To avoid complex processing of the
snapshot log (which is still textual) the serializer emits final
snapshot position to code name mappings that can be quickly be read
without replaying the snapshot log. (This might be useful for the
ticks processor.)
Review URL: http://codereview.chromium.org/6904127
http://code.google.com/p/v8/source/detail?r=7729
Modified:
/branches/bleeding_edge/src/isolate.cc
/branches/bleeding_edge/src/log-utils.cc
/branches/bleeding_edge/src/log-utils.h
/branches/bleeding_edge/src/log.cc
/branches/bleeding_edge/src/log.h
/branches/bleeding_edge/src/utils.h
/branches/bleeding_edge/tools/ll_prof.py
=======================================
--- /branches/bleeding_edge/src/isolate.cc Tue Apr 26 06:53:19 2011
+++ /branches/bleeding_edge/src/isolate.cc Fri Apr 29 09:06:25 2011
@@ -818,7 +818,7 @@
// If we are deserializing, log non-function code objects and compiled
// functions found in the snapshot.
- if (des != NULL && FLAG_log_code) {
+ if (des != NULL && (FLAG_log_code || FLAG_ll_prof)) {
HandleScope scope;
LOG(this, LogCodeObjects());
LOG(this, LogCompiledFunctions());
=======================================
--- /branches/bleeding_edge/src/log-utils.cc Fri Mar 18 13:35:07 2011
+++ /branches/bleeding_edge/src/log-utils.cc Fri Apr 29 09:06:25 2011
@@ -126,7 +126,7 @@
: write_to_file_(false),
is_stopped_(false),
output_handle_(NULL),
- output_code_handle_(NULL),
+ ll_output_handle_(NULL),
output_buffer_(NULL),
mutex_(NULL),
message_buffer_(NULL),
@@ -168,7 +168,7 @@
bool start_logging = 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_log_regexp || FLAG_log_state_changes || FLAG_ll_prof;
bool open_log_file = start_logging || FLAG_prof_lazy;
@@ -233,7 +233,12 @@
}
-static const char kCodeLogExt[] = ".code";
+// Extension added to V8 log file name to get the low-level log name.
+static const char kLowLevelLogExt[] = ".ll";
+
+// File buffer size of the low-level log. We don't use the default to
+// minimize the associated overhead.
+static const int kLowLevelLogBufferSize = 2 * MB;
void Log::OpenFile(const char* name) {
@@ -241,14 +246,13 @@
output_handle_ = OS::FOpen(name, OS::LogFileOpenMode);
write_to_file_ = true;
if (FLAG_ll_prof) {
- // Open a file for logging the contents of code objects so that
- // they can be disassembled later.
- size_t name_len = strlen(name);
- ScopedVector<char> code_name(
- static_cast<int>(name_len + sizeof(kCodeLogExt)));
- memcpy(code_name.start(), name, name_len);
- memcpy(code_name.start() + name_len, kCodeLogExt, sizeof(kCodeLogExt));
- output_code_handle_ = OS::FOpen(code_name.start(),
OS::LogFileOpenMode);
+ // Open the low-level log file.
+ size_t len = strlen(name);
+ ScopedVector<char> ll_name(static_cast<int>(len +
sizeof(kLowLevelLogExt)));
+ memcpy(ll_name.start(), name, len);
+ memcpy(ll_name.start() + len, kLowLevelLogExt,
sizeof(kLowLevelLogExt));
+ ll_output_handle_ = OS::FOpen(ll_name.start(), OS::LogFileOpenMode);
+ setvbuf(ll_output_handle_, NULL, _IOFBF, kLowLevelLogBufferSize);
}
}
@@ -266,8 +270,8 @@
if (write_to_file_) {
if (output_handle_ != NULL) fclose(output_handle_);
output_handle_ = NULL;
- if (output_code_handle_ != NULL) fclose(output_code_handle_);
- output_code_handle_ = NULL;
+ if (ll_output_handle_ != NULL) fclose(ll_output_handle_);
+ ll_output_handle_ = NULL;
} else {
delete output_buffer_;
output_buffer_ = NULL;
@@ -361,6 +365,7 @@
void LogMessageBuilder::AppendDetailed(String* str, bool show_impl_info) {
+ if (str == NULL) return;
AssertNoAllocation no_heap_allocation; // Ensure string stay valid.
int len = str->length();
if (len > 0x1000)
=======================================
--- /branches/bleeding_edge/src/log-utils.h Fri Mar 18 13:35:07 2011
+++ /branches/bleeding_edge/src/log-utils.h Fri Apr 29 09:06:25 2011
@@ -154,8 +154,8 @@
// mutex_ should be acquired before using output_handle_ or
output_buffer_.
FILE* output_handle_;
- // Used when low-level profiling is active to save code object contents.
- FILE* output_code_handle_;
+ // Used when low-level profiling is active.
+ FILE* ll_output_handle_;
LogDynamicBuffer* output_buffer_;
=======================================
--- /branches/bleeding_edge/src/log.cc Thu Apr 28 10:49:55 2011
+++ /branches/bleeding_edge/src/log.cc Fri Apr 29 09:06:25 2011
@@ -332,12 +332,189 @@
overflow = Remove(&sample);
}
}
+
+
+// Low-level profiling event structures.
+
+struct LowLevelCodeCreateStruct {
+ static const char kTag = 'C';
+
+ int32_t name_size;
+ Address code_address;
+ int32_t code_size;
+};
+
+
+struct LowLevelCodeMoveStruct {
+ static const char kTag = 'M';
+
+ Address from_address;
+ Address to_address;
+};
+
+
+struct LowLevelCodeDeleteStruct {
+ static const char kTag = 'D';
+
+ Address address;
+};
+
+
+struct LowLevelSnapshotPositionStruct {
+ static const char kTag = 'P';
+
+ Address address;
+ int32_t position;
+};
+
+
+static const char kCodeMovingGCTag = 'G';
//
// Logger class implementation.
//
+class Logger::NameMap {
+ public:
+ NameMap() : impl_(&PointerEquals) {}
+
+ ~NameMap() {
+ for (HashMap::Entry* p = impl_.Start(); p != NULL; p = impl_.Next(p)) {
+ DeleteArray(static_cast<const char*>(p->value));
+ }
+ }
+
+ void Insert(Address code_address, const char* name, int name_size) {
+ HashMap::Entry* entry = FindOrCreateEntry(code_address);
+ if (entry->value == NULL) {
+ entry->value = CopyName(name, name_size);
+ }
+ }
+
+ const char* Lookup(Address code_address) {
+ HashMap::Entry* entry = FindEntry(code_address);
+ return (entry != NULL) ? static_cast<const char*>(entry->value) : NULL;
+ }
+
+ void Remove(Address code_address) {
+ HashMap::Entry* entry = FindEntry(code_address);
+ if (entry != NULL) DeleteArray(static_cast<const char*>(entry->value));
+ RemoveEntry(entry);
+ }
+
+ void Move(Address from, Address to) {
+ if (from == to) return;
+ HashMap::Entry* from_entry = FindEntry(from);
+ ASSERT(from_entry != NULL);
+ void* value = from_entry->value;
+ RemoveEntry(from_entry);
+ HashMap::Entry* to_entry = FindOrCreateEntry(to);
+ ASSERT(to_entry->value == NULL);
+ to_entry->value = value;
+ }
+
+ private:
+ static bool PointerEquals(void* lhs, void* rhs) {
+ return lhs == rhs;
+ }
+
+ static char* CopyName(const char* name, int name_size) {
+ char* result = NewArray<char>(name_size + 1);
+ for (int i = 0; i < name_size; ++i) {
+ char c = name[i];
+ if (c == '\0') c = ' ';
+ result[i] = c;
+ }
+ result[name_size] = '\0';
+ return result;
+ }
+
+ HashMap::Entry* FindOrCreateEntry(Address code_address) {
+ return impl_.Lookup(code_address, ComputePointerHash(code_address),
true);
+ }
+
+ HashMap::Entry* FindEntry(Address code_address) {
+ return impl_.Lookup(code_address, ComputePointerHash(code_address),
false);
+ }
+
+ void RemoveEntry(HashMap::Entry* entry) {
+ impl_.Remove(entry->key, entry->hash);
+ }
+
+ HashMap impl_;
+
+ DISALLOW_COPY_AND_ASSIGN(NameMap);
+};
+
+
+class Logger::NameBuffer {
+ public:
+ NameBuffer() { Reset(); }
+
+ void Reset() {
+ utf8_pos_ = 0;
+ }
+
+ void AppendString(String* str) {
+ if (str == NULL) return;
+ if (str->HasOnlyAsciiChars()) {
+ int utf8_length = Min(str->length(), kUtf8BufferSize - utf8_pos_);
+ String::WriteToFlat(str, utf8_buffer_ + utf8_pos_, 0, utf8_length);
+ utf8_pos_ += utf8_length;
+ return;
+ }
+ int uc16_length = Min(str->length(), kUc16BufferSize);
+ String::WriteToFlat(str, uc16_buffer_, 0, uc16_length);
+ for (int i = 0; i < uc16_length && utf8_pos_ < kUtf8BufferSize; ++i) {
+ uc16 c = uc16_buffer_[i];
+ if (c <= String::kMaxAsciiCharCodeU) {
+ utf8_buffer_[utf8_pos_++] = c;
+ } else {
+ int char_length = unibrow::Utf8::Length(c);
+ if (utf8_pos_ + char_length > kUtf8BufferSize) break;
+ unibrow::Utf8::Encode(utf8_buffer_ + utf8_pos_, c);
+ utf8_pos_ += char_length;
+ }
+ }
+ }
+
+ void AppendBytes(const char* bytes, int size) {
+ size = Min(size, kUtf8BufferSize - utf8_pos_);
+ memcpy(utf8_buffer_ + utf8_pos_, bytes, size);
+ utf8_pos_ += size;
+ }
+
+ void AppendBytes(const char* bytes) {
+ AppendBytes(bytes, StrLength(bytes));
+ }
+
+ void AppendByte(char c) {
+ if (utf8_pos_ >= kUtf8BufferSize) return;
+ utf8_buffer_[utf8_pos_++] = c;
+ }
+
+ void AppendInt(int n) {
+ Vector<char> buffer(utf8_buffer_ + utf8_pos_, kUtf8BufferSize -
utf8_pos_);
+ int size = OS::SNPrintF(buffer, "%d", n);
+ if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
+ utf8_pos_ += size;
+ }
+ }
+
+ const char* get() { return utf8_buffer_; }
+ int size() const { return utf8_pos_; }
+
+ private:
+ static const int kUtf8BufferSize = 512;
+ static const int kUc16BufferSize = 128;
+
+ int utf8_pos_;
+ char utf8_buffer_[kUtf8BufferSize];
+ uc16 uc16_buffer_[kUc16BufferSize];
+};
+
+
Logger::Logger()
: ticker_(NULL),
profiler_(NULL),
@@ -347,6 +524,8 @@
cpu_profiler_nesting_(0),
heap_profiler_nesting_(0),
log_(new Log(this)),
+ name_buffer_(new NameBuffer),
+ address_to_name_map_(NULL),
is_initialized_(false),
last_address_(NULL),
prev_sp_(NULL),
@@ -354,10 +533,14 @@
prev_to_(NULL),
prev_code_(NULL) {
}
+
Logger::~Logger() {
+ delete address_to_name_map_;
+ delete name_buffer_;
delete log_;
}
+
#define DECLARE_EVENT(ignore1, name) name,
static const char* const kLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
@@ -735,7 +918,20 @@
Code* code,
const char* comment) {
#ifdef ENABLE_LOGGING_AND_PROFILING
- if (!log_->IsEnabled() || !FLAG_log_code) return;
+ if (!log_->IsEnabled()) return;
+ if (FLAG_ll_prof || Serializer::enabled()) {
+ name_buffer_->Reset();
+ name_buffer_->AppendBytes(kLogEventsNames[tag]);
+ name_buffer_->AppendByte(':');
+ name_buffer_->AppendBytes(comment);
+ }
+ if (FLAG_ll_prof) {
+ LowLevelCodeCreateEvent(code, name_buffer_->get(),
name_buffer_->size());
+ }
+ if (Serializer::enabled()) {
+ RegisterSnapshotCodeName(code, name_buffer_->get(),
name_buffer_->size());
+ }
+ if (!FLAG_log_code) return;
LogMessageBuilder msg(this);
msg.Append("%s,%s,",
kLogEventsNames[CODE_CREATION_EVENT],
@@ -749,7 +945,6 @@
msg.Append(*p);
}
msg.Append('"');
- LowLevelCodeCreateEvent(code, &msg);
msg.Append('\n');
msg.WriteToLogFile();
#endif
@@ -760,13 +955,30 @@
Code* code,
String* name) {
#ifdef ENABLE_LOGGING_AND_PROFILING
- if (name != NULL) {
- SmartPointer<char> str =
- name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
- CodeCreateEvent(tag, code, *str);
- } else {
- CodeCreateEvent(tag, code, "");
- }
+ if (!log_->IsEnabled()) return;
+ if (FLAG_ll_prof || Serializer::enabled()) {
+ name_buffer_->Reset();
+ name_buffer_->AppendBytes(kLogEventsNames[tag]);
+ name_buffer_->AppendByte(':');
+ name_buffer_->AppendString(name);
+ }
+ if (FLAG_ll_prof) {
+ LowLevelCodeCreateEvent(code, name_buffer_->get(),
name_buffer_->size());
+ }
+ if (Serializer::enabled()) {
+ RegisterSnapshotCodeName(code, name_buffer_->get(),
name_buffer_->size());
+ }
+ if (!FLAG_log_code) return;
+ LogMessageBuilder msg(this);
+ msg.Append("%s,%s,",
+ kLogEventsNames[CODE_CREATION_EVENT],
+ kLogEventsNames[tag]);
+ msg.AppendAddress(code->address());
+ msg.Append(",%d,\"", code->ExecutableSize());
+ msg.AppendDetailed(name, false);
+ msg.Append('"');
+ msg.Append('\n');
+ msg.WriteToLogFile();
#endif
}
@@ -788,7 +1000,20 @@
SharedFunctionInfo* shared,
String* name) {
#ifdef ENABLE_LOGGING_AND_PROFILING
- if (!log_->IsEnabled() || !FLAG_log_code) return;
+ if (!log_->IsEnabled()) return;
+ if (FLAG_ll_prof || Serializer::enabled()) {
+ name_buffer_->Reset();
+ name_buffer_->AppendBytes(kLogEventsNames[tag]);
+ name_buffer_->AppendByte(':');
+ name_buffer_->AppendString(name);
+ }
+ if (FLAG_ll_prof) {
+ LowLevelCodeCreateEvent(code, name_buffer_->get(),
name_buffer_->size());
+ }
+ if (Serializer::enabled()) {
+ RegisterSnapshotCodeName(code, name_buffer_->get(),
name_buffer_->size());
+ }
+ if (!FLAG_log_code) return;
if (code == Isolate::Current()->builtins()->builtin(
Builtins::kLazyCompile))
return;
@@ -803,7 +1028,6 @@
msg.Append(",%d,\"%s\",", code->ExecutableSize(), *str);
msg.AppendAddress(shared->address());
msg.Append(",%s", ComputeMarker(code));
- LowLevelCodeCreateEvent(code, &msg);
msg.Append('\n');
msg.WriteToLogFile();
#endif
@@ -818,7 +1042,24 @@
SharedFunctionInfo* shared,
String* source, int line) {
#ifdef ENABLE_LOGGING_AND_PROFILING
- if (!log_->IsEnabled() || !FLAG_log_code) return;
+ if (!log_->IsEnabled()) return;
+ if (FLAG_ll_prof || Serializer::enabled()) {
+ name_buffer_->Reset();
+ name_buffer_->AppendBytes(kLogEventsNames[tag]);
+ name_buffer_->AppendByte(':');
+ name_buffer_->AppendString(shared->DebugName());
+ name_buffer_->AppendByte(' ');
+ name_buffer_->AppendString(source);
+ name_buffer_->AppendByte(':');
+ name_buffer_->AppendInt(line);
+ }
+ if (FLAG_ll_prof) {
+ LowLevelCodeCreateEvent(code, name_buffer_->get(),
name_buffer_->size());
+ }
+ if (Serializer::enabled()) {
+ RegisterSnapshotCodeName(code, name_buffer_->get(),
name_buffer_->size());
+ }
+ if (!FLAG_log_code) return;
LogMessageBuilder msg(this);
SmartPointer<char> name =
shared->DebugName()->ToCString(DISALLOW_NULLS,
ROBUST_STRING_TRAVERSAL);
@@ -835,7 +1076,6 @@
line);
msg.AppendAddress(shared->address());
msg.Append(",%s", ComputeMarker(code));
- LowLevelCodeCreateEvent(code, &msg);
msg.Append('\n');
msg.WriteToLogFile();
#endif
@@ -844,14 +1084,26 @@
void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int
args_count) {
#ifdef ENABLE_LOGGING_AND_PROFILING
- if (!log_->IsEnabled() || !FLAG_log_code) return;
+ if (!log_->IsEnabled()) return;
+ if (FLAG_ll_prof || Serializer::enabled()) {
+ name_buffer_->Reset();
+ name_buffer_->AppendBytes(kLogEventsNames[tag]);
+ name_buffer_->AppendByte(':');
+ name_buffer_->AppendInt(args_count);
+ }
+ if (FLAG_ll_prof) {
+ LowLevelCodeCreateEvent(code, name_buffer_->get(),
name_buffer_->size());
+ }
+ if (Serializer::enabled()) {
+ RegisterSnapshotCodeName(code, name_buffer_->get(),
name_buffer_->size());
+ }
+ if (!FLAG_log_code) return;
LogMessageBuilder msg(this);
msg.Append("%s,%s,",
kLogEventsNames[CODE_CREATION_EVENT],
kLogEventsNames[tag]);
msg.AppendAddress(code->address());
msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count);
- LowLevelCodeCreateEvent(code, &msg);
msg.Append('\n');
msg.WriteToLogFile();
#endif
@@ -860,10 +1112,8 @@
void Logger::CodeMovingGCEvent() {
#ifdef ENABLE_LOGGING_AND_PROFILING
- if (!log_->IsEnabled() || !FLAG_log_code || !FLAG_ll_prof) return;
- LogMessageBuilder msg(this);
- msg.Append("%s\n", kLogEventsNames[CODE_MOVING_GC]);
- msg.WriteToLogFile();
+ if (!log_->IsEnabled() || !FLAG_ll_prof) return;
+ LowLevelLogWriteBytes(&kCodeMovingGCTag, sizeof(kCodeMovingGCTag));
OS::SignalCodeMovingGC();
#endif
}
@@ -871,7 +1121,20 @@
void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
#ifdef ENABLE_LOGGING_AND_PROFILING
- if (!log_->IsEnabled() || !FLAG_log_code) return;
+ if (!log_->IsEnabled()) return;
+ if (FLAG_ll_prof || Serializer::enabled()) {
+ name_buffer_->Reset();
+ name_buffer_->AppendBytes(kLogEventsNames[REG_EXP_TAG]);
+ name_buffer_->AppendByte(':');
+ name_buffer_->AppendString(source);
+ }
+ if (FLAG_ll_prof) {
+ LowLevelCodeCreateEvent(code, name_buffer_->get(),
name_buffer_->size());
+ }
+ if (Serializer::enabled()) {
+ RegisterSnapshotCodeName(code, name_buffer_->get(),
name_buffer_->size());
+ }
+ if (!FLAG_log_code) return;
LogMessageBuilder msg(this);
msg.Append("%s,%s,",
kLogEventsNames[CODE_CREATION_EVENT],
@@ -880,7 +1143,6 @@
msg.Append(",%d,\"", code->ExecutableSize());
msg.AppendDetailed(source, false);
msg.Append('\"');
- LowLevelCodeCreateEvent(code, &msg);
msg.Append('\n');
msg.WriteToLogFile();
#endif
@@ -889,6 +1151,11 @@
void Logger::CodeMoveEvent(Address from, Address to) {
#ifdef ENABLE_LOGGING_AND_PROFILING
+ if (!log_->IsEnabled()) return;
+ if (FLAG_ll_prof) LowLevelCodeMoveEvent(from, to);
+ if (Serializer::enabled() && address_to_name_map_ != NULL) {
+ address_to_name_map_->Move(from, to);
+ }
MoveEventInternal(CODE_MOVE_EVENT, from, to);
#endif
}
@@ -896,6 +1163,11 @@
void Logger::CodeDeleteEvent(Address from) {
#ifdef ENABLE_LOGGING_AND_PROFILING
+ if (!log_->IsEnabled()) return;
+ if (FLAG_ll_prof) LowLevelCodeDeleteEvent(from);
+ if (Serializer::enabled() && address_to_name_map_ != NULL) {
+ address_to_name_map_->Remove(from);
+ }
DeleteEventInternal(CODE_DELETE_EVENT, from);
#endif
}
@@ -903,7 +1175,21 @@
void Logger::SnapshotPositionEvent(Address addr, int pos) {
#ifdef ENABLE_LOGGING_AND_PROFILING
- if (!log_->IsEnabled() || !FLAG_log_snapshot_positions) return;
+ if (!log_->IsEnabled()) return;
+ if (FLAG_ll_prof) LowLevelSnapshotPositionEvent(addr, pos);
+ if (Serializer::enabled() && address_to_name_map_ != NULL) {
+ const char* code_name = address_to_name_map_->Lookup(addr);
+ if (code_name == NULL) return; // Not a code object.
+ LogMessageBuilder msg(this);
+ msg.Append("%s,%d,\"", kLogEventsNames[SNAPSHOT_CODE_NAME_EVENT], pos);
+ for (const char* p = code_name; *p != '\0'; ++p) {
+ if (*p == '"') msg.Append('\\');
+ msg.Append(*p);
+ }
+ msg.Append("\"\n");
+ msg.WriteToLogFile();
+ }
+ if (!FLAG_log_snapshot_positions) return;
LogMessageBuilder msg(this);
msg.Append("%s,", kLogEventsNames[SNAPSHOT_POSITION_EVENT]);
msg.AppendAddress(addr);
@@ -1308,7 +1594,7 @@
void Logger::LogCodeObject(Object* object) {
- if (FLAG_log_code) {
+ if (FLAG_log_code || FLAG_ll_prof) {
Code* code_object = Code::cast(object);
LogEventsAndTags tag = Logger::STUB_TAG;
const char* description = "Unknown code from the snapshot";
@@ -1370,7 +1656,7 @@
void Logger::LogCodeInfo() {
#ifdef ENABLE_LOGGING_AND_PROFILING
- if (!log_->IsEnabled() || !FLAG_log_code || !FLAG_ll_prof) return;
+ if (!log_->IsEnabled() || !FLAG_ll_prof) return;
#if V8_TARGET_ARCH_IA32
const char arch[] = "ia32";
#elif V8_TARGET_ARCH_X64
@@ -1380,21 +1666,69 @@
#else
const char arch[] = "unknown";
#endif
- LogMessageBuilder msg(this);
- msg.Append("code-info,%s,%d\n", arch, Code::kHeaderSize);
- msg.WriteToLogFile();
+ LowLevelLogWriteBytes(arch, sizeof(arch));
#endif // ENABLE_LOGGING_AND_PROFILING
}
-void Logger::LowLevelCodeCreateEvent(Code* code, LogMessageBuilder* msg) {
- if (!FLAG_ll_prof || log_->output_code_handle_ == NULL) return;
- int pos = static_cast<int>(ftell(log_->output_code_handle_));
- size_t rv = fwrite(code->instruction_start(), 1,
code->instruction_size(),
- log_->output_code_handle_);
- ASSERT(static_cast<size_t>(code->instruction_size()) == rv);
+void Logger::RegisterSnapshotCodeName(Code* code,
+ const char* name,
+ int name_size) {
+ ASSERT(Serializer::enabled());
+ if (address_to_name_map_ == NULL) {
+ address_to_name_map_ = new NameMap;
+ }
+ address_to_name_map_->Insert(code->address(), name, name_size);
+}
+
+
+void Logger::LowLevelCodeCreateEvent(Code* code,
+ const char* name,
+ int name_size) {
+ if (log_->ll_output_handle_ == NULL) return;
+ LowLevelCodeCreateStruct event;
+ event.name_size = name_size;
+ event.code_address = code->instruction_start();
+ ASSERT(event.code_address == code->address() + Code::kHeaderSize);
+ event.code_size = code->instruction_size();
+ LowLevelLogWriteStruct(event);
+ LowLevelLogWriteBytes(name, name_size);
+ LowLevelLogWriteBytes(
+ reinterpret_cast<const char*>(code->instruction_start()),
+ code->instruction_size());
+}
+
+
+void Logger::LowLevelCodeMoveEvent(Address from, Address to) {
+ if (log_->ll_output_handle_ == NULL) return;
+ LowLevelCodeMoveStruct event;
+ event.from_address = from + Code::kHeaderSize;
+ event.to_address = to + Code::kHeaderSize;
+ LowLevelLogWriteStruct(event);
+}
+
+
+void Logger::LowLevelCodeDeleteEvent(Address from) {
+ if (log_->ll_output_handle_ == NULL) return;
+ LowLevelCodeDeleteStruct event;
+ event.address = from + Code::kHeaderSize;
+ LowLevelLogWriteStruct(event);
+}
+
+
+void Logger::LowLevelSnapshotPositionEvent(Address addr, int pos) {
+ if (log_->ll_output_handle_ == NULL) return;
+ LowLevelSnapshotPositionStruct event;
+ event.address = addr + Code::kHeaderSize;
+ event.position = pos;
+ LowLevelLogWriteStruct(event);
+}
+
+
+void Logger::LowLevelLogWriteBytes(const char* bytes, int size) {
+ size_t rv = fwrite(bytes, 1, size, log_->ll_output_handle_);
+ ASSERT(static_cast<size_t>(size) == rv);
USE(rv);
- msg->Append(",%d", pos);
}
@@ -1497,7 +1831,6 @@
// --ll-prof implies --log-code and --log-snapshot-positions.
if (FLAG_ll_prof) {
- FLAG_log_code = true;
FLAG_log_snapshot_positions = true;
}
@@ -1524,7 +1857,7 @@
bool start_logging = 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_log_regexp || FLAG_log_state_changes || FLAG_ll_prof;
if (start_logging) {
logging_nesting_ = 1;
=======================================
--- /branches/bleeding_edge/src/log.h Fri Mar 18 13:35:07 2011
+++ /branches/bleeding_edge/src/log.h Fri Apr 29 09:06:25 2011
@@ -69,11 +69,12 @@
// tick profiler requires code events, so --prof implies --log-code.
// Forward declarations.
-class Ticker;
+class HashMap;
+class LogMessageBuilder;
class Profiler;
class Semaphore;
class SlidingStateWindow;
-class LogMessageBuilder;
+class Ticker;
#undef LOG
#ifdef ENABLE_LOGGING_AND_PROFILING
@@ -95,6 +96,7 @@
V(CODE_MOVING_GC, "code-moving-gc") \
V(SHARED_FUNC_MOVE_EVENT, "sfi-move") \
V(SNAPSHOT_POSITION_EVENT, "snapshot-pos") \
+ V(SNAPSHOT_CODE_NAME_EVENT, "snapshot-code-name") \
V(TICK_EVENT, "tick") \
V(REPEAT_META_EVENT, "repeat") \
V(BUILTIN_TAG, "Builtin") \
@@ -300,6 +302,9 @@
void LogFailure();
private:
+ class NameBuffer;
+ class NameMap;
+
Logger();
~Logger();
@@ -326,8 +331,26 @@
// Emits general information about generated code.
void LogCodeInfo();
- // Handles code creation when low-level profiling is active.
- void LowLevelCodeCreateEvent(Code* code, LogMessageBuilder* msg);
+ void RegisterSnapshotCodeName(Code* code, const char* name, int
name_size);
+
+ // Low-level logging support.
+
+ void LowLevelCodeCreateEvent(Code* code, const char* name, int
name_size);
+
+ void LowLevelCodeMoveEvent(Address from, Address to);
+
+ void LowLevelCodeDeleteEvent(Address from);
+
+ void LowLevelSnapshotPositionEvent(Address addr, int pos);
+
+ void LowLevelLogWriteBytes(const char* bytes, int size);
+
+ template <typename T>
+ void LowLevelLogWriteStruct(const T& s) {
+ char tag = T::kTag;
+ LowLevelLogWriteBytes(reinterpret_cast<const char*>(&tag),
sizeof(tag));
+ LowLevelLogWriteBytes(reinterpret_cast<const char*>(&s), sizeof(s));
+ }
// Emits a profiler tick event. Used by the profiler thread.
void TickEvent(TickSample* sample, bool overflow);
@@ -379,6 +402,10 @@
Log* log_;
+ NameBuffer* name_buffer_;
+
+ NameMap* address_to_name_map_;
+
// Guards against multiple calls to TearDown() that can happen in some
tests.
// 'true' between Setup() and TearDown().
bool is_initialized_;
=======================================
--- /branches/bleeding_edge/src/utils.h Wed Apr 13 01:00:59 2011
+++ /branches/bleeding_edge/src/utils.h Fri Apr 29 09:06:25 2011
@@ -249,6 +249,12 @@
hash = hash ^ (hash >> 16);
return hash;
}
+
+
+static inline uint32_t ComputePointerHash(void* ptr) {
+ return ComputeIntegerHash(
+ static_cast<uint32_t>(reinterpret_cast<intptr_t>(ptr)));
+}
//
----------------------------------------------------------------------------
=======================================
--- /branches/bleeding_edge/tools/ll_prof.py Fri Mar 18 12:41:05 2011
+++ /branches/bleeding_edge/tools/ll_prof.py Fri Apr 29 09:06:25 2011
@@ -124,7 +124,7 @@
self.callee_ticks = collections.defaultdict(lambda: 0)
self.callee_ticks[callee] += 1
- def PrintAnnotated(self, code_info, options):
+ def PrintAnnotated(self, arch, options):
if self.self_ticks_map is None:
ticks_map = []
else:
@@ -135,7 +135,7 @@
ticks_offsets = [t[0] for t in ticks_map]
ticks_counts = [t[1] for t in ticks_map]
# Get a list of disassembled lines and their addresses.
- lines = self._GetDisasmLines(code_info, options)
+ lines = self._GetDisasmLines(arch, options)
if len(lines) == 0:
return
# Print annotated lines.
@@ -174,17 +174,17 @@
self.end_address - self.start_address,
self.origin)
- def _GetDisasmLines(self, code_info, options):
+ def _GetDisasmLines(self, arch, options):
if self.origin == JS_ORIGIN or self.origin == JS_SNAPSHOT_ORIGIN:
inplace = False
- filename = options.log + ".code"
+ filename = options.log + ".ll"
else:
inplace = True
filename = self.origin
return disasm.GetDisasmLines(filename,
self.origin_offset,
self.end_address - self.start_address,
- code_info.arch,
+ arch,
inplace)
@@ -304,76 +304,102 @@
self.header_size = header_size
-class CodeLogReader(object):
- """V8 code event log reader."""
-
- _CODE_INFO_RE = re.compile(
- r"code-info,([^,]+),(\d+)")
-
- _CODE_CREATE_RE = re.compile(
-
r"code-creation,([^,]+),(0x[a-f0-9]+),(\d+),\"(.*)\"(?:,(0x[a-f0-9]+),([~*])?)?(?:,(\d+))?")
-
- _CODE_MOVE_RE = re.compile(
- r"code-move,(0x[a-f0-9]+),(0x[a-f0-9]+)")
-
- _CODE_DELETE_RE = re.compile(
- r"code-delete,(0x[a-f0-9]+)")
-
- _SNAPSHOT_POS_RE = re.compile(
- r"snapshot-pos,(0x[a-f0-9]+),(\d+)")
-
- _CODE_MOVING_GC = "code-moving-gc"
-
- def __init__(self, log_name, code_map, is_snapshot,
snapshot_pos_to_name):
- self.log = open(log_name, "r")
+class SnapshotLogReader(object):
+ """V8 snapshot log reader."""
+
+ _SNAPSHOT_CODE_NAME_RE = re.compile(
+ r"snapshot-code-name,(\d+),\"(.*)\"")
+
+ def __init__(self, log_name):
+ self.log_name = log_name
+
+ def ReadNameMap(self):
+ log = open(self.log_name, "r")
+ try:
+ snapshot_pos_to_name = {}
+ for line in log:
+ match = SnapshotLogReader._SNAPSHOT_CODE_NAME_RE.match(line)
+ if match:
+ pos = int(match.group(1))
+ name = match.group(2)
+ snapshot_pos_to_name[pos] = name
+ finally:
+ log.close()
+ return snapshot_pos_to_name
+
+
+class LogReader(object):
+ """V8 low-level (binary) log reader."""
+
+ _ARCH_TO_POINTER_TYPE_MAP = {
+ "ia32": ctypes.c_uint32,
+ "arm": ctypes.c_uint32,
+ "x64": ctypes.c_uint64
+ }
+
+ _CODE_CREATE_TAG = "C"
+ _CODE_MOVE_TAG = "M"
+ _CODE_DELETE_TAG = "D"
+ _SNAPSHOT_POSITION_TAG = "P"
+ _CODE_MOVING_GC_TAG = "G"
+
+ def __init__(self, log_name, code_map, snapshot_pos_to_name):
+ self.log_file = open(log_name, "r")
+ self.log = mmap.mmap(self.log_file.fileno(), 0, mmap.MAP_PRIVATE)
+ self.log_pos = 0
self.code_map = code_map
- self.is_snapshot = is_snapshot
self.snapshot_pos_to_name = snapshot_pos_to_name
self.address_to_snapshot_name = {}
- def ReadCodeInfo(self):
- line = self.log.readline() or ""
- match = CodeLogReader._CODE_INFO_RE.match(line)
- assert match, "No code info in log"
- return CodeInfo(arch=match.group(1), header_size=int(match.group(2)))
-
- def ReadUpToGC(self, code_info):
- made_progress = False
- code_header_size = code_info.header_size
- while True:
- line = self.log.readline()
- if not line:
- return made_progress
- made_progress = True
-
- if line.startswith(CodeLogReader._CODE_MOVING_GC):
+ self.arch = self.log[:self.log.find("\0")]
+ self.log_pos += len(self.arch) + 1
+ assert self.arch in LogReader._ARCH_TO_POINTER_TYPE_MAP, \
+ "Unsupported architecture %s" % self.arch
+ pointer_type = LogReader._ARCH_TO_POINTER_TYPE_MAP[self.arch]
+
+ self.code_create_struct = LogReader._DefineStruct([
+ ("name_size", ctypes.c_int32),
+ ("code_address", pointer_type),
+ ("code_size", ctypes.c_int32)])
+
+ self.code_move_struct = LogReader._DefineStruct([
+ ("from_address", pointer_type),
+ ("to_address", pointer_type)])
+
+ self.code_delete_struct = LogReader._DefineStruct([
+ ("address", pointer_type)])
+
+ self.snapshot_position_struct = LogReader._DefineStruct([
+ ("address", pointer_type),
+ ("position", ctypes.c_int32)])
+
+ def ReadUpToGC(self):
+ while self.log_pos < self.log.size():
+ tag = self.log[self.log_pos]
+ self.log_pos += 1
+
+ if tag == LogReader._CODE_MOVING_GC_TAG:
self.address_to_snapshot_name.clear()
- return made_progress
-
- match = CodeLogReader._CODE_CREATE_RE.match(line)
- if match:
- start_address = int(match.group(2), 16) + code_header_size
- end_address = start_address + int(match.group(3)) -
code_header_size
+ return
+
+ if tag == LogReader._CODE_CREATE_TAG:
+ event = self.code_create_struct.from_buffer(self.log, self.log_pos)
+ self.log_pos += ctypes.sizeof(event)
+ start_address = event.code_address
+ end_address = start_address + event.code_size
if start_address in self.address_to_snapshot_name:
name = self.address_to_snapshot_name[start_address]
origin = JS_SNAPSHOT_ORIGIN
else:
- tag = match.group(1)
- optimization_status = match.group(6)
- func_name = match.group(4)
- if optimization_status:
- name = "%s:%s%s" % (tag, optimization_status, func_name)
- else:
- name = "%s:%s" % (tag, func_name)
+ name = self.log[self.log_pos:self.log_pos + event.name_size]
origin = JS_ORIGIN
- if self.is_snapshot:
- origin_offset = 0
- else:
- origin_offset = int(match.group(7))
+ self.log_pos += event.name_size
+ origin_offset = self.log_pos
+ self.log_pos += event.code_size
code = Code(name, start_address, end_address, origin,
origin_offset)
conficting_code = self.code_map.Find(start_address)
if conficting_code:
- CodeLogReader._HandleCodeConflict(conficting_code, code)
+ LogReader._HandleCodeConflict(conficting_code, code)
# TODO(vitalyr): this warning is too noisy because of our
# attempts to reconstruct code log from the snapshot.
# print >>sys.stderr, \
@@ -382,10 +408,11 @@
self.code_map.Add(code)
continue
- match = CodeLogReader._CODE_MOVE_RE.match(line)
- if match:
- old_start_address = int(match.group(1), 16) + code_header_size
- new_start_address = int(match.group(2), 16) + code_header_size
+ if tag == LogReader._CODE_MOVE_TAG:
+ event = self.code_move_struct.from_buffer(self.log, self.log_pos)
+ self.log_pos += ctypes.sizeof(event)
+ old_start_address = event.from_address
+ new_start_address = event.to_address
if old_start_address == new_start_address:
# Skip useless code move entries.
continue
@@ -402,9 +429,10 @@
self.code_map.Add(code)
continue
- match = CodeLogReader._CODE_DELETE_RE.match(line)
- if match:
- old_start_address = int(match.group(1), 16) + code_header_size
+ if tag == LogReader._CODE_DELETE_TAG:
+ event = self.code_delete_struct.from_buffer(self.log, self.log_pos)
+ self.log_pos += ctypes.sizeof(event)
+ old_start_address = event.address
code = self.code_map.Find(old_start_address)
if not code:
print >>sys.stderr, "Warning: Not found %x" % old_start_address
@@ -414,40 +442,36 @@
self.code_map.Remove(code)
continue
- match = CodeLogReader._SNAPSHOT_POS_RE.match(line)
- if match:
- start_address = int(match.group(1), 16) + code_header_size
- snapshot_pos = int(match.group(2))
- if self.is_snapshot:
- code = self.code_map.Find(start_address)
- if code:
- assert code.start_address == start_address, \
- "Inexact snapshot address %x for %s" % (start_address,
code)
- self.snapshot_pos_to_name[snapshot_pos] = code.name
- else:
- if snapshot_pos in self.snapshot_pos_to_name:
- self.address_to_snapshot_name[start_address] = \
- self.snapshot_pos_to_name[snapshot_pos]
+ if tag == LogReader._SNAPSHOT_POSITION_TAG:
+ event = self.snapshot_position_struct.from_buffer(self.log,
+ self.log_pos)
+ self.log_pos += ctypes.sizeof(event)
+ start_address = event.address
+ snapshot_pos = event.position
+ if snapshot_pos in self.snapshot_pos_to_name:
+ self.address_to_snapshot_name[start_address] = \
+ self.snapshot_pos_to_name[snapshot_pos]
+ continue
+
+ assert False, "Unknown tag %s" % tag
def Dispose(self):
self.log.close()
+ self.log_file.close()
+
+ @staticmethod
+ def _DefineStruct(fields):
+ class Struct(ctypes.Structure):
+ _fields_ = fields
+ return Struct
@staticmethod
def _HandleCodeConflict(old_code, new_code):
assert (old_code.start_address == new_code.start_address and
old_code.end_address == new_code.end_address), \
"Conficting code log entries %s and %s" % (old_code, new_code)
- CodeLogReader._UpdateNames(old_code, new_code)
-
- @staticmethod
- def _UpdateNames(old_code, new_code):
if old_code.name == new_code.name:
return
- # Kludge: there are code objects with custom names that don't
- # match their flags.
- misnamed_code = set(["Builtin:CpuFeatures::Probe"])
- if old_code.name in misnamed_code:
- return
# Code object may be shared by a few functions. Collect the full
# set of names.
old_code.AddName(new_code.name)
@@ -756,14 +780,14 @@
return True
-def PrintReport(code_map, library_repo, code_info, options):
+def PrintReport(code_map, library_repo, arch, options):
print "Ticks per symbol:"
used_code = [code for code in code_map.UsedCode()]
used_code.sort(key=lambda x: x.self_ticks, reverse=True)
for i, code in enumerate(used_code):
print "%10d %s [%s]" % (code.self_ticks, code.FullName(), code.origin)
if options.disasm_all or i < options.disasm_top:
- code.PrintAnnotated(code_info, options)
+ code.PrintAnnotated(arch, options)
print
print "Ticks per library:"
mmap_infos = [m for m in library_repo.infos]
@@ -825,11 +849,11 @@
if not options.quiet:
if options.snapshot:
- print "V8 logs: %s, %s, %s.code" % (options.snapshot_log,
- options.log,
- options.log)
+ print "V8 logs: %s, %s, %s.ll" % (options.snapshot_log,
+ options.log,
+ options.log)
else:
- print "V8 log: %s, %s.code (no snapshot)" % (options.log,
options.log)
+ print "V8 log: %s, %s.ll (no snapshot)" % (options.log, options.log)
print "Perf trace file: %s" % options.trace
# Stats.
@@ -840,30 +864,24 @@
mmap_time = 0
sample_time = 0
- # Initialize the log reader and get the code info.
- code_map = CodeMap()
+ # Process the snapshot log to fill the snapshot name map.
snapshot_name_map = {}
- log_reader = CodeLogReader(log_name=options.log,
- code_map=code_map,
- is_snapshot=False,
- snapshot_pos_to_name=snapshot_name_map)
- code_info = log_reader.ReadCodeInfo()
+ if options.snapshot:
+ snapshot_log_reader = SnapshotLogReader(log_name=options.snapshot_log)
+ snapshot_name_map = snapshot_log_reader.ReadNameMap()
+
+ # Initialize the log reader.
+ code_map = CodeMap()
+ log_reader = LogReader(log_name=options.log + ".ll",
+ code_map=code_map,
+ snapshot_pos_to_name=snapshot_name_map)
if not options.quiet:
- print "Generated code architecture: %s" % code_info.arch
+ print "Generated code architecture: %s" % log_reader.arch
print
- # Process the snapshot log to fill the snapshot name map.
- if options.snapshot:
- snapshot_log_reader = CodeLogReader(log_name=options.snapshot_log,
- code_map=CodeMap(),
- is_snapshot=True,
-
snapshot_pos_to_name=snapshot_name_map)
- while snapshot_log_reader.ReadUpToGC(code_info):
- pass
-
# Process the code and trace logs.
library_repo = LibraryRepo()
- log_reader.ReadUpToGC(code_info)
+ log_reader.ReadUpToGC()
trace_reader = TraceReader(options.trace)
while True:
header, offset = trace_reader.ReadEventHeader()
@@ -874,7 +892,7 @@
start = time.time()
mmap_info = trace_reader.ReadMmap(header, offset)
if mmap_info.filename == V8_GC_FAKE_MMAP:
- log_reader.ReadUpToGC(code_info)
+ log_reader.ReadUpToGC()
else:
library_repo.Load(mmap_info, code_map, options)
mmap_time += time.time() - start
@@ -901,7 +919,7 @@
if options.dot:
PrintDot(code_map, options)
else:
- PrintReport(code_map, library_repo, code_info, options)
+ PrintReport(code_map, library_repo, log_reader.arch, options)
if not options.quiet:
print
--
v8-dev mailing list
[email protected]
http://groups.google.com/group/v8-dev
