Changed all log messages to be handled through the LogMessageBuilder instead ...

src/log.cc

 // Copyright 2006-2008 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 250 matching lines @@
 
 #ifdef ENABLE_LOGGING_AND_PROFILING
 // Utility class for formatting log messages. It fills the message into the
 // static buffer in Logger.
 class LogMessageBuilder BASE_EMBEDDED {
  public:
   explicit LogMessageBuilder();
   ~LogMessageBuilder() { }
 
   void Append(const char* format, ...);
+  void Append(const char* format, va_list args);
   void Append(const char c);
+  void Append(String *str);
+  void AppendDetailed(String* str, bool show_impl_info);
 
   void WriteToLogFile();
 
  private:
   ScopedLock sl;
   int pos_;
 };
 
 
 // Create a message builder starting from position 0. This acquires the mutex
 // in the logger as well.
 LogMessageBuilder::LogMessageBuilder(): pos_(0), sl(Logger::mutex_) {
   ASSERT(Logger::message_buffer_ != NULL);
 }
 
 
 // Append string data to the log message.
 void LogMessageBuilder::Append(const char* format, ...) {
   Vector<char> buf(Logger::message_buffer_ + pos_,
                    Logger::kMessageBufferSize - pos_);
   va_list args;
   va_start(args, format);
+  Append(format, args);
+  va_end(args);
+  ASSERT(pos_ <= Logger::kMessageBufferSize);
+}
+
+
+// Append string data to the log message.
+void LogMessageBuilder::Append(const char* format, va_list args) {
+  Vector<char> buf(Logger::message_buffer_ + pos_,
+                   Logger::kMessageBufferSize - pos_);
   int result = v8::internal::OS::VSNPrintF(buf, format, args);
-  va_end(args);
 
   // Result is -1 if output was truncated.
   if (result >= 0) {
     pos_ += result;
   } else {
     pos_ = Logger::kMessageBufferSize;
   }
   ASSERT(pos_ <= Logger::kMessageBufferSize);
 }
 
 
 // Append a character to the log message.
 void LogMessageBuilder::Append(const char c) {
   if (pos_ < Logger::kMessageBufferSize) {
     Logger::message_buffer_[pos_++] = c;
   }
   ASSERT(pos_ <= Logger::kMessageBufferSize);
 }
 
 
+// Append a heap string.
+void LogMessageBuilder::Append(String* str) {
+  AssertNoAllocation no_heap_allocation;  // Ensure string stay valid.
+  StringShape shape(str);
+  int length = str->length(shape);
+  for (int i = 0; i < length; i++) {
+    Append(static_cast<char>(str->Get(shape, i)));
+  }
+}
+
+void LogMessageBuilder::AppendDetailed(String* str, bool show_impl_info) {
+  AssertNoAllocation no_heap_allocation;  // Ensure string stay valid.
+  StringShape shape(str);
+  int len = str->length(shape);
+  if (len > 0x1000)
+    len = 0x1000;
+  if (show_impl_info) {
+    Append(shape.IsAsciiRepresentation() ? 'a' : '2');
+    if (shape.IsExternal())
+      Append('e');
+    if (shape.IsSymbol())
+      Append('#');
+    Append(":%i:", str->length());
+  }
+  for (int i = 0; i < len; i++) {
+    uc32 c = str->Get(shape, 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 {
+      Append("%lc", c);
+    }
+  }
+}
+
 // Write the log message to the log file currently opened.
 void LogMessageBuilder::WriteToLogFile() {
   ASSERT(pos_ <= Logger::kMessageBufferSize);
   fwrite(Logger::message_buffer_, 1, pos_, Logger::logfile_);
 }
 #endif
 
 
 //
 // Logger class implementation.
 //
 Ticker* Logger::ticker_ = NULL;
 char* Logger::message_buffer_ = NULL;
 FILE* Logger::logfile_ = NULL;
 Profiler* Logger::profiler_ = NULL;
 Mutex* Logger::mutex_ = NULL;
 VMState* Logger::current_state_ = NULL;
 SlidingStateWindow* Logger::sliding_state_window_ = NULL;
 
 #endif  // ENABLE_LOGGING_AND_PROFILING
 
 
 void Logger::Preamble(const char* content) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log_code) return;
