Handle filling up of memory buffer to make log processing in DevTools Profiler easier.

When profiler's memory buffer is filled up, profiling is stopped and it is ensured that the last record in the buffer is "profiler,\"pause\"" thus making the end of profiling session explicit. Otherwise DevTools Profiler would need to guess whether the current profiling session has been stopped.

Tested with Chromium.

Review URL: http://codereview.chromium.org/115859


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

src/log-utils.cc

@@ -34,11 +34,14 @@ namespace internal {
 
 #ifdef ENABLE_LOGGING_AND_PROFILING
 
-LogDynamicBuffer::LogDynamicBuffer(int block_size, int max_size)
+LogDynamicBuffer::LogDynamicBuffer(
+    int block_size, int max_size, const char* seal, int seal_size)
     : block_size_(block_size),
       max_size_(max_size - (max_size % block_size_)),
+      seal_(seal),
+      seal_size_(seal_size),
       blocks_(max_size_ / block_size_ + 1),
-      write_pos_(0), block_index_(0), block_write_pos_(0) {
+      write_pos_(0), block_index_(0), block_write_pos_(0), is_sealed_(false) {
   ASSERT(BlocksCount() > 0);
   AllocateBlock(0);
   for (int i = 1; i < BlocksCount(); ++i) {
@@ -78,8 +81,26 @@ int LogDynamicBuffer::Read(int from_pos, char* dest_buf, int buf_size) {
 }
 
 
+int LogDynamicBuffer::Seal() {
+  WriteInternal(seal_, seal_size_);
+  is_sealed_ = true;
+  return 0;
+}
+
+
 int LogDynamicBuffer::Write(const char* data, int data_size) {
-  if ((write_pos_ + data_size) > max_size_) return 0;
+  if (is_sealed_) {
+    return 0;
+  }
+  if ((write_pos_ + data_size) <= (max_size_ - seal_size_)) {
+    return WriteInternal(data, data_size);
+  } else {
+    return Seal();
+  }
+}
+
+
+int LogDynamicBuffer::WriteInternal(const char* data, int data_size) {
   int data_pos = 0;
   while (data_pos < data_size) {
     const int write_size =
@@ -98,9 +119,12 @@ int LogDynamicBuffer::Write(const char* data, int data_size) {
 }
 
 
+bool Log::is_stopped_ = false;
 Log::WritePtr Log::Write = NULL;
 FILE* Log::output_handle_ = NULL;
 LogDynamicBuffer* Log::output_buffer_ = NULL;
+// Must be the same message as in Logger::PauseProfiler
+const char* Log::kDynamicBufferSeal = "profiler,\"pause\"\n";
 Mutex* Log::mutex_ = NULL;
 char* Log::message_buffer_ = NULL;
 
@@ -130,7 +154,8 @@ void Log::OpenFile(const char* name) {
 void Log::OpenMemoryBuffer() {
   ASSERT(!IsEnabled());
   output_buffer_ = new LogDynamicBuffer(
-      kDynamicBufferBlockSize, kMaxDynamicBufferSize);
+      kDynamicBufferBlockSize, kMaxDynamicBufferSize,
+      kDynamicBufferSeal, strlen(kDynamicBufferSeal));
   Write = WriteToMemory;
   Init();
 }
@@ -150,6 +175,8 @@ void Log::Close() {
 
   delete mutex_;
   mutex_ = NULL;
+
+  is_stopped_ = false;
 }
 
 
@@ -171,6 +198,10 @@ int Log::GetLogLines(int from_pos, char* dest_buf, int max_size) {
 }
 
 
+LogMessageBuilder::WriteFailureHandler
+    LogMessageBuilder::write_failure_handler = NULL;
+
+
 LogMessageBuilder::LogMessageBuilder(): sl(Log::mutex_), pos_(0) {
   ASSERT(Log::message_buffer_ != NULL);
 }
@@ -251,13 +282,19 @@ void LogMessageBuilder::AppendDetailed(String* str, bool show_impl_info) {
 
 void LogMessageBuilder::WriteToLogFile() {
   ASSERT(pos_ <= Log::kMessageBufferSize);
-  Log::Write(Log::message_buffer_, pos_);
+  const int written = Log::Write(Log::message_buffer_, pos_);
+  if (written != pos_ && write_failure_handler != NULL) {
+    write_failure_handler();
+  }
 }
 
 
 void LogMessageBuilder::WriteCStringToLogFile(const char* str) {
-  int len = strlen(str);
+  const int len = strlen(str);
-  Log::Write(str, len);
+  const int written = Log::Write(str, len);
+  if (written != len && write_failure_handler != NULL) {
+    write_failure_handler();
+  }
 }
 
 #endif  // ENABLE_LOGGING_AND_PROFILING

src/log-utils.h

@@ -35,12 +35,17 @@ namespace internal {
 
 // A memory buffer that increments its size as you write in it.  Size
 // is incremented with 'block_size' steps, never exceeding 'max_size'.
-// During growth, memory contents are never copied.
+// During growth, memory contents are never copied.  At the end of the
+// buffer an amount of memory specified in 'seal_size' is reserved.
+// When writing position reaches max_size - seal_size, buffer auto-seals
+// itself with 'seal' and allows no further writes. Data pointed by
+// 'seal' must be available during entire LogDynamicBuffer lifetime.
 //
 // An instance of this class is created dynamically by Log.
 class LogDynamicBuffer {
  public:
-  LogDynamicBuffer(int block_size, int max_size);
+  LogDynamicBuffer(
+      int block_size, int max_size, const char* seal, int seal_size);
 
   ~LogDynamicBuffer();
 
@@ -51,8 +56,9 @@ class LogDynamicBuffer {
 
   // Writes 'data' to the buffer, making it larger if necessary.  If
   // data is too big to fit in the buffer, it doesn't get written at
-  // all. Returns amount of data written (it is either 'data_size', or
+  // all. In that case, buffer auto-seals itself and stops to accept
-  // 0, if 'data' is too big).
+  // any incoming writes. Returns amount of data written (it is either
+  // 'data_size', or 0, if 'data' is too big).
   int Write(const char* data, int data_size);
 
  private:
@@ -66,12 +72,19 @@ class LogDynamicBuffer {
 
   int PosInBlock(int pos) const { return pos % block_size_; }
 
+  int Seal();
+
+  int WriteInternal(const char* data, int data_size);
+
   const int block_size_;
   const int max_size_;
+  const char* seal_;
+  const int seal_size_;
   ScopedVector<char*> blocks_;
   int write_pos_;
   int block_index_;
   int block_write_pos_;
+  bool is_sealed_;
 };
 
 
@@ -87,6 +100,9 @@ class Log : public AllStatic {
   // Opens memory buffer for logging.
   static void OpenMemoryBuffer();
 
+  // Disables logging, but preserves acquired resources.
+  static void stop() { is_stopped_ = true; }
+
   // Frees all resources acquired in Open... functions.
   static void Close();
 
@@ -95,7 +111,7 @@ class Log : public AllStatic {
 
   // Returns whether logging is enabled.
   static bool IsEnabled() {
-    return output_handle_ != NULL || output_buffer_ != NULL;
+    return !is_stopped_ && (output_handle_ != NULL || output_buffer_ != NULL);
   }
 
  private:
@@ -121,6 +137,9 @@ class Log : public AllStatic {
     return output_buffer_->Write(msg, length);
   }
 
+  // Whether logging is stopped (e.g. due to insufficient resources).
+  static bool is_stopped_;
+
   // When logging is active, either output_handle_ or output_buffer_ is used
   // to store a pointer to log destination. If logging was opened via OpenStdout
   // or OpenFile, then output_handle_ is used. If logging was opened
@@ -136,6 +155,9 @@ class Log : public AllStatic {
   // Maximum size of dynamic buffer.
   static const int kMaxDynamicBufferSize = 50 * 1024 * 1024;
 
+  // Message to "seal" dynamic buffer with.
+  static const char* kDynamicBufferSeal;
+
   // mutex_ is a Mutex used for enforcing exclusive
   // access to the formatting buffer and the log file or log memory buffer.
   static Mutex* mutex_;
@@ -180,7 +202,16 @@ class LogMessageBuilder BASE_EMBEDDED {
   // Write a null-terminated string to to the log file currently opened.
   void WriteCStringToLogFile(const char* str);
 
+  // A handler that is called when Log::Write fails.
+  typedef void (*WriteFailureHandler)();
+
+  static void set_write_failure_handler(WriteFailureHandler handler) {
+    write_failure_handler = handler;
+  }
+
  private:
+  static WriteFailureHandler write_failure_handler;
+
   ScopedLock sl;
   int pos_;
 };

src/log.cc

@@ -813,12 +813,14 @@ void Logger::PauseProfiler() {
   if (FLAG_prof_lazy) {
     if (!FLAG_sliding_state_window) ticker_->Stop();
     FLAG_log_code = false;
+    // Must be the same message as Log::kDynamicBufferSeal.
     LOG(UncheckedStringEvent("profiler", "pause"));
   }
 }
 
 
 void Logger::ResumeProfiler() {
+  if (!Log::IsEnabled()) return;
   if (FLAG_prof_lazy) {
     LOG(UncheckedStringEvent("profiler", "resume"));
     FLAG_log_code = true;
@@ -829,6 +831,14 @@ void Logger::ResumeProfiler() {
 }
 
 
+// This function can be called when Log's mutex is acquired,
+// either from main or Profiler's thread.
+void Logger::StopLoggingAndProfiling() {
+  Log::stop();
+  PauseProfiler();
+}
+
+
 bool Logger::IsProfilerSamplerActive() {
   return ticker_->IsActive();
 }
@@ -995,6 +1005,8 @@ bool Logger::Setup() {
     profiler_->Engage();
   }
 
+  LogMessageBuilder::set_write_failure_handler(StopLoggingAndProfiling);
+
   return true;
 
 #else
@@ -1005,6 +1017,8 @@ bool Logger::Setup() {
 
 void Logger::TearDown() {
 #ifdef ENABLE_LOGGING_AND_PROFILING
+  LogMessageBuilder::set_write_failure_handler(NULL);
+
   // Stop the profiler before closing the file.
   if (profiler_ != NULL) {
     profiler_->Disengage();

src/log.h

@@ -231,6 +231,9 @@ class Logger {
   // Logs a StringEvent regardless of whether FLAG_log is true.
   static void UncheckedStringEvent(const char* name, const char* value);
 
+  // Stops logging and profiling in case of insufficient resources.
+  static void StopLoggingAndProfiling();
+
   // Returns whether profiler's sampler is active.
   static bool IsProfilerSamplerActive();
 

test/cctest/test-log-utils.cc

@@ -37,12 +37,14 @@ static int ReadData(
 }
 
 
-// Helper function used by CHECK_EQ to compare Vectors.
+// Helper function used by CHECK_EQ to compare Vectors. Templatized to
+// accept both "char" and "const char" vector contents.
+template <typename E, typename V>
 static inline void CheckEqualsHelper(const char* file, int line,
                                      const char* expected_source,
-                                     const Vector<char>& expected,
+                                     const Vector<E>& expected,
                                      const char* value_source,
-                                     const Vector<char>& value) {
+                                     const Vector<V>& value) {
   if (expected.length() != value.length()) {
     V8_Fatal(file, line, "CHECK_EQ(%s, %s) failed\n"
              "#   Vectors lengths differ: %d expected, %d found",
@@ -62,7 +64,7 @@ static inline void CheckEqualsHelper(const char* file, int line,
 
 
 TEST(DynaBufSingleBlock) {
-  LogDynamicBuffer dynabuf(32, 32);
+  LogDynamicBuffer dynabuf(32, 32, "", 0);
   EmbeddedVector<char, 32> ref_buf;
   WriteData(&dynabuf, &ref_buf);
   EmbeddedVector<char, 32> buf;
@@ -77,7 +79,7 @@ TEST(DynaBufSingleBlock) {
 
 
 TEST(DynaBufCrossBlocks) {
-  LogDynamicBuffer dynabuf(32, 128);
+  LogDynamicBuffer dynabuf(32, 128, "", 0);
   EmbeddedVector<char, 48> ref_buf;
   WriteData(&dynabuf, &ref_buf);
   CHECK_EQ(48, dynabuf.Write(ref_buf.start(), ref_buf.length()));
@@ -93,7 +95,7 @@ TEST(DynaBufCrossBlocks) {
 
 
 TEST(DynaBufReadTruncation) {
-  LogDynamicBuffer dynabuf(32, 128);
+  LogDynamicBuffer dynabuf(32, 128, "", 0);
   EmbeddedVector<char, 128> ref_buf;
   WriteData(&dynabuf, &ref_buf);
   EmbeddedVector<char, 128> buf;
@@ -105,4 +107,26 @@ TEST(DynaBufReadTruncation) {
   CHECK_EQ(ref_buf.SubVector(128 - 32, 128), tail_buf.SubVector(0, 32));
 }
 
+
+TEST(DynaBufSealing) {
+  const char* seal = "Sealed";
+  const int seal_size = strlen(seal);
+  LogDynamicBuffer dynabuf(32, 128, seal, seal_size);
+  EmbeddedVector<char, 100> ref_buf;
+  WriteData(&dynabuf, &ref_buf);
+  // Try to write data that will not fit in the buffer.
+  CHECK_EQ(0, dynabuf.Write(ref_buf.start(), 128 - 100 - seal_size + 1));
+  // Now the buffer is sealed, writing of any amount of data is forbidden.
+  CHECK_EQ(0, dynabuf.Write(ref_buf.start(), 1));
+  EmbeddedVector<char, 100> buf;
+  CHECK_EQ(100, ReadData(&dynabuf, 0, &buf));
+  CHECK_EQ(ref_buf, buf);
+  // Check the seal.
+  EmbeddedVector<char, 50> seal_buf;
+  CHECK_EQ(seal_size, ReadData(&dynabuf, 100, &seal_buf));
+  CHECK_EQ(v8::internal::CStrVector(seal), seal_buf.SubVector(0, seal_size));
+  // Verify that there's no data beyond the seal.
+  CHECK_EQ(0, ReadData(&dynabuf, 100 + seal_size, &buf));
+}
+
 #endif  // ENABLE_LOGGING_AND_PROFILING