Revert "[logging] Use OFStream for log events"

This reverts commit 06ff9e97.

Reason for revert: Breaks deopt information with --prof. Deopts no longer show up properly in the logfile / profview

Original change's description:
> [logging] Use OFStream for log events
> 
> This simplifies a few operations and removes the size limitations
> implied by the message buffer used.
> 
> Change-Id: I8b873a0ffa399a037ff5c2501ba4b68158810968
> Reviewed-on: https://chromium-review.googlesource.com/724285
> Commit-Queue: Camillo Bruni <cbruni@chromium.org>
> Reviewed-by: Adam Klein <adamk@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#48766}

TBR=adamk@chromium.org,cbruni@chromium.org

Change-Id: I290da0b2472ad0e765b765b26bdde334253376e3
No-Presubmit: true
No-Tree-Checks: true
No-Try: true
Reviewed-on: https://chromium-review.googlesource.com/730164Reviewed-by: Benedikt Meurer <bmeurer@chromium.org>
Commit-Queue: Benedikt Meurer <bmeurer@chromium.org>
Cr-Commit-Position: refs/heads/master@{#48776}

src/log-utils.cc

@@ -18,26 +18,15 @@ namespace internal {
 const char* const Log::kLogToTemporaryFile = "&";
 const char* const Log::kLogToConsole = "-";
 
-// static
-FILE* Log::CreateOutputHandle(const char* file_name) {
-  // If we're logging anything, we need to open the log file.
-  if (!Log::InitLogAtStart()) {
-    return nullptr;
-  } else if (strcmp(file_name, kLogToConsole) == 0) {
-    return stdout;
-  } else if (strcmp(file_name, kLogToTemporaryFile) == 0) {
-    return base::OS::OpenTemporaryFile();
-  } else {
-    return base::OS::FOpen(file_name, base::OS::LogFileOpenMode);
-  }
-}
-
-Log::Log(Logger* logger, const char* file_name)
+Log::Log(Logger* logger)
     : is_stopped_(false),
-      output_handle_(Log::CreateOutputHandle(file_name)),
-      os_(output_handle_ == nullptr ? stdout : output_handle_),
-      format_buffer_(NewArray<char>(kMessageBufferSize)),
-      logger_(logger) {
+      output_handle_(nullptr),
+      message_buffer_(nullptr),
+      logger_(logger) {}
+
+void Log::Initialize(const char* log_file_name) {
+  message_buffer_ = NewArray<char>(kMessageBufferSize);
+
   // --log-all enables all the log flags.
   if (FLAG_log_all) {
     FLAG_log_api = true;
@@ -51,19 +40,49 @@ Log::Log(Logger* logger, const char* file_name)
   // --prof implies --log-code.
   if (FLAG_prof) FLAG_log_code = true;
 
+  // If we're logging anything, we need to open the log file.
+  if (Log::InitLogAtStart()) {
+    if (strcmp(log_file_name, kLogToConsole) == 0) {
+      OpenStdout();
+    } else if (strcmp(log_file_name, kLogToTemporaryFile) == 0) {
+      OpenTemporaryFile();
+    } else {
+      OpenFile(log_file_name);
+    }
+
     if (output_handle_ != nullptr) {
       Log::MessageBuilder msg(this);
       if (strlen(Version::GetEmbedder()) == 0) {
         msg.Append("v8-version,%d,%d,%d,%d,%d", Version::GetMajor(),
-                 Version::GetMinor(), Version::GetBuild(), Version::GetPatch(),
-                 Version::IsCandidate());
+                   Version::GetMinor(), Version::GetBuild(),
+                   Version::GetPatch(), Version::IsCandidate());
       } else {
         msg.Append("v8-version,%d,%d,%d,%d,%s,%d", Version::GetMajor(),
-                 Version::GetMinor(), Version::GetBuild(), Version::GetPatch(),
-                 Version::GetEmbedder(), Version::IsCandidate());
+                   Version::GetMinor(), Version::GetBuild(),
+                   Version::GetPatch(), Version::GetEmbedder(),
+                   Version::IsCandidate());
       }
       msg.WriteToLogFile();
     }
+  }
+}
+
+
+void Log::OpenStdout() {
+  DCHECK(!IsEnabled());
+  output_handle_ = stdout;
+}
+
+
+void Log::OpenTemporaryFile() {
+  DCHECK(!IsEnabled());
+  output_handle_ = base::OS::OpenTemporaryFile();
+}
+
+
+void Log::OpenFile(const char* name) {
+  DCHECK(!IsEnabled());
+  output_handle_ = base::OS::FOpen(name, base::OS::LogFileOpenMode);
 }
 
 FILE* Log::Close() {
@@ -77,63 +96,74 @@ FILE* Log::Close() {
   }
   output_handle_ = nullptr;
 
-  DeleteArray(format_buffer_);
-  format_buffer_ = nullptr;
+  DeleteArray(message_buffer_);
+  message_buffer_ = nullptr;
 
   is_stopped_ = false;
   return result;
 }
 
+
 Log::MessageBuilder::MessageBuilder(Log* log)
-    : log_(log), lock_guard_(&log_->mutex_) {
-  DCHECK_NOT_NULL(log_->format_buffer_);
+  : log_(log),
+    lock_guard_(&log_->mutex_),
+    pos_(0) {
+  DCHECK_NOT_NULL(log_->message_buffer_);
 }
 
 
 void Log::MessageBuilder::Append(const char* format, ...) {
+  Vector<char> buf(log_->message_buffer_ + pos_,
+                   Log::kMessageBufferSize - pos_);
   va_list args;
   va_start(args, format);
   AppendVA(format, args);
   va_end(args);
+  DCHECK_LE(pos_, Log::kMessageBufferSize);
 }
 
 
 void Log::MessageBuilder::AppendVA(const char* format, va_list args) {
-  Vector<char> buf(log_->format_buffer_, Log::kMessageBufferSize);
-  int length = v8::internal::VSNPrintF(buf, format, args);
-  // {length} is -1 if output was truncated.
-  if (length == -1) {
-    length = Log::kMessageBufferSize;
+  Vector<char> buf(log_->message_buffer_ + pos_,
+                   Log::kMessageBufferSize - pos_);
+  int result = v8::internal::VSNPrintF(buf, format, args);
+
+  // Result is -1 if output was truncated.
+  if (result >= 0) {
+    pos_ += result;
+  } else {
+    pos_ = Log::kMessageBufferSize;
+  }
+  DCHECK_LE(pos_, Log::kMessageBufferSize);
+}
+
+
+void Log::MessageBuilder::Append(const char c) {
+  if (pos_ < Log::kMessageBufferSize) {
+    log_->message_buffer_[pos_++] = c;
   }
-  DCHECK_LE(length, Log::kMessageBufferSize);
-  AppendStringPart(log_->format_buffer_, length);
+  DCHECK_LE(pos_, Log::kMessageBufferSize);
 }
 
 
 void Log::MessageBuilder::AppendDoubleQuotedString(const char* string) {
-  OFStream& os = log_->os_;
-  // TODO(cbruni): unify escaping.
-  os << '"';
+  Append('"');
   for (const char* p = string; *p != '\0'; p++) {
-    if (*p == '"') os << '\\';
-    os << *p;
+    if (*p == '"') {
+      Append('\\');
     }
-  os << '"';
+    Append(*p);
+  }
+  Append('"');
 }
 
-void Log::MessageBuilder::AppendDoubleQuotedString(String* string) {
-  OFStream& os = log_->os_;
-  os << '"';
-  // TODO(cbruni): unify escaping.
-  AppendEscapedString(string);
-  os << '"';
-}
 
-void Log::MessageBuilder::Append(String* string) {
+void Log::MessageBuilder::Append(String* str) {
   DisallowHeapAllocation no_gc;  // Ensure string stay valid.
-  std::unique_ptr<char[]> characters =
-      string->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
-  log_->os_ << characters.get();
+  int length = str->length();
+  for (int i = 0; i < length; i++) {
+    Append(static_cast<char>(str->Get(i)));
+  }
 }
 
 void Log::MessageBuilder::AppendAddress(Address addr) {
@@ -142,69 +172,109 @@ void Log::MessageBuilder::AppendAddress(Address addr) {
 
 void Log::MessageBuilder::AppendSymbolName(Symbol* symbol) {
   DCHECK(symbol);
-  OFStream& os = log_->os_;
-  os << "symbol(";
+  Append("symbol(");
   if (!symbol->name()->IsUndefined(symbol->GetIsolate())) {
-    os << "\"";
+    Append("\"");
     AppendDetailed(String::cast(symbol->name()), false);
-    os << "\" ";
+    Append("\" ");
   }
-  os << "hash " << std::hex << symbol->Hash() << std::dec << ")";
+  Append("hash %x)", symbol->Hash());
 }
 
 
 void Log::MessageBuilder::AppendDetailed(String* str, bool show_impl_info) {
   if (str == nullptr) return;
   DisallowHeapAllocation no_gc;  // Ensure string stay valid.
-  OFStream& os = log_->os_;
   int len = str->length();
-  if (len > 0x1000) len = 0x1000;
+  if (len > 0x1000)
+    len = 0x1000;
   if (show_impl_info) {
-    os << (str->IsOneByteRepresentation() ? 'a' : '2');
-    if (StringShape(str).IsExternal()) os << 'e';
-    if (StringShape(str).IsInternalized()) os << '#';
-    os << ':' << str->length() << ':';
+    Append(str->IsOneByteRepresentation() ? 'a' : '2');
+    if (StringShape(str).IsExternal())
+      Append('e');
+    if (StringShape(str).IsInternalized())
+      Append('#');
+    Append(":%i:", str->length());
+  }
+  for (int i = 0; i < len; i++) {
+    uc32 c = str->Get(i);
+    if (c > 0xff) {
+      Append("\\u%04x", c);
+    } else if (c < 32 || c > 126) {
+      Append("\\x%02x", c);
+    } else if (c == ',') {
+      Append("\\,");
+    } else if (c == '\\') {
+      Append("\\\\");
+    } else if (c == '\"') {
+      Append("\"\"");
+    } else {
+      Append("%lc", c);
+    }
   }
-  AppendEscapedString(str, len);
 }
 
-void Log::MessageBuilder::AppendEscapedString(String* str) {
+void Log::MessageBuilder::AppendUnbufferedHeapString(String* str) {
   if (str == nullptr) return;
-  int len = str->length();
-  AppendEscapedString(str, len);
-}
-
-void Log::MessageBuilder::AppendEscapedString(String* str, int len) {
-  DCHECK_LE(len, str->length());
   DisallowHeapAllocation no_gc;  // Ensure string stay valid.
-  OFStream& os = log_->os_;
-  // TODO(cbruni): unify escaping.
+  ScopedVector<char> buffer(16);
+  int len = str->length();
   for (int i = 0; i < len; i++) {
     uc32 c = str->Get(i);
     if (c >= 32 && c <= 126) {
       if (c == '\"') {
-        os << "\"\"";
+        AppendUnbufferedCString("\"\"");
       } else if (c == '\\') {
-        os << "\\\\";
-      } else if (c == ',') {
-        os << "\\,";
+        AppendUnbufferedCString("\\\\");
       } else {
-        os << static_cast<char>(c);
+        AppendUnbufferedChar(c);
       }
     } else if (c > 0xff) {
-      Append("\\u%04x", c);
+      int length = v8::internal::SNPrintF(buffer, "\\u%04x", c);
+      DCHECK_EQ(6, length);
+      log_->WriteToFile(buffer.start(), length);
     } else {
-      DCHECK(c < 32 || (c > 126 && c <= 0xff));
-      Append("\\x%02x", c);
+      DCHECK_LE(c, 0xffff);
+      int length = v8::internal::SNPrintF(buffer, "\\x%02x", c);
+      DCHECK_EQ(4, length);
+      log_->WriteToFile(buffer.start(), length);
     }
   }
 }
 
+void Log::MessageBuilder::AppendUnbufferedChar(char c) {
+  log_->WriteToFile(&c, 1);
+}
+
+void Log::MessageBuilder::AppendUnbufferedCString(const char* str) {
+  log_->WriteToFile(str, static_cast<int>(strlen(str)));
+}
+
 void Log::MessageBuilder::AppendStringPart(const char* str, int len) {
-  log_->os_.write(str, len);
+  if (pos_ + len > Log::kMessageBufferSize) {
+    len = Log::kMessageBufferSize - pos_;
+    DCHECK_GE(len, 0);
+    if (len == 0) return;
+  }
+  Vector<char> buf(log_->message_buffer_ + pos_,
+                   Log::kMessageBufferSize - pos_);
+  StrNCpy(buf, str, len);
+  pos_ += len;
+  DCHECK_LE(pos_, Log::kMessageBufferSize);
 }
 
-void Log::MessageBuilder::WriteToLogFile() { log_->os_ << std::endl; }
+void Log::MessageBuilder::WriteToLogFile() {
+  DCHECK_LE(pos_, Log::kMessageBufferSize);
+  // Assert that we do not already have a new line at the end.
+  DCHECK(pos_ == 0 || log_->message_buffer_[pos_ - 1] != '\n');
+  if (pos_ == Log::kMessageBufferSize) pos_--;
+  log_->message_buffer_[pos_++] = '\n';
+  const int written = log_->WriteToFile(log_->message_buffer_, pos_);
+  if (written != pos_) {
+    log_->stop();
+    log_->logger_->LogFailure();
+  }
+}
 
 }  // namespace internal
 }  // namespace v8

src/log-utils.h

@@ -13,7 +13,6 @@
 #include "src/base/compiler-specific.h"
 #include "src/base/platform/mutex.h"
 #include "src/flags.h"
-#include "src/ostreams.h"
 
 namespace v8 {
 namespace internal {
@@ -23,7 +22,8 @@ class Logger;
 // Functions and data for performing output of log messages.
 class Log {
  public:
-  Log(Logger* log, const char* log_file_name);
+  // Performs process-wide initialization.
+  void Initialize(const char* log_file_name);
 
   // Disables logging, but preserves acquired resources.
   void stop() { is_stopped_ = true; }
@@ -66,9 +66,11 @@ class Log {
     // Append string data to the log message.
     void PRINTF_FORMAT(2, 0) AppendVA(const char* format, va_list args);
 
+    // Append a character to the log message.
+    void Append(const char c);
+
     // Append double quoted string to the log message.
     void AppendDoubleQuotedString(const char* string);
-    void AppendDoubleQuotedString(String* string);
 
     // Append a heap string.
     void Append(String* str);
@@ -86,32 +88,37 @@ class Log {
     // Helpers for appending char, C-string and heap string without
     // buffering. This is useful for entries that can exceed the 2kB
     // limit.
-    void AppendEscapedString(String* source);
-    void AppendEscapedString(String* source, int len);
-
-    // Delegate insertion to the underlying {log_}.
-    template <typename T>
-    MessageBuilder& operator<<(T value) {
-      log_->os_ << value;
-      return *this;
-    }
+    void AppendUnbufferedChar(char c);
+    void AppendUnbufferedCString(const char* str);
+    void AppendUnbufferedHeapString(String* source);
 
-    // Finish the current log line an flush the it to the log file.
+    // Write the log message to the log file currently opened.
     void WriteToLogFile();
 
    private:
     Log* log_;
     base::LockGuard<base::Mutex> lock_guard_;
+    int pos_;
   };
 
  private:
-  static FILE* CreateOutputHandle(const char* file_name);
+  explicit Log(Logger* logger);
+
+  // Opens stdout for logging.
+  void OpenStdout();
+
+  // Opens file for logging.
+  void OpenFile(const char* name);
+
+  // Opens a temporary file for logging.
+  void OpenTemporaryFile();
 
   // Implementation of writing to a log file.
   int WriteToFile(const char* msg, int length) {
     DCHECK_NOT_NULL(output_handle_);
-    os_.write(msg, length);
-    DCHECK(!os_.bad());
+    size_t rv = fwrite(msg, 1, length, output_handle_);
+    DCHECK_EQ(length, rv);
+    USE(rv);
     return length;
   }
 
@@ -121,7 +128,6 @@ class Log {
   // When logging is active output_handle_ is used to store a pointer to log
   // destination.  mutex_ should be acquired before using output_handle_.
   FILE* output_handle_;
-  OFStream os_;
 
   // mutex_ is a Mutex used for enforcing exclusive
   // access to the formatting buffer and the log file or log memory buffer.
@@ -129,7 +135,7 @@ class Log {
 
   // Buffer used for formatting log messages. This is a singleton buffer and
   // mutex_ should be acquired before using it.
-  char* format_buffer_;
+  char* message_buffer_;
 
   Logger* logger_;