Current logger code is messy. It mixes together
authorloislo@chromium.org <loislo@chromium.org@ce2b1a6d-e550-0410-aec6-3dcde31c8c00>
Mon, 15 Jul 2013 11:35:39 +0000 (11:35 +0000)
committerloislo@chromium.org <loislo@chromium.org@ce2b1a6d-e550-0410-aec6-3dcde31c8c00>
Mon, 15 Jul 2013 11:35:39 +0000 (11:35 +0000)
four or even five different logging destinations.
I think we can extract the code related to a destination
into a separate class, do the same for the all destinations
and have four classes with more or less simple common logging
API

BUG=none
Meta-bug= https://code.google.com/p/chromium/issues/detail?id=260203

R=yangguo@chromium.org, yurys@chromium.org

Review URL: https://codereview.chromium.org/18259024

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

src/log-utils.cc
src/log-utils.h
src/log.cc
src/log.h

index a733b52..a6fa6be 100644 (file)
@@ -35,26 +35,19 @@ namespace internal {
 
 
 const char* const Log::kLogToTemporaryFile = "&";
+const char* const Log::kLogToConsole = "-";
 
 
 Log::Log(Logger* logger)
   : is_stopped_(false),
     output_handle_(NULL),
-    ll_output_handle_(NULL),
     mutex_(NULL),
     message_buffer_(NULL),
     logger_(logger) {
 }
 
 
-static void AddIsolateIdIfNeeded(StringStream* stream) {
-  Isolate* isolate = Isolate::Current();
-  if (isolate->IsDefaultIsolate()) return;
-  stream->Add("isolate-%p-", isolate);
-}
-
-
-void Log::Initialize() {
+void Log::Initialize(const char* log_file_name) {
   mutex_ = OS::CreateMutex();
   message_buffer_ = NewArray<char>(kMessageBufferSize);
 
@@ -81,55 +74,12 @@ void Log::Initialize() {
 
   // If we're logging anything, we need to open the log file.
   if (Log::InitLogAtStart()) {
-    if (strcmp(FLAG_logfile, "-") == 0) {
+    if (strcmp(log_file_name, kLogToConsole) == 0) {
       OpenStdout();
-    } else if (strcmp(FLAG_logfile, kLogToTemporaryFile) == 0) {
+    } else if (strcmp(log_file_name, 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
-        // placeholders.
-        HeapStringAllocator allocator;
-        StringStream stream(&allocator);
-        AddIsolateIdIfNeeded(&stream);
-        for (const char* p = FLAG_logfile; *p; p++) {
-          if (*p == '%') {
-            p++;
-            switch (*p) {
-              case '\0':
-                // If there's a % at the end of the string we back up
-                // one character so we can escape the loop properly.
-                p--;
-                break;
-              case 'p':
-                stream.Add("%d", OS::GetCurrentProcessId());
-                break;
-              case 't': {
-                // %t expands to the current time in milliseconds.
-                double time = OS::TimeCurrentMillis();
-                stream.Add("%.0f", FmtElm(time));
-                break;
-              }
-              case '%':
-                // %% expands (contracts really) to %.
-                stream.Put('%');
-                break;
-              default:
-                // All other %'s expand to themselves.
-                stream.Put('%');
-                stream.Put(*p);
-                break;
-            }
-          } else {
-            stream.Put(*p);
-          }
-        }
-        SmartArrayPointer<const char> expanded = stream.ToCString();
-        OpenFile(*expanded);
-      } else {
-        OpenFile(FLAG_logfile);
-      }
+      OpenFile(log_file_name);
     }
   }
 }
@@ -147,27 +97,9 @@ void Log::OpenTemporaryFile() {
 }
 
 
-// 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);
-  if (FLAG_ll_prof) {
-    // Open the low-level log file.
-    size_t len = strlen(name);
-    ScopedVector<char> ll_name(static_cast<int>(len + sizeof(kLowLevelLogExt)));
-    OS::MemCopy(ll_name.start(), name, len);
-    OS::MemCopy(ll_name.start() + len,
-                kLowLevelLogExt, sizeof(kLowLevelLogExt));
-    ll_output_handle_ = OS::FOpen(ll_name.start(), OS::LogFileOpenMode);
-    setvbuf(ll_output_handle_, NULL, _IOFBF, kLowLevelLogBufferSize);
-  }
 }
 
 
@@ -181,8 +113,6 @@ FILE* Log::Close() {
     }
   }
   output_handle_ = NULL;
-  if (ll_output_handle_ != NULL) fclose(ll_output_handle_);
-  ll_output_handle_ = NULL;
 
   DeleteArray(message_buffer_);
   message_buffer_ = NULL;
index c499540..c0b863f 100644 (file)
@@ -39,7 +39,7 @@ class Logger;
 class Log {
  public:
   // Performs process-wide initialization.
-  void Initialize();
+  void Initialize(const char* log_file_name);
 
   // Disables logging, but preserves acquired resources.
   void stop() { is_stopped_ = true; }
@@ -66,6 +66,7 @@ class Log {
   // 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* const kLogToTemporaryFile;
+  static const char* const kLogToConsole;
 
  private:
   explicit Log(Logger* logger);
@@ -96,9 +97,6 @@ class Log {
   // destination.  mutex_ should be acquired before using output_handle_.
   FILE* output_handle_;
 
-  // Used when low-level profiling is active.
-  FILE* ll_output_handle_;
-
   // mutex_ is a Mutex used for enforcing exclusive
   // access to the formatting buffer and the log file or log memory buffer.
   Mutex* mutex_;
index a44add6..843d128 100644 (file)
 namespace v8 {
 namespace internal {
 
+
+// Low-level logging support.
+class LowLevelLogger {
+ public:
+  explicit LowLevelLogger(const char* file_name);
+  ~LowLevelLogger();
+
+  void CodeCreateEvent(Code* code, const char* name, int name_size);
+  void CodeMoveEvent(Address from, Address to);
+  void CodeDeleteEvent(Address from);
+  void SnapshotPositionEvent(Address addr, int pos);
+  void CodeMovingGCEvent();
+
+ private:
+  // Low-level profiling event structures.
+
+  struct CodeCreateStruct {
+    static const char kTag = 'C';
+
+    int32_t name_size;
+    Address code_address;
+    int32_t code_size;
+  };
+
+
+  struct CodeMoveStruct {
+    static const char kTag = 'M';
+
+    Address from_address;
+    Address to_address;
+  };
+
+
+  struct CodeDeleteStruct {
+    static const char kTag = 'D';
+
+    Address address;
+  };
+
+
+  struct SnapshotPositionStruct {
+    static const char kTag = 'P';
+
+    Address address;
+    int32_t position;
+  };
+
+
+  static const char kCodeMovingGCTag = 'G';
+
+
+  // Extension added to V8 log file name to get the low-level log name.
+  static const char kLogExt[];
+
+  // File buffer size of the low-level log. We don't use the default to
+  // minimize the associated overhead.
+  static const int kLogBufferSize = 2 * MB;
+
+  void LogCodeInfo();
+  void LogWriteBytes(const char* bytes, int size);
+
+  template <typename T>
+  void LogWriteStruct(const T& s) {
+    char tag = T::kTag;
+    LogWriteBytes(reinterpret_cast<const char*>(&tag), sizeof(tag));
+    LogWriteBytes(reinterpret_cast<const char*>(&s), sizeof(s));
+  }
+
+  FILE* ll_output_handle_;
+};
+
+const char LowLevelLogger::kLogExt[] = ".ll";
+
+#define LL_LOG(Call) if (ll_logger_) ll_logger_->Call;
+
+
 // The Profiler samples pc and sp values for the main thread.
 // Each sample is appended to a circular buffer.
 // An independent thread removes data and writes it to the log.
@@ -210,43 +286,6 @@ void Profiler::Run() {
 }
 
 
-// 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.
 //
@@ -405,6 +444,7 @@ Logger::Logger(Isolate* isolate)
     logging_nesting_(0),
     cpu_profiler_nesting_(0),
     log_(new Log(this)),
+    ll_logger_(NULL),
     name_buffer_(new NameBuffer),
     address_to_name_map_(NULL),
     is_initialized_(false),
@@ -952,9 +992,7 @@ void Logger::LogRecordedBuffer(Code* code, SharedFunctionInfo* shared) {
                         name_buffer_->size());
   }
   if (!log_->IsEnabled()) return;
-  if (FLAG_ll_prof) {
-    LowLevelCodeCreateEvent(code, name_buffer_->get(), name_buffer_->size());
-  }
+  LL_LOG(CodeCreateEvent(code, name_buffer_->get(), name_buffer_->size()));
   if (Serializer::enabled()) {
     RegisterSnapshotCodeName(code, name_buffer_->get(), name_buffer_->size());
   }
@@ -1142,7 +1180,7 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
 
 void Logger::CodeMovingGCEvent() {
   if (!log_->IsEnabled() || !FLAG_ll_prof) return;
-  LowLevelLogWriteBytes(&kCodeMovingGCTag, sizeof(kCodeMovingGCTag));
+  LL_LOG(CodeMovingGCEvent());
   OS::SignalCodeMovingGC();
 }
 
@@ -1169,7 +1207,7 @@ void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
 void Logger::CodeMoveEvent(Address from, Address to) {
   if (code_event_handler_ != NULL) IssueCodeMovedEvent(from, to);
   if (!log_->IsEnabled()) return;
-  if (FLAG_ll_prof) LowLevelCodeMoveEvent(from, to);
+  LL_LOG(CodeMoveEvent(from, to));
   if (Serializer::enabled() && address_to_name_map_ != NULL) {
     address_to_name_map_->Move(from, to);
   }
@@ -1180,7 +1218,7 @@ void Logger::CodeMoveEvent(Address from, Address to) {
 void Logger::CodeDeleteEvent(Address from) {
   if (code_event_handler_ != NULL) IssueCodeRemovedEvent(from);
   if (!log_->IsEnabled()) return;
-  if (FLAG_ll_prof) LowLevelCodeDeleteEvent(from);
+  LL_LOG(CodeDeleteEvent(from));
   if (Serializer::enabled() && address_to_name_map_ != NULL) {
     address_to_name_map_->Remove(from);
   }
@@ -1226,7 +1264,7 @@ void Logger::CodeEndLinePosInfoRecordEvent(Code* code,
 
 void Logger::SnapshotPositionEvent(Address addr, int pos) {
   if (!log_->IsEnabled()) return;
-  if (FLAG_ll_prof) LowLevelSnapshotPositionEvent(addr, pos);
+  LL_LOG(SnapshotPositionEvent(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.
@@ -1564,8 +1602,38 @@ void Logger::LogCodeObject(Object* object) {
 }
 
 
-void Logger::LogCodeInfo() {
-  if (!log_->IsEnabled() || !FLAG_ll_prof) return;
+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);
+}
+
+
+LowLevelLogger::LowLevelLogger(const char* name)
+    : ll_output_handle_(NULL) {
+  // Open the low-level log file.
+  size_t len = strlen(name);
+  ScopedVector<char> ll_name(static_cast<int>(len + sizeof(kLogExt)));
+  OS::MemCopy(ll_name.start(), name, len);
+  OS::MemCopy(ll_name.start() + len, kLogExt, sizeof(kLogExt));
+  ll_output_handle_ = OS::FOpen(ll_name.start(), OS::LogFileOpenMode);
+  setvbuf(ll_output_handle_, NULL, _IOFBF, kLogBufferSize);
+
+  LogCodeInfo();
+}
+
+
+LowLevelLogger::~LowLevelLogger() {
+  fclose(ll_output_handle_);
+  ll_output_handle_ = NULL;
+}
+
+
+void LowLevelLogger::LogCodeInfo() {
 #if V8_TARGET_ARCH_IA32
   const char arch[] = "ia32";
 #elif V8_TARGET_ARCH_X64
@@ -1577,71 +1645,62 @@ void Logger::LogCodeInfo() {
 #else
   const char arch[] = "unknown";
 #endif
-  LowLevelLogWriteBytes(arch, sizeof(arch));
-}
-
-
-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);
+  LogWriteBytes(arch, sizeof(arch));
 }
 
-
-void Logger::LowLevelCodeCreateEvent(Code* code,
+void LowLevelLogger::CodeCreateEvent(Code* code,
                                      const char* name,
                                      int name_size) {
-  if (log_->ll_output_handle_ == NULL) return;
-  LowLevelCodeCreateStruct event;
+  CodeCreateStruct 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(
+  LogWriteStruct(event);
+  LogWriteBytes(name, name_size);
+  LogWriteBytes(
       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;
+void LowLevelLogger::CodeMoveEvent(Address from, Address to) {
+  CodeMoveStruct event;
   event.from_address = from + Code::kHeaderSize;
   event.to_address = to + Code::kHeaderSize;
-  LowLevelLogWriteStruct(event);
+  LogWriteStruct(event);
 }
 
 
-void Logger::LowLevelCodeDeleteEvent(Address from) {
-  if (log_->ll_output_handle_ == NULL) return;
-  LowLevelCodeDeleteStruct event;
+void LowLevelLogger::CodeDeleteEvent(Address from) {
+  CodeDeleteStruct event;
   event.address = from + Code::kHeaderSize;
-  LowLevelLogWriteStruct(event);
+  LogWriteStruct(event);
 }
 
 
-void Logger::LowLevelSnapshotPositionEvent(Address addr, int pos) {
-  if (log_->ll_output_handle_ == NULL) return;
-  LowLevelSnapshotPositionStruct event;
+void LowLevelLogger::SnapshotPositionEvent(Address addr, int pos) {
+  SnapshotPositionStruct event;
   event.address = addr + Code::kHeaderSize;
   event.position = pos;
-  LowLevelLogWriteStruct(event);
+  LogWriteStruct(event);
 }
 
 
-void Logger::LowLevelLogWriteBytes(const char* bytes, int size) {
-  size_t rv = fwrite(bytes, 1, size, log_->ll_output_handle_);
+void LowLevelLogger::LogWriteBytes(const char* bytes, int size) {
+  size_t rv = fwrite(bytes, 1, size, ll_output_handle_);
   ASSERT(static_cast<size_t>(size) == rv);
   USE(rv);
 }
 
 
+void LowLevelLogger::CodeMovingGCEvent() {
+  const char tag = kCodeMovingGCTag;
+
+  LogWriteBytes(&tag, sizeof(tag));
+}
+
+
 void Logger::LogCodeObjects() {
   Heap* heap = isolate_->heap();
   heap->CollectAllGarbage(Heap::kMakeHeapIterableMask,
@@ -1744,6 +1803,63 @@ void Logger::LogAccessorCallbacks() {
 }
 
 
+static void AddIsolateIdIfNeeded(StringStream* stream) {
+  Isolate* isolate = Isolate::Current();
+  if (isolate->IsDefaultIsolate()) return;
+  stream->Add("isolate-%p-", isolate);
+}
+
+
+static SmartArrayPointer<const char> PrepareLogFileName(const char* file_name) {
+  if (strchr(file_name, '%') != NULL ||
+      !Isolate::Current()->IsDefaultIsolate()) {
+    // If there's a '%' in the log file name we have to expand
+    // placeholders.
+    HeapStringAllocator allocator;
+    StringStream stream(&allocator);
+    AddIsolateIdIfNeeded(&stream);
+    for (const char* p = file_name; *p; p++) {
+      if (*p == '%') {
+        p++;
+        switch (*p) {
+          case '\0':
+            // If there's a % at the end of the string we back up
+            // one character so we can escape the loop properly.
+            p--;
+            break;
+          case 'p':
+            stream.Add("%d", OS::GetCurrentProcessId());
+            break;
+          case 't': {
+            // %t expands to the current time in milliseconds.
+            double time = OS::TimeCurrentMillis();
+            stream.Add("%.0f", FmtElm(time));
+            break;
+          }
+          case '%':
+            // %% expands (contracts really) to %.
+            stream.Put('%');
+            break;
+          default:
+            // All other %'s expand to themselves.
+            stream.Put('%');
+            stream.Put(*p);
+            break;
+        }
+      } else {
+        stream.Put(*p);
+      }
+    }
+    return SmartArrayPointer<const char>(stream.ToCString());
+  }
+  int length = StrLength(file_name);
+  char* str = NewArray<char>(length + 1);
+  OS::MemCopy(str, file_name, length);
+  str[length] = '\0';
+  return SmartArrayPointer<const char>(str);
+}
+
+
 bool Logger::SetUp(Isolate* isolate) {
   // Tests and EnsureInitialize() can call this twice in a row. It's harmless.
   if (is_initialized_) return true;
@@ -1760,9 +1876,13 @@ bool Logger::SetUp(Isolate* isolate) {
     FLAG_prof_auto = false;
   }
 
-  log_->Initialize();
+  SmartArrayPointer<const char> log_file_name =
+      PrepareLogFileName(FLAG_logfile);
+  log_->Initialize(*log_file_name);
 
-  if (FLAG_ll_prof) LogCodeInfo();
+  if (FLAG_ll_prof) {
+    ll_logger_ = new LowLevelLogger(*log_file_name);
+  }
 
   ticker_ = new Ticker(isolate, kSamplingIntervalMs);
 
@@ -1819,6 +1939,11 @@ FILE* Logger::TearDown() {
   delete ticker_;
   ticker_ = NULL;
 
+  if (ll_logger_) {
+    delete ll_logger_;
+    ll_logger_ = NULL;
+  }
+
   return log_->Close();
 }
 
index 07ecd0e..bb3dbd5 100644 (file)
--- a/src/log.h
+++ b/src/log.h
@@ -151,6 +151,7 @@ class CompilationInfo;
 // original tags when writing to the log.
 
 
+class LowLevelLogger;
 class Sampler;
 
 
@@ -430,30 +431,8 @@ class Logger {
   // Appends symbol for the name.
   void AppendSymbolName(LogMessageBuilder*, Symbol*);
 
-  // Emits general information about generated code.
-  void LogCodeInfo();
-
   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);
 
@@ -495,6 +474,7 @@ class Logger {
   int cpu_profiler_nesting_;
 
   Log* log_;
+  LowLevelLogger* ll_logger_;
 
   NameBuffer* name_buffer_;