Implement tick events compression in a log file.

src/log-utils.cc

 // Copyright 2009 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 109 matching lines @@
 
 
 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;
+LogRecordCompressor* Log::record_compressor_ = NULL;
 
 
 void Log::Init() {
   mutex_ = OS::CreateMutex();
   message_buffer_ = NewArray<char>(kMessageBufferSize);
+  if (FLAG_compress_log) {
+    record_compressor_ = new LogRecordCompressor(kRecordCompressorWindow);
+  }
 }
 
 
 void Log::OpenStdout() {
   ASSERT(!IsEnabled());
   output_handle_ = stdout;
   Write = WriteToFile;
   Init();
 }
 
@@ skipping 21 matching lines @@
     fclose(output_handle_);
     output_handle_ = NULL;
   } else if (Write == WriteToMemory) {
     delete output_buffer_;
     output_buffer_ = NULL;
   } else {
     ASSERT(Write == NULL);
   }
   Write = NULL;
 
+  delete record_compressor_;
+  record_compressor_ = NULL;
+
+  DeleteArray(message_buffer_);
+  message_buffer_ = NULL;
+
   delete mutex_;
   mutex_ = NULL;
 
   is_stopped_ = false;
 }
 
 
 int Log::GetLogLines(int from_pos, char* dest_buf, int max_size) {
   if (Write != WriteToMemory) return 0;
   ASSERT(output_buffer_ != NULL);
@@ skipping 87 matching lines @@
       Append("\\,");
     } else if (c == '\\') {
       Append("\\\\");
     } else {
       Append("%lc", c);
     }
   }
 }
 
 
+bool LogMessageBuilder::StoreInCompressor() {
+  if (!FLAG_compress_log) return true;
+  ASSERT(Log::record_compressor_ != NULL);
+  return Log::record_compressor_->Store(
+      Vector<const char>(Log::message_buffer_, pos_));
+}
+
+
+bool LogMessageBuilder::RetrieveCompressedPrevious(const char* prefix) {
+  if (!FLAG_compress_log) return true;
+  ASSERT(Log::record_compressor_ != NULL);
+  pos_ = 0;
+  if (prefix[0] != '\0') Append(prefix);
+  Vector<char> prev_record(Log::message_buffer_ + pos_,
+                           Log::kMessageBufferSize - pos_);
+  const bool has_previous =
+      Log::record_compressor_->RetrievePreviousCompressed(&prev_record);
+  if (!has_previous) return false;
+  pos_ += prev_record.length();
+  return true;
+}
+
+
 void LogMessageBuilder::WriteToLogFile() {
   ASSERT(pos_ <= Log::kMessageBufferSize);
   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) {
   const int len = strlen(str);
   const int written = Log::Write(str, len);
   if (written != len && write_failure_handler != NULL) {
     write_failure_handler();
   }
 }
 
