Logger: extract low level logging code into a separate class.

src/log.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
@@ skipping 27 matching lines @@
 #include "macro-assembler.h"
 #include "platform.h"
 #include "runtime-profiler.h"
 #include "serialize.h"
 #include "string-stream.h"
 #include "vm-state-inl.h"
 
 namespace v8 {
 namespace internal {
 
+
+// Low-level logging support.
+class LowLevelLogger {
+ public:

[yurys, 2013/07/15 04:16:35]

Consider moving this class and logic related to the correpoding log file into
its own file.

[loislo, 2013/07/15 07:37:00]

I'd like to do that as a separate change.

+  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.
 // This design minimizes the time spent in the sampler.
 //
 class Profiler: public Thread {
  public:
   explicit Profiler(Isolate* isolate);
   void Engage();
   void Disengage();
@@ skipping 145 matching lines @@
 void Profiler::Run() {
   TickSample sample;
   bool overflow = Remove(&sample);
   while (running_) {
     LOG(isolate_, TickEvent(&sample, overflow));
     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)) {
@@ skipping 138 matching lines @@
 
 
 Logger::Logger(Isolate* isolate)
   : isolate_(isolate),
     ticker_(NULL),
     profiler_(NULL),
     log_events_(NULL),
     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),
     code_event_handler_(NULL),
     last_address_(NULL),
     prev_sp_(NULL),
     prev_function_(NULL),
     prev_to_(NULL),
     prev_code_(NULL),
     epoch_(0) {
@@ skipping 527 matching lines @@
 void Logger::LogRecordedBuffer(Code* code, SharedFunctionInfo* shared) {
   if (code_event_handler_ != NULL) {
     Script* script = shared && shared->script()->IsScript() ?
         Script::cast(shared->script()) : NULL;
     IssueCodeAddedEvent(code,
                         script,
                         name_buffer_->get(),
                         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());
   }
 }
 
 
 void Logger::AppendCodeCreateHeader(LogMessageBuilder* msg,
                                     LogEventsAndTags tag,
                                     Code* code) {
   ASSERT(msg);
@@ skipping 167 matching lines @@
   LogMessageBuilder msg(this);
   AppendCodeCreateHeader(&msg, tag, code);
   msg.Append("\"args_count: %d\"", args_count);
   msg.Append('\n');
   msg.WriteToLogFile();
 }
 
 
 void Logger::CodeMovingGCEvent() {
   if (!log_->IsEnabled() || !FLAG_ll_prof) return;
-  LowLevelLogWriteBytes(&kCodeMovingGCTag, sizeof(kCodeMovingGCTag));
+  LL_LOG(CodeMovingGCEvent());
   OS::SignalCodeMovingGC();
 }
 
 
 void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
   if (!is_logging_code_events()) return;
   if (FLAG_ll_prof || Serializer::enabled() || code_event_handler_ != NULL) {
     InitNameBuffer(REG_EXP_TAG);
     name_buffer_->AppendString(source);
     LogRecordedBuffer(code, NULL);
   }
 
   if (!FLAG_log_code || !log_->IsEnabled()) return;
   LogMessageBuilder msg(this);
   AppendCodeCreateHeader(&msg, REG_EXP_TAG, code);
   msg.Append('"');
   msg.AppendDetailed(source, false);
   msg.Append('"');
   msg.Append('\n');
   msg.WriteToLogFile();
 }
 
 
 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);
   }
   MoveEventInternal(CODE_MOVE_EVENT, from, 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);
   }
   DeleteEventInternal(CODE_DELETE_EVENT, from);
 }
 
 void Logger::CodeLinePosInfoAddPositionEvent(void* jit_handler_data,
                                      int pc_offset,
                                      int position) {
   if (code_event_handler_ != NULL) {
@@ skipping 25 matching lines @@
 void Logger::CodeEndLinePosInfoRecordEvent(Code* code,
                                            void* jit_handler_data) {
   if (code_event_handler_ != NULL) {
     IssueEndCodePosInfoEvent(code, jit_handler_data);
   }
 }
 
 
 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.
     LogMessageBuilder msg(this);
     msg.Append("%s,%d,", kLogEventsNames[SNAPSHOT_CODE_NAME_EVENT], pos);
     msg.AppendDoubleQuotedString(code_name);
     msg.Append("\n");
     msg.WriteToLogFile();
   }
   if (!FLAG_log_snapshot_positions) return;
@@ skipping 317 matching lines @@
       description = "A keyed call IC from the snapshot";
       tag = Logger::KEYED_CALL_IC_TAG;
       break;
     case Code::NUMBER_OF_KINDS:
       break;
   }
   PROFILE(isolate_, CodeCreateEvent(tag, code_object, description));
 }
 
 
-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
   const char arch[] = "x64";
 #elif V8_TARGET_ARCH_ARM
   const char arch[] = "arm";
 #elif V8_TARGET_ARCH_MIPS
   const char arch[] = "mips";
 #else
   const char arch[] = "unknown";
 #endif
-  LowLevelLogWriteBytes(arch, sizeof(arch));
+  LogWriteBytes(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);
-}
-
-
-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,
                           "Logger::LogCodeObjects");
   HeapIterator iterator(heap);
   DisallowHeapAllocation no_gc;
   for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
     if (obj->IsCode()) LogCodeObject(obj);
   }
 }
@@ skipping 82 matching lines @@
       PROFILE(isolate_, GetterCallbackEvent(name, getter_entry));
     }
     Address setter_entry = v8::ToCData<Address>(ai->setter());
     if (setter_entry != 0) {
       PROFILE(isolate_, SetterCallbackEvent(name, setter_entry));
     }
   }
 }
 
 
+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(FLAG_logfile, '%') != NULL ||

[yurys, 2013/07/15 04:16:35]

FLAG_logfile is passed as the parameter and read here from the flag. I think you
can drop the parameter.

[loislo, 2013/07/15 07:37:00]

FLAG_logfile was replaced with file_name

+      !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);
+      }
+    }
+    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;
   is_initialized_ = true;
 
   // --ll-prof implies --log-code and --log-snapshot-positions.
   if (FLAG_ll_prof) {
     FLAG_log_snapshot_positions = true;
   }
 
   // --prof_lazy controls --log-code, implies --noprof_auto.
   if (FLAG_prof_lazy) {
     FLAG_log_code = false;
     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 && Log::InitLogAtStart()) {

[yurys, 2013/07/15 04:16:35]

Log::InitLogAtStart() check is redundant.

[loislo, 2013/07/15 07:37:00]

Done.

+    ll_logger_ = new LowLevelLogger(*log_file_name);
+  }
 
   ticker_ = new Ticker(isolate, kSamplingIntervalMs);
 
   if (Log::InitLogAtStart()) {
     logging_nesting_ = 1;
   }
 
   if (FLAG_prof) {
     profiler_ = new Profiler(isolate);
     if (!FLAG_prof_auto) {
@@ skipping 36 matching lines @@
   // Stop the profiler before closing the file.
   if (profiler_ != NULL) {
     profiler_->Disengage();
     delete profiler_;
     profiler_ = NULL;
   }
 
   delete ticker_;
   ticker_ = NULL;
 
+  if (ll_logger_) {
+    delete ll_logger_;
+    ll_logger_ = NULL;
+  }
+
   return log_->Close();
 }
 

[yurys, 2013/07/15 04:16:35]

#undefine LL_LOG ?

[loislo, 2013/07/15 07:37:00]

I see no reasons to do that because it gives us no benefits.

 } }  // namespace v8::internal