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

git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@7729 ce2b1a6d-e550-0410-aec6-3dcde31c8c00

src/isolate.cc

@@ -818,7 +818,7 @@ bool Isolate::Init(Deserializer* des) {
 
   // 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());

src/log-utils.cc

@@ -126,7 +126,7 @@ Log::Log(Logger* logger)
   : 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 @@ void Log::Initialize() {
 
   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 @@ void Log::OpenStdout() {
 }
 
 
-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 @@ void Log::OpenFile(const char* name) {
   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 @@ void Log::Close() {
   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::AppendAddress(Address addr) {
 
 
 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)

src/log-utils.h

@@ -154,8 +154,8 @@ class Log {
   // 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_;
 

src/log.h

@@ -69,11 +69,12 @@ namespace internal {
 // 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 @@ class LogMessageBuilder;
   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 @@ class Logger {
   void LogFailure();
 
  private:
+  class NameBuffer;
+  class NameMap;
+
   Logger();
   ~Logger();
 
@@ -326,8 +331,26 @@ class Logger {
   // 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 @@ class Logger {
 
   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_;

src/utils.h

@@ -251,6 +251,12 @@ static inline uint32_t ComputeIntegerHash(uint32_t key) {
 }
 
 
+static inline uint32_t ComputePointerHash(void* ptr) {
+  return ComputeIntegerHash(
+      static_cast<uint32_t>(reinterpret_cast<intptr_t>(ptr)));
+}
+
+
 // ----------------------------------------------------------------------------
 // Miscellaneous