-  ScopedLock sl(mutex_);
-  fprintf(logfile_, "%s", content);
+  LogMessageBuilder msg;
+  msg.Append("%s", content);
+  msg.WriteToLogFile();
 #endif
 }
 
 
 void Logger::StringEvent(const char* name, const char* value) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (FLAG_log) UncheckedStringEvent(name, value);
 #endif
 }
 
 
 #ifdef ENABLE_LOGGING_AND_PROFILING
 void Logger::UncheckedStringEvent(const char* name, const char* value) {
   if (logfile_ == NULL) return;
-  ScopedLock sl(mutex_);
-  fprintf(logfile_, "%s,\"%s\"\n", name, value);
+  LogMessageBuilder msg;
+  msg.Append("%s,\"%s\"\n", name, value);
+  msg.WriteToLogFile();
 }
 #endif
 
 
 void Logger::IntEvent(const char* name, int value) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log) return;
-  ScopedLock sl(mutex_);
-  fprintf(logfile_, "%s,%d\n", name, value);
+  LogMessageBuilder msg;
+  msg.Append("%s,%d\n", name, value);
+  msg.WriteToLogFile();
 #endif
 }
 
 
 void Logger::HandleEvent(const char* name, Object** location) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log_handles) return;
-  ScopedLock sl(mutex_);
-  fprintf(logfile_, "%s,0x%x\n", name,
-          reinterpret_cast<unsigned int>(location));
+  LogMessageBuilder msg;
+  msg.Append("%s,0x%x\n", name,
+             reinterpret_cast<unsigned int>(location));
+  msg.WriteToLogFile();
 #endif
 }
 
 
 #ifdef ENABLE_LOGGING_AND_PROFILING
 // ApiEvent is private so all the calls come from the Logger class.  It is the
 // caller's responsibility to ensure that logfile_ is not NULL and that
 // FLAG_log_api is true.
 void Logger::ApiEvent(const char* format, ...) {
   ASSERT(logfile_ != NULL && FLAG_log_api);
-  ScopedLock sl(mutex_);
+  LogMessageBuilder msg;
   va_list ap;
   va_start(ap, format);
-  vfprintf(logfile_, format, ap);
+  msg.Append(format, ap);
+  va_end(ap);
+  msg.WriteToLogFile();
 }
 #endif
 
 
 void Logger::ApiNamedSecurityCheck(Object* key) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log_api) return;
   if (key->IsString()) {
     SmartPointer<char> str =
         String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
     ApiEvent("api,check-security,\"%s\"\n", *str);
   } else if (key->IsUndefined()) {
     ApiEvent("api,check-security,undefined\n");
   } else {
     ApiEvent("api,check-security,['no-name']\n");
   }
 #endif
 }
 
 
 void Logger::SharedLibraryEvent(const char* library_path,
                                 unsigned start,
                                 unsigned end) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_prof) return;
-  ScopedLock sl(mutex_);
-  fprintf(logfile_, "shared-library,\"%s\",0x%08x,0x%08x\n", library_path,
-          start, end);
+  LogMessageBuilder msg;
+  msg.Append("shared-library,\"%s\",0x%08x,0x%08x\n", library_path,
+             start, end);
+  msg.WriteToLogFile();
 #endif
 }
 
 
 void Logger::SharedLibraryEvent(const wchar_t* library_path,
                                 unsigned start,
                                 unsigned end) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_prof) return;
-  ScopedLock sl(mutex_);
-  fprintf(logfile_, "shared-library,\"%ls\",0x%08x,0x%08x\n", library_path,
-          start, end);
+  LogMessageBuilder msg;
+  msg.Append("shared-library,\"%ls\",0x%08x,0x%08x\n", library_path,
+             start, end);
+  msg.WriteToLogFile();
 #endif
 }
 
 
 #ifdef ENABLE_LOGGING_AND_PROFILING
