Reland "[logging] Use OFStream for log events"

This is a reland of 06ff9e97
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}

Change-Id: Iafda1c88d9180d188d6b8bd7d03d6d27100538d8
Reviewed-on: https://chromium-review.googlesource.com/731107
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Reviewed-by: Adam Klein <adamk@chromium.org>
Cr-Commit-Position: refs/heads/master@{#48804}

src/log-utils.cc

@@ -18,15 +18,26 @@ namespace internal {
 const char* const Log::kLogToTemporaryFile = "&";
 const char* const Log::kLogToConsole = "-";
 
-Log::Log(Logger* logger)
-    : is_stopped_(false),
-      output_handle_(nullptr),
-      message_buffer_(nullptr),
-      logger_(logger) {}
-
-void Log::Initialize(const char* log_file_name) {
-  message_buffer_ = NewArray<char>(kMessageBufferSize);
+// 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)
+    : is_stopped_(false),
+      output_handle_(Log::CreateOutputHandle(file_name)),
+      os_(output_handle_ == nullptr ? stdout : output_handle_),
+      format_buffer_(NewArray<char>(kMessageBufferSize)),
+      logger_(logger) {
   // --log-all enables all the log flags.
   if (FLAG_log_all) {
     FLAG_log_api = true;
@@ -40,49 +51,19 @@ void Log::Initialize(const char* log_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() {
@@ -96,74 +77,63 @@ FILE* Log::Close() {
   }
   output_handle_ = nullptr;
 
-  DeleteArray(message_buffer_);
-  message_buffer_ = nullptr;
+  DeleteArray(format_buffer_);
+  format_buffer_ = nullptr;
 
   is_stopped_ = false;
   return result;
 }
 
-
 Log::MessageBuilder::MessageBuilder(Log* log)
-  : log_(log),
-    lock_guard_(&log_->mutex_),
-    pos_(0) {
-  DCHECK_NOT_NULL(log_->message_buffer_);
+    : log_(log), lock_guard_(&log_->mutex_) {
+  DCHECK_NOT_NULL(log_->format_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_->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;
+  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;
   }
-  DCHECK_LE(pos_, Log::kMessageBufferSize);
+  DCHECK_LE(length, Log::kMessageBufferSize);
+  AppendStringPart(log_->format_buffer_, length);
 }
 
 
 void Log::MessageBuilder::AppendDoubleQuotedString(const char* string) {
-  Append('"');
+  OFStream& os = log_->os_;
+  // TODO(cbruni): unify escaping.
+  os << '"';
   for (const char* p = string; *p != '\0'; p++) {
-    if (*p == '"') {
-      Append('\\');
+    if (*p == '"') os << '\\';
+    os << *p;
   }
-    Append(*p);
-  }
-  Append('"');
+  os << '"';
 }
 
+void Log::MessageBuilder::AppendDoubleQuotedString(String* string) {
+  OFStream& os = log_->os_;
+  os << '"';
+  // TODO(cbruni): unify escaping.
+  AppendEscapedString(string);
+  os << '"';
+}
 
-void Log::MessageBuilder::Append(String* str) {
+void Log::MessageBuilder::Append(String* string) {
   DisallowHeapAllocation no_gc;  // Ensure string stay valid.
-  int length = str->length();
-  for (int i = 0; i < length; i++) {
-    Append(static_cast<char>(str->Get(i)));
-  }
+  std::unique_ptr<char[]> characters =
+      string->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
+  log_->os_ << characters.get();
 }
 
 void Log::MessageBuilder::AppendAddress(Address addr) {
@@ -172,109 +142,69 @@ void Log::MessageBuilder::AppendAddress(Address addr) {
 
 void Log::MessageBuilder::AppendSymbolName(Symbol* symbol) {
   DCHECK(symbol);
-  Append("symbol(");
+  OFStream& os = log_->os_;
+  os << "symbol(";
   if (!symbol->name()->IsUndefined(symbol->GetIsolate())) {
-    Append("\"");
+    os << "\"";
     AppendDetailed(String::cast(symbol->name()), false);
-    Append("\" ");
+    os << "\" ";
   }
-  Append("hash %x)", symbol->Hash());
+  os << "hash " << std::hex << symbol->Hash() << std::dec << ")";
 }
 
 
 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) {
-    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);
-    }
+    os << (str->IsOneByteRepresentation() ? 'a' : '2');
+    if (StringShape(str).IsExternal()) os << 'e';
+    if (StringShape(str).IsInternalized()) os << '#';
+    os << ':' << str->length() << ':';
   }
+  AppendEscapedString(str, len);
 }
 
-void Log::MessageBuilder::AppendUnbufferedHeapString(String* str) {
+void Log::MessageBuilder::AppendEscapedString(String* str) {
   if (str == nullptr) return;
-  DisallowHeapAllocation no_gc;  // Ensure string stay valid.
-  ScopedVector<char> buffer(16);
   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.
   for (int i = 0; i < len; i++) {
     uc32 c = str->Get(i);
     if (c >= 32 && c <= 126) {
       if (c == '\"') {
-        AppendUnbufferedCString("\"\"");
+        os << "\"\"";
       } else if (c == '\\') {
-        AppendUnbufferedCString("\\\\");
+        os << "\\\\";
+      } else if (c == ',') {
+        os << "\\,";
       } else {
-        AppendUnbufferedChar(c);
+        os << static_cast<char>(c);
       }
     } else if (c > 0xff) {
-      int length = v8::internal::SNPrintF(buffer, "\\u%04x", c);
-      DCHECK_EQ(6, length);
-      log_->WriteToFile(buffer.start(), length);
+      Append("\\u%04x", c);
     } else {
-      DCHECK_LE(c, 0xffff);
-      int length = v8::internal::SNPrintF(buffer, "\\x%02x", c);
-      DCHECK_EQ(4, length);
-      log_->WriteToFile(buffer.start(), length);
+      DCHECK(c < 32 || (c > 126 && c <= 0xff));
+      Append("\\x%02x", c);
     }
   }
 }
 
-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) {
-  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);
+  log_->os_.write(str, len);
 }
 
-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();
-  }
-}
+void Log::MessageBuilder::WriteToLogFile() { log_->os_ << std::endl; }
 
 }  // namespace internal
 }  // namespace v8

src/log-utils.h

@@ -13,6 +13,7 @@
 #include "src/base/compiler-specific.h"
 #include "src/base/platform/mutex.h"
 #include "src/flags.h"
+#include "src/ostreams.h"
 
 namespace v8 {
 namespace internal {
@@ -22,8 +23,7 @@ class Logger;
 // Functions and data for performing output of log messages.
 class Log {
  public:
-  // Performs process-wide initialization.
-  void Initialize(const char* log_file_name);
+  Log(Logger* log, const char* log_file_name);
 
   // Disables logging, but preserves acquired resources.
   void stop() { is_stopped_ = true; }
@@ -66,11 +66,9 @@ 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);
@@ -88,37 +86,32 @@ 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 AppendUnbufferedChar(char c);
-    void AppendUnbufferedCString(const char* str);
-    void AppendUnbufferedHeapString(String* source);
+    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;
+    }
 
-    // Write the log message to the log file currently opened.
+    // Finish the current log line an flush the it to the log file.
     void WriteToLogFile();
 
    private:
     Log* log_;
     base::LockGuard<base::Mutex> lock_guard_;
-    int pos_;
   };
 
  private:
-  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();
+  static FILE* CreateOutputHandle(const char* file_name);
 
   // Implementation of writing to a log file.
   int WriteToFile(const char* msg, int length) {
     DCHECK_NOT_NULL(output_handle_);
-    size_t rv = fwrite(msg, 1, length, output_handle_);
-    DCHECK_EQ(length, rv);
-    USE(rv);
+    os_.write(msg, length);
+    DCHECK(!os_.bad());
     return length;
   }
 
@@ -128,6 +121,7 @@ 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.
@@ -135,7 +129,7 @@ class Log {
 
   // Buffer used for formatting log messages. This is a singleton buffer and
   // mutex_ should be acquired before using it.
-  char* message_buffer_;
+  char* format_buffer_;
 
   Logger* logger_;
 

test/cctest/log-eq-of-logging-and-traversal.js

@@ -187,6 +187,13 @@ if (typeof result !== "string") {
                (c[2] ? c[2] : "---") + " " +
                (c[3] ? c[3] : "---"));
     }
+    out.push("================================================")
+    out.push("MAKE SURE TO USE A CLEAN ISOLATiE!");
+    out.push("Use tools/test.py");
+    out.push("================================================")
+    out.push("*   Lines are the same");
+    out.push("--- Line is missing"
+    out.push("================================================")
   }
   result[0] ? true : out.join("\n");
 } else {

test/cctest/test-log.cc

@@ -70,7 +70,7 @@ static const char* StrNStr(const char* s1, const char* s2, size_t n) {
 
 // Look for a log line which starts with {prefix} and ends with {suffix}.
 static const char* FindLogLine(i::Vector<const char>* log, const char* prefix,
-                               const char* suffix) {
+                               const char* suffix = nullptr) {
   const char* start = log->start();
   const char* end = start + log->length();
   CHECK_EQ(end[0], '\0');
@@ -79,6 +79,7 @@ static const char* FindLogLine(i::Vector<const char>* log, const char* prefix,
   while (start < end) {
     const char* prefixResult = StrNStr(start, prefix, (end - start));
     if (!prefixResult) return NULL;
+    if (suffix == nullptr) return prefixResult;
     const char* suffixResult =
         StrNStr(prefixResult, suffix, (end - prefixResult));
     if (!suffixResult) return NULL;
@@ -122,6 +123,8 @@ class ScopedLoggerInitializer {
 
   Logger* logger() { return logger_; }
 
+  void PrintLog() { printf("%s", log_.start()); }
+
   v8::Local<v8::String> GetLogString() {
     return v8::String::NewFromUtf8(isolate_, log_.start(),
                                    v8::NewStringType::kNormal, log_.length())
@@ -134,7 +137,7 @@ class ScopedLoggerInitializer {
     CHECK(exists);
   }
 
-  const char* FindLine(const char* prefix, const char* suffix) {
+  const char* FindLine(const char* prefix, const char* suffix = nullptr) {
     return FindLogLine(&log_, prefix, suffix);
   }
 
@@ -176,6 +179,9 @@ TEST(FindLogLine) {
       "prefix4 suffix4";
   // Make sure the vector contains the terminating \0 character.
   i::Vector<const char> log(string, strlen(string));
+  CHECK(FindLogLine(&log, "prefix1, stuff,   suffix1"));
+  CHECK(FindLogLine(&log, "prefix1, stuff"));
+  CHECK(FindLogLine(&log, "prefix1"));
   CHECK(FindLogLine(&log, "prefix1", "suffix1"));
   CHECK(FindLogLine(&log, "prefix1", "suffix1"));
   CHECK(!FindLogLine(&log, "prefix2", "suffix2"));
@@ -654,3 +660,40 @@ TEST(Issue539892) {
   }
   isolate->Dispose();
 }
+
+TEST(LogAll) {
+  SETUP_FLAGS();
+  i::FLAG_log_all = true;
+  v8::Isolate::CreateParams create_params;
+  create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
+  v8::Isolate* isolate = v8::Isolate::New(create_params);
+
+  {
+    ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
+
+    // Function that will
+    const char* source_text =
+        "function testAddFn(a,b) { return a + b };"
+        "let result;"
+        "for (let i = 0; i < 100000; i++) { result = testAddFn(i, i); };"
+        "testAddFn('1', 1);"
+        "for (let i = 0; i < 100000; i++) { result = testAddFn('1', i); }";
+    CompileRun(source_text);
+
+    logger.StopLogging();
+
+    // We should find at least one code-creation even for testAddFn();
+    CHECK(logger.FindLine("api,v8::Context::New"));
+    CHECK(logger.FindLine("timer-event-start", "V8.CompileCode"));
+    CHECK(logger.FindLine("timer-event-end", "V8.CompileCode"));
+    CHECK(logger.FindLine("code-creation,Script", ":1:1"));
+    CHECK(logger.FindLine("api,v8::Script::Run"));
+    CHECK(logger.FindLine("code-creation,LazyCompile,", "testAddFn"));
+    if (i::FLAG_opt && !i::FLAG_always_opt) {
+      CHECK(logger.FindLine("code-deopt,", "soft"));
+      CHECK(logger.FindLine("timer-event-start", "V8.DeoptimizeCode"));
+      CHECK(logger.FindLine("timer-event-end", "V8.DeoptimizeCode"));
+    }
+  }
+  isolate->Dispose();
+}