+
+// Formatting string for back references. E.g. "#2:4" means
+// "the second line above, start from the 4th field (0-based)".
+const char* LogRecordCompressor::kBackwardReferenceFormat = "#%d:%d";
+
+
+LogRecordCompressor::~LogRecordCompressor() {
+  for (int i = 0; i < buffer_.length(); ++i) {
+    buffer_[i].Dispose();
+  }
+}
+
+
+bool LogRecordCompressor::Store(const Vector<const char>& record) {
+  // Check if the record is the same as the last stored one.
+  if (curr_ != -1) {
+    Vector<const char>& curr = buffer_[curr_];
+    if (record.length() == curr.length()
+        && strncmp(record.start(), curr.start(), record.length()) == 0) {
+      return false;
+    }
+  }
+  prev_ = curr_++;

[Søren Thygesen Gjesse, 2009/06/11 11:13:56]

Maybe add a comment here saying that we keep a circular bufer of the
kRecordCompressorWindow last records.

[Mikhail Naganov, 2009/06/11 14:07:12]

Done.

+  curr_ %= buffer_.length();
+  Vector<char> record_copy = Vector<char>::New(record.length());
+  memcpy(record_copy.start(), record.start(), record.length());
+  buffer_[curr_].Dispose();
+  buffer_[curr_] =
+      Vector<const char>(record_copy.start(), record_copy.length());
+  return true;
+}
+
+
+bool LogRecordCompressor::RetrievePreviousCompressed(
+    Vector<char>* prev_record) {
+  if (prev_ == -1) return false;
+
+  int index = prev_;
+  // Distance from prev_.
+  int distance = 0;
+  // Best compression result among records in the buffer.
+  struct {
+    intptr_t truncated_len;
+    int distance;
+    int field_num;
+  } best = {-1, 0, 0};
+  Vector<const char>& prev = buffer_[prev_];
+  const char* const prev_end = prev.start() + prev.length();
+  do {
+    // We're moving backwards until we reach the current record.
+    if (--index == -1) index = buffer_.length() - 1;
+    ++distance;
+    if (index == curr_) break;
+
+    Vector<const char>& data = buffer_[index];
+    if (data.start() == NULL) break;
+    const char* const data_end = data.start() + data.length();
+    const char* prev_ptr = prev_end;
+    const char* data_ptr = data_end;
+    // Compare strings backwards, stop on the last matching character.

[Søren Thygesen Gjesse, 2009/06/11 11:13:56]

I am not sure how expensive this is, but perhaps comparing 4 chars at a time
using a uint32_t pointer instead of a char pointer can make a difference, even
though there is the edge case of moving to the first 4 byte aligned char.

[Mikhail Naganov, 2009/06/11 14:07:12]

I'm aware of this optimization, but don't want to introduce it. This code runs
in a separate thread, so it doesn't affect V8's performance.

+    while (prev_ptr != prev.start() && data_ptr != data.start()
+          && *(prev_ptr - 1) == *(data_ptr - 1)) {
+      --prev_ptr;
+      --data_ptr;
+    }
+    if (prev_end - prev_ptr < kUncompressibleBound) continue;
+
+    // Align to the field boundary.
+    do {
+      ++prev_ptr;
+      ++data_ptr;
+    } while (prev_ptr != prev_end
+             && (prev_ptr != prev.start() && *(prev_ptr - 1) != kFieldSeparator

[Søren Thygesen Gjesse, 2009/06/11 11:13:56]

Will prev_ptr ever become prev.start() as the do loop starts by incrementing
prev_ptr? Maybe assert that instead.

[Mikhail Naganov, 2009/06/11 14:07:12]

I've removed field alignment, so this code has gone.

+                 || data_ptr != data.start()
+                 && *(data_ptr - 1) != kFieldSeparator));
+    // Check if the record is still compressible.
+    const intptr_t truncated_len = prev_end - prev_ptr;
+    if (truncated_len < kUncompressibleBound) continue;
+
+    // Determine reference field number.
+    int field_num = 0;
+    for (const char* fld_ptr = data.start();
+         fld_ptr != data_ptr; ++fld_ptr) {
+      if (*fld_ptr == kFieldSeparator) field_num++;
+    }
+    // Record compression results.
+    if (truncated_len > best.truncated_len) {
+      best.truncated_len = truncated_len;
+      best.distance = distance;
+      best.field_num = field_num;
+    }
+  } while (true);
+
+  if (best.distance == 0) {
+    // Can't compress the previous record. Return as is.
+    ASSERT(prev_record->length() >= prev.length());
+    memcpy(prev_record->start(), prev.start(), prev.length());
+    prev_record->Truncate(prev.length());
+  } else {
+    // Copy the uncompressible part unchanged.
+    const intptr_t unchanged_len = prev.length() - best.truncated_len;
+    ASSERT(prev_record->length() >= unchanged_len + kUncompressibleBound);
+    memcpy(prev_record->start(), prev.start(), unchanged_len);
+    // Append the backward reference.
+    Vector<char> patch(prev_record->start() + unchanged_len,
+                       kUncompressibleBound);
+    OS::SNPrintF(patch, kBackwardReferenceFormat,
+                 best.distance, best.field_num);
+    prev_record->Truncate(unchanged_len + strlen(patch.start()));
+  }
+  return true;
+}
+
 #endif  // ENABLE_LOGGING_AND_PROFILING
 
 } }  // namespace v8::internal