-void Logger::LogString(Handle<String> str, bool show_impl_info) {
-  StringShape shape(*str);
-  int len = str->length(shape);
-  if (len > 0x1000)
-    len = 0x1000;
-  if (show_impl_info) {
-    fputc(shape.IsAsciiRepresentation() ? 'a' : '2', logfile_);
-    if (shape.IsExternal())
-      fputc('e', logfile_);
-    if (shape.IsSymbol())
-      fputc('#', logfile_);
-    fprintf(logfile_, ":%i:", str->length());
-  }
-  for (int i = 0; i < len; i++) {
-    uc32 c = str->Get(shape, i);
-    if (c > 0xff) {
-      fprintf(logfile_, "\\u%04x", c);
-    } else if (c < 32 || c > 126) {
-      fprintf(logfile_, "\\x%02x", c);
-    } else if (c == ',') {
-      fprintf(logfile_, "\\,");
-    } else if (c == '\\') {
-      fprintf(logfile_, "\\\\");
-    } else {
-      fprintf(logfile_, "%lc", c);
-    }
-  }
-}
-
 void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
   // Prints "/" + re.source + "/" +
   //      (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
+  LogMessageBuilder msg;
 
   Handle<Object> source = GetProperty(regexp, "source");
   if (!source->IsString()) {
-    fprintf(logfile_, "no source");
+    msg.Append("no source");
     return;
   }
 
   switch (regexp->TypeTag()) {
     case JSRegExp::ATOM:
-      fprintf(logfile_, "a");
+      msg.Append('a');
       break;
     default:
       break;
   }
-  fprintf(logfile_, "/");
-  LogString(Handle<String>::cast(source), false);
-  fprintf(logfile_, "/");
+  msg.Append('/');
+  msg.AppendDetailed(*Handle<String>::cast(source), false);
+  msg.Append('/');
 
   // global flag
   Handle<Object> global = GetProperty(regexp, "global");
   if (global->IsTrue()) {
-    fprintf(logfile_, "g");
+    msg.Append('g');
   }
   // ignorecase flag
   Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
   if (ignorecase->IsTrue()) {
-    fprintf(logfile_, "i");
+    msg.Append('i');
   }
   // multiline flag
   Handle<Object> multiline = GetProperty(regexp, "multiline");
   if (multiline->IsTrue()) {
-    fprintf(logfile_, "m");
+    msg.Append('m');
   }
+
+  msg.WriteToLogFile();
 }
 #endif  // ENABLE_LOGGING_AND_PROFILING
 
 
 void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log_regexp) return;
-  ScopedLock sl(mutex_);
-
-  fprintf(logfile_, "regexp-compile,");
+  LogMessageBuilder msg;
+  msg.Append("regexp-compile,");
   LogRegExpSource(regexp);
-  fprintf(logfile_, in_cache ? ",hit\n" : ",miss\n");
+  msg.Append(in_cache ? ",hit\n" : ",miss\n");
+  msg.WriteToLogFile();
 #endif
 }
 
 
 void Logger::LogRuntime(Vector<const char> format, JSArray* args) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
-  ScopedLock sl(mutex_);
+  if (logfile_ == NULL || !FLAG_log_runtime) return;
   HandleScope scope;
+  LogMessageBuilder msg;
   for (int i = 0; i < format.length(); i++) {
     char c = format[i];
     if (c == '%' && i <= format.length() - 2) {
       i++;
       ASSERT('0' <= format[i] && format[i] <= '9');
       Object* obj = args->GetElement(format[i] - '0');
       i++;
       switch (format[i]) {
         case 's':
-          Logger::LogString(Handle<String>(String::cast(obj)), false);
+          msg.AppendDetailed(String::cast(obj), false);
           break;
         case 'S':
-          Logger::LogString(Handle<String>(String::cast(obj)), true);
+          msg.AppendDetailed(String::cast(obj), true);
           break;
         case 'r':
           Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj)));
           break;
         case 'x':
-          fprintf(logfile_, "0x%x", Smi::cast(obj)->value());
+          msg.Append("0x%x", Smi::cast(obj)->value());
           break;
         case 'i':
-          fprintf(logfile_, "%i", Smi::cast(obj)->value());
+          msg.Append("%i", Smi::cast(obj)->value());
           break;
         default:
           UNREACHABLE();
       }
     } else {
-      fputc(c, logfile_);
+      msg.Append(c);
     }
   }
