ll_prof: Reduce profiling hooks overhead from >400% to 25%.

src/log-utils.cc

 // Copyright 2009 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
@@ skipping 108 matching lines @@
   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),
     output_handle_(NULL),
-    output_code_handle_(NULL),
+    ll_output_handle_(NULL),
     output_buffer_(NULL),
     mutex_(NULL),
     message_buffer_(NULL),
     logger_(logger) {
 }
 
 
 static void AddIsolateIdIfNeeded(StringStream* stream) {
   Isolate* isolate = Isolate::Current();
   if (isolate->IsDefaultIsolate()) return;
@@ skipping 21 matching lines @@
   if (FLAG_prof) FLAG_log_code = true;
 
   // --prof_lazy controls --log-code, implies --noprof_auto.
   if (FLAG_prof_lazy) {
     FLAG_log_code = false;
     FLAG_prof_auto = false;
   }
 
   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;
 
   // 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  {
@@ skipping 44 matching lines @@
 }
 
 
 void Log::OpenStdout() {
   ASSERT(!IsEnabled());
   output_handle_ = stdout;
   write_to_file_ = true;
 }
 
 
-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) {
   ASSERT(!IsEnabled());
   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);
   }
 }
 
 
 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 (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;
   }
 
   DeleteArray(message_buffer_);
   message_buffer_ = NULL;
 
   delete mutex_;
   mutex_ = NULL;
@@ skipping 73 matching lines @@
   }
 }
 
 
 void LogMessageBuilder::AppendAddress(Address addr) {
   Append("0x%" V8PRIxPTR, 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)
     len = 0x1000;
   if (show_impl_info) {
     Append(str->IsAsciiRepresentation() ? 'a' : '2');
     if (StringShape(str).IsExternal())
       Append('e');
     if (StringShape(str).IsSymbol())
       Append('#');
@@ skipping 40 matching lines @@
   if (written != pos_) {
     log_->stop();
     log_->logger_->LogFailure();
   }
 }
 
 
 #endif  // ENABLE_LOGGING_AND_PROFILING
 
 } }  // namespace v8::internal