-  fputc('\n', logfile_);
+  msg.Append('\n');
+  msg.WriteToLogFile();
 #endif
 }
 
 
 void Logger::ApiIndexedSecurityCheck(uint32_t index) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log_api) return;
   ApiEvent("api,check-security,%u\n", index);
 #endif
 }
@@ skipping 41 matching lines @@
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log_api) return;
   Logger::ApiEvent("api,%s\n", name);
 #endif
 }
 
 
 void Logger::NewEvent(const char* name, void* object, size_t size) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log) return;
-  ScopedLock sl(mutex_);
-  fprintf(logfile_, "new,%s,0x%x,%u\n", name,
-          reinterpret_cast<unsigned int>(object),
-          static_cast<unsigned int>(size));
+  LogMessageBuilder msg;
+  msg.Append("new,%s,0x%x,%u\n", name,
+             reinterpret_cast<unsigned int>(object),
+             static_cast<unsigned int>(size));
+  msg.WriteToLogFile();
 #endif
 }
 
 
 void Logger::DeleteEvent(const char* name, void* object) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log) return;
-  ScopedLock sl(mutex_);
-  fprintf(logfile_, "delete,%s,0x%x\n", name,
-          reinterpret_cast<unsigned int>(object));
+  LogMessageBuilder msg;
+  msg.Append("delete,%s,0x%x\n", name,
+             reinterpret_cast<unsigned int>(object));
+  msg.WriteToLogFile();
 #endif
 }
 
 
 void Logger::CodeCreateEvent(const char* tag, Code* code, const char* comment) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log_code) return;
   LogMessageBuilder msg;
   msg.Append("code-creation,%s,0x%x,%d,\"", tag,
              reinterpret_cast<unsigned int>(code->address()),
              code->instruction_size());
   for (const char* p = comment; *p != '\0'; p++) {
-    if (*p == '\"') fprintf(logfile_, "\\");
+    if (*p == '"') {
+      msg.Append('\\');
+    }
     msg.Append(*p);
   }
   msg.Append('"');
   msg.Append('\n');
   msg.WriteToLogFile();
 #endif
 }
 
 
 void Logger::CodeCreateEvent(const char* tag, Code* code, String* name) {
@@ skipping 99 matching lines @@
              reinterpret_cast<unsigned int>(masm),
              masm->pc_offset());
   msg.WriteToLogFile();
 #endif
 }
 
 
 void Logger::ResourceEvent(const char* name, const char* tag) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log) return;
-  ScopedLock sl(mutex_);
-  fprintf(logfile_, "%s,%s,", name, tag);
+  LogMessageBuilder msg;
+  msg.Append("%s,%s,", name, tag);
 
   uint32_t sec, usec;
   if (OS::GetUserTime(&sec, &usec) != -1) {
-    fprintf(logfile_, "%d,%d,", sec, usec);
+    msg.Append("%d,%d,", sec, usec);
   }
-  fprintf(logfile_, "%.0f", OS::TimeCurrentMillis());
+  msg.Append("%.0f", OS::TimeCurrentMillis());
 
-  fprintf(logfile_, "\n");
+  msg.Append('\n');
+  msg.WriteToLogFile();
 #endif
 }
 
 
 void Logger::SuspectReadEvent(String* name, Object* obj) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log_suspect) return;
+  LogMessageBuilder msg;
   String* class_name = obj->IsJSObject()
                        ? JSObject::cast(obj)->class_name()
                        : Heap::empty_string();
   ScopedLock sl(mutex_);
-  fprintf(logfile_, "suspect-read,");
-  class_name->PrintOn(logfile_);
-  fprintf(logfile_, ",\"");
-  name->PrintOn(logfile_);
-  fprintf(logfile_, "\"\n");
+  msg.Append("suspect-read,");
+  msg.Append(class_name);
+  msg.Append(',');
+  msg.Append('"');
+  msg.Append(name);
+  msg.Append('"');
+  msg.Append('\n');
+  msg.WriteToLogFile();
 #endif
 }
 
 
 void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log_gc) return;
-  ScopedLock sl(mutex_);
-  fprintf(logfile_, "heap-sample-begin,\"%s\",\"%s\"\n", space, kind);
+  LogMessageBuilder msg;
+  msg.Append("heap-sample-begin,\"%s\",\"%s\"\n", space, kind);
+  msg.WriteToLogFile();
 #endif
 }
 
 
 void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log_gc) return;
-  ScopedLock sl(mutex_);
-  fprintf(logfile_, "heap-sample-end,\"%s\",\"%s\"\n", space, kind);
+  LogMessageBuilder msg;
+  msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
+  msg.WriteToLogFile();
 #endif
 }
 
 
 void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log_gc) return;
-  ScopedLock sl(mutex_);
-  fprintf(logfile_, "heap-sample-item,%s,%d,%d\n", type, number, bytes);
+  LogMessageBuilder msg;
+  msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
+  msg.WriteToLogFile();
 #endif
 }
 
 
 void Logger::DebugTag(const char* call_site_tag) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log) return;
-  ScopedLock sl(mutex_);
-  fprintf(logfile_, "debug-tag,%s\n", call_site_tag);
+  LogMessageBuilder msg;
+  msg.Append("debug-tag,%s\n", call_site_tag);
+  msg.WriteToLogFile();
 #endif
 }
 
 
 void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log) return;
   StringBuilder s(parameter.length() + 1);
   for (int i = 0; i < parameter.length(); ++i) {
     s.AddCharacter(static_cast<char>(parameter[i]));
   }
   char* parameter_string = s.Finalize();
-  ScopedLock sl(mutex_);
-  fprintf(logfile_,
-          "debug-queue-event,%s,%15.3f,%s\n",
-          event_type,
-          OS::TimeCurrentMillis(),
-          parameter_string);
+  LogMessageBuilder msg;
+  msg.Append("debug-queue-event,%s,%15.3f,%s\n",
+             event_type,
+             OS::TimeCurrentMillis(),
+             parameter_string);
   DeleteArray(parameter_string);
+  msg.WriteToLogFile();
 #endif
 }
 
 
 #ifdef ENABLE_LOGGING_AND_PROFILING
 void Logger::TickEvent(TickSample* sample, bool overflow) {
   if (logfile_ == NULL || !FLAG_prof) return;
-  ScopedLock sl(mutex_);
-  fprintf(logfile_, "tick,0x%x,0x%x,%d", sample->pc, sample->sp,
-          static_cast<int>(sample->state));
-  if (overflow) fprintf(logfile_, ",overflow");
-  fprintf(logfile_, "\n");
+  LogMessageBuilder msg;
+  msg.Append("tick,0x%x,0x%x,%d", sample->pc, sample->sp,
+             static_cast<int>(sample->state));
+  if (overflow) {
+    msg.Append(",overflow");
+  }
+  msg.Append('\n');
+  msg.WriteToLogFile();
 }
 
 
 bool Logger::IsProfilerPaused() {
   return profiler_->paused();
 }
 
 
 void Logger::PauseProfiler() {
   profiler_->pause();
 }
 
 
 void Logger::ResumeProfiler() {
   profiler_->resume();
 }
 #endif
 
 
 bool Logger::Setup() {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   // --log-all enables all the log flags.
   if (FLAG_log_all) {
+    FLAG_log_runtime = true;
     FLAG_log_api = true;
     FLAG_log_code = true;
     FLAG_log_gc = true;
     FLAG_log_suspect = true;
     FLAG_log_handles = true;
     FLAG_log_regexp = true;
   }
 
   // --prof implies --log-code.
   if (FLAG_prof) FLAG_log_code = true;
 
-  bool open_log_file = FLAG_log || FLAG_log_api || FLAG_log_code
-      || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
+  bool open_log_file = 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;
 
   // If we're logging anything, we need to open the log file.
   if (open_log_file) {
     if (strcmp(FLAG_logfile, "-") == 0) {
       logfile_ = stdout;
     } else if (strchr(FLAG_logfile, '%') != NULL) {
       // If there's a '%' in the log file name we have to expand
       // placeholders.
       HeapStringAllocator allocator;
@@ skipping 146 matching lines @@
   if (FLAG_log_state_changes) {
     LOG(UncheckedStringEvent("Leaving", StateToString(state_)));
     if (previous_) {
       LOG(UncheckedStringEvent("To", StateToString(previous_->state_)));
     }
   }
 }
 #endif
 
 } }  // namespace v8::internal