Add log compression ability.

This is a trivial per-row compression:
- short aliases are introduced for events and code creation tags;
- in tick events, offsets are used instead of absolute addresses;
- removed 'code-allocation' event, as it seems not used.

The first two options are depend on the new flag: 'compress-log', which is off by default.

On benchmarks run w/o snapshot, this gives 45% log size reduction.

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


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

src/builtins.cc

@@ -720,7 +720,8 @@ void Builtins::Setup(bool create_heap_objects) {
       // bootstrapper.
       Bootstrapper::AddFixup(Code::cast(code), &masm);
       // Log the event and add the code to the builtins array.
-      LOG(CodeCreateEvent("Builtin", Code::cast(code), functions[i].s_name));
+      LOG(CodeCreateEvent(Logger::BUILTIN_TAG,
+                          Code::cast(code), functions[i].s_name));
       builtins_[i] = code;
 #ifdef ENABLE_DISASSEMBLER
       if (FLAG_print_builtin_code) {

src/code-stubs.cc

@@ -66,7 +66,7 @@ Handle<Code> CodeStub::GetCode() {
     // Add unresolved entries in the code to the fixup list.
     Bootstrapper::AddFixup(*code, &masm);
 
-    LOG(CodeCreateEvent("Stub", *code, GetName()));
+    LOG(CodeCreateEvent(Logger::STUB_TAG, *code, GetName()));
     Counters::total_stubs_code_size.Increment(code->instruction_size());
 
 #ifdef ENABLE_DISASSEMBLER

src/codegen.cc

@@ -302,7 +302,7 @@ Handle<JSFunction> CodeGenerator::BuildBoilerplate(FunctionLiteral* node) {
     }
 
     // Function compilation complete.
-    LOG(CodeCreateEvent("Function", *code, *node->name()));
+    LOG(CodeCreateEvent(Logger::FUNCTION_TAG, *code, *node->name()));
 
 #ifdef ENABLE_OPROFILE_AGENT
     OProfileAgent::CreateNativeCodeRegion(*node->name(),

src/compiler.cc

@@ -179,11 +179,13 @@ static Handle<JSFunction> MakeFunction(bool is_global,
     if (script->name()->IsString()) {
       SmartPointer<char> data =
           String::cast(script->name())->ToCString(DISALLOW_NULLS);
-      LOG(CodeCreateEvent(is_eval ? "Eval" : "Script", *code, *data));
+      LOG(CodeCreateEvent(is_eval ? Logger::EVAL_TAG : Logger::SCRIPT_TAG,
+                          *code, *data));
       OProfileAgent::CreateNativeCodeRegion(*data, code->address(),
                                             code->ExecutableSize());
     } else {
-      LOG(CodeCreateEvent(is_eval ? "Eval" : "Script", *code, ""));
+      LOG(CodeCreateEvent(is_eval ? Logger::EVAL_TAG : Logger::SCRIPT_TAG,
+                          *code, ""));
       OProfileAgent::CreateNativeCodeRegion(is_eval ? "Eval" : "Script",
           code->address(), code->ExecutableSize());
     }
@@ -380,14 +382,14 @@ bool Compiler::CompileLazy(Handle<SharedFunctionInfo> shared,
       if (line_num > 0) {
         line_num += script->line_offset()->value() + 1;
       }
-      LOG(CodeCreateEvent("LazyCompile", *code, *func_name,
+      LOG(CodeCreateEvent(Logger::LAZY_COMPILE_TAG, *code, *func_name,
                           String::cast(script->name()), line_num));
       OProfileAgent::CreateNativeCodeRegion(*func_name,
                                             String::cast(script->name()),
                                             line_num, code->address(),
                                             code->ExecutableSize());
     } else {
-      LOG(CodeCreateEvent("LazyCompile", *code, *func_name));
+      LOG(CodeCreateEvent(Logger::LAZY_COMPILE_TAG, *code, *func_name));
       OProfileAgent::CreateNativeCodeRegion(*func_name, code->address(),
                                             code->ExecutableSize());
     }

src/flag-definitions.h

@@ -332,6 +332,8 @@ DEFINE_bool(log_gc, false,
 DEFINE_bool(log_handles, false, "Log global handle events.")
 DEFINE_bool(log_state_changes, false, "Log state changes.")
 DEFINE_bool(log_suspect, false, "Log suspect operations.")
+DEFINE_bool(compress_log, false,
+            "Compress log to save space (makes log less human-readable).")
 DEFINE_bool(prof, false,
             "Log statistical profiling information (implies --log-code).")
 DEFINE_bool(prof_auto, true,

src/heap.cc

@@ -1766,7 +1766,6 @@ Object* Heap::CreateCode(const CodeDesc& desc,
   // through the self_reference parameter.
   code->CopyFrom(desc);
   if (sinfo != NULL) sinfo->Serialize(code);  // write scope info
-  LOG(CodeAllocateEvent(code, desc.origin));
 
 #ifdef DEBUG
   code->Verify();

src/ia32/assembler-ia32.cc

@@ -117,7 +117,8 @@ void CpuFeatures::Probe() {
   Object* code =
       Heap::CreateCode(desc, NULL, Code::ComputeFlags(Code::STUB), NULL);
   if (!code->IsCode()) return;
-  LOG(CodeCreateEvent("Builtin", Code::cast(code), "CpuFeatures::Probe"));
+  LOG(CodeCreateEvent(Logger::BUILTIN_TAG,
+                      Code::cast(code), "CpuFeatures::Probe"));
   typedef uint64_t (*F0)();
   F0 probe = FUNCTION_CAST<F0>(Code::cast(code)->entry());
   supported_ = probe();

src/log.cc

@@ -262,6 +262,7 @@ void Profiler::Engage() {
   Logger::ticker_->SetProfiler(this);
 
   Logger::ProfilerBeginEvent();
+  Logger::LogAliases();
 }
 
 
@@ -301,6 +302,19 @@ Profiler* Logger::profiler_ = NULL;
 VMState* Logger::current_state_ = NULL;
 VMState Logger::bottom_state_(EXTERNAL);
 SlidingStateWindow* Logger::sliding_state_window_ = NULL;
+const char** Logger::log_events_ = NULL;
+
+#define DECLARE_LONG_EVENT(ignore1, long_name, ignore2) long_name,
+const char* kLongLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
+  LOG_EVENTS_AND_TAGS_LIST(DECLARE_LONG_EVENT)
+};
+#undef DECLARE_LONG_EVENT
+
+#define DECLARE_SHORT_EVENT(ignore1, ignore2, short_name) short_name,
+const char* kCompressedLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
+  LOG_EVENTS_AND_TAGS_LIST(DECLARE_SHORT_EVENT)
+};
+#undef DECLARE_SHORT_EVENT
 
 
 bool Logger::IsEnabled() {
@@ -315,6 +329,17 @@ void Logger::ProfilerBeginEvent() {
   msg.WriteToLogFile();
 }
 
+
+void Logger::LogAliases() {
+  if (!Log::IsEnabled() || !FLAG_compress_log) return;
+  LogMessageBuilder msg;
+  for (int i = 0; i < NUMBER_OF_LOG_EVENTS; ++i) {
+    msg.Append("alias,%s,%s\n",
+               kCompressedLogEventsNames[i], kLongLogEventsNames[i]);
+  }
+  msg.WriteToLogFile();
+}
+
 #endif  // ENABLE_LOGGING_AND_PROFILING
 
 
@@ -594,12 +619,15 @@ void Logger::DeleteEvent(const char* name, void* object) {
 }
 
 
-void Logger::CodeCreateEvent(const char* tag, Code* code, const char* comment) {
+void Logger::CodeCreateEvent(LogEventsAndTags tag,
+                             Code* code,
+                             const char* comment) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (!Log::IsEnabled() || !FLAG_log_code) return;
   LogMessageBuilder msg;
-  msg.Append("code-creation,%s,0x%" V8PRIxPTR ",%d,\"", tag, code->address(),
-             code->ExecutableSize());
+  msg.Append("%s,%s,0x%" V8PRIxPTR ",%d,\"",
+             log_events_[CODE_CREATION_EVENT], log_events_[tag],
+             code->address(), code->ExecutableSize());
   for (const char* p = comment; *p != '\0'; p++) {
     if (*p == '"') {
       msg.Append('\\');
@@ -613,20 +641,22 @@ void Logger::CodeCreateEvent(const char* tag, Code* code, const char* comment) {
 }
 
 
-void Logger::CodeCreateEvent(const char* tag, Code* code, String* name) {
+void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, String* name) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (!Log::IsEnabled() || !FLAG_log_code) return;
   LogMessageBuilder msg;
   SmartPointer<char> str =
       name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
-  msg.Append("code-creation,%s,0x%" V8PRIxPTR ",%d,\"%s\"\n",
-             tag, code->address(), code->ExecutableSize(), *str);
+  msg.Append("%s,%s,0x%" V8PRIxPTR ",%d,\"%s\"\n",
+             log_events_[CODE_CREATION_EVENT], log_events_[tag],
+             code->address(), code->ExecutableSize(), *str);
   msg.WriteToLogFile();
 #endif
 }
 
 
-void Logger::CodeCreateEvent(const char* tag, Code* code, String* name,
+void Logger::CodeCreateEvent(LogEventsAndTags tag,
+                             Code* code, String* name,
                              String* source, int line) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (!Log::IsEnabled() || !FLAG_log_code) return;
@@ -635,8 +665,9 @@ void Logger::CodeCreateEvent(const char* tag, Code* code, String* name,
       name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
   SmartPointer<char> sourcestr =
       source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
-  msg.Append("code-creation,%s,0x%" V8PRIxPTR ",%d,\"%s %s:%d\"\n",
-             tag, code->address(),
+  msg.Append("%s,%s,0x%" V8PRIxPTR ",%d,\"%s %s:%d\"\n",
+             log_events_[CODE_CREATION_EVENT],
+             log_events_[tag], code->address(),
              code->ExecutableSize(),
              *str, *sourcestr, line);
   msg.WriteToLogFile();
@@ -644,11 +675,13 @@ void Logger::CodeCreateEvent(const char* tag, Code* code, String* name,
 }
 
 
-void Logger::CodeCreateEvent(const char* tag, Code* code, int args_count) {
+void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (!Log::IsEnabled() || !FLAG_log_code) return;
   LogMessageBuilder msg;
-  msg.Append("code-creation,%s,0x%" V8PRIxPTR ",%d,\"args_count: %d\"\n", tag,
+  msg.Append("%s,%s,0x%" V8PRIxPTR ",%d,\"args_count: %d\"\n",
+             log_events_[CODE_CREATION_EVENT],
+             log_events_[tag],
              code->address(),
              code->ExecutableSize(),
              args_count);
@@ -661,7 +694,9 @@ void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (!Log::IsEnabled() || !FLAG_log_code) return;
   LogMessageBuilder msg;
-  msg.Append("code-creation,%s,0x%" V8PRIxPTR ",%d,\"", "RegExp",
+  msg.Append("%s,%s,0x%" V8PRIxPTR ",%d,\"",
+             log_events_[CODE_CREATION_EVENT],
+             log_events_[REG_EXP_TAG],
              code->address(),
              code->ExecutableSize());
   msg.AppendDetailed(source, false);
@@ -671,23 +706,12 @@ void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
 }
 
 
-void Logger::CodeAllocateEvent(Code* code, Assembler* assem) {
-#ifdef ENABLE_LOGGING_AND_PROFILING
-  if (!Log::IsEnabled() || !FLAG_log_code) return;
-  LogMessageBuilder msg;
-  msg.Append("code-allocate,0x%" V8PRIxPTR ",0x%" V8PRIxPTR "\n",
-             code->address(),
-             assem);
-  msg.WriteToLogFile();
-#endif
-}
-
-
 void Logger::CodeMoveEvent(Address from, Address to) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (!Log::IsEnabled() || !FLAG_log_code) return;
   LogMessageBuilder msg;
-  msg.Append("code-move,0x%" V8PRIxPTR ",0x%" V8PRIxPTR "\n", from, to);
+  msg.Append("%s,0x%" V8PRIxPTR ",0x%" V8PRIxPTR "\n",
+             log_events_[CODE_MOVE_EVENT], from, to);
   msg.WriteToLogFile();
 #endif
 }
@@ -697,7 +721,7 @@ void Logger::CodeDeleteEvent(Address from) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (!Log::IsEnabled() || !FLAG_log_code) return;
   LogMessageBuilder msg;
-  msg.Append("code-delete,0x%" V8PRIxPTR "\n", from);
+  msg.Append("%s,0x%" V8PRIxPTR "\n", log_events_[CODE_DELETE_EVENT], from);
   msg.WriteToLogFile();
 #endif
 }
@@ -803,13 +827,26 @@ void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
 void Logger::TickEvent(TickSample* sample, bool overflow) {
   if (!Log::IsEnabled() || !FLAG_prof) return;
   LogMessageBuilder msg;
-  msg.Append("tick,0x%" V8PRIxPTR ",0x%" V8PRIxPTR ",%d",
+  msg.Append("%s,0x%" V8PRIxPTR ",0x%" V8PRIxPTR ",%d",
+             log_events_[TICK_EVENT],
              sample->pc, sample->sp, static_cast<int>(sample->state));
   if (overflow) {
     msg.Append(",overflow");
   }
+  uintptr_t prev_ptr = sample->pc;
   for (int i = 0; i < sample->frames_count; ++i) {
-    msg.Append(",0x%" V8PRIxPTR, sample->stack[i]);
+    if (FLAG_compress_log) {
+      const uintptr_t ptr = OffsetFrom(sample->stack[i]);
+      intptr_t delta = ptr - prev_ptr;
+      prev_ptr = ptr;
+      // To avoid printing negative offsets in an unsigned form,
+      // we are printing an absolute value with a sign.
+      const char sign = delta >= 0 ? '+' : '-';
+      if (sign == '-') { delta = -delta; }
+      msg.Append(",%c0x%" V8PRIxPTR, sign, delta);
+    } else {
+      msg.Append(",0x%" V8PRIxPTR, sample->stack[i]);
+    }
   }
   msg.Append('\n');
   msg.WriteToLogFile();
@@ -913,17 +950,19 @@ void Logger::LogCompiledFunctions() {
         int line_num = GetScriptLineNumber(script, shared->start_position());
         if (line_num > 0) {
           line_num += script->line_offset()->value() + 1;
-          LOG(CodeCreateEvent("LazyCompile", shared->code(), *func_name,
+          LOG(CodeCreateEvent(Logger::LAZY_COMPILE_TAG,
+                              shared->code(), *func_name,
                               *script_name, line_num));
         } else {
           // Can't distinguish enum and script here, so always use Script.
-          LOG(CodeCreateEvent("Script", shared->code(), *script_name));
+          LOG(CodeCreateEvent(Logger::SCRIPT_TAG,
+                              shared->code(), *script_name));
         }
         continue;
       }
     }
     // If no script or script has no name.
-    LOG(CodeCreateEvent("LazyCompile", shared->code(), *func_name));
+    LOG(CodeCreateEvent(Logger::LAZY_COMPILE_TAG, shared->code(), *func_name));
   }
 
   DeleteArray(sfis);
@@ -1022,6 +1061,9 @@ bool Logger::Setup() {
 
   LogMessageBuilder::set_write_failure_handler(StopLoggingAndProfiling);
 
+  log_events_ = FLAG_compress_log ?
+      kCompressedLogEventsNames : kLongLogEventsNames;
+
   return true;
 
 #else

src/log.h

@@ -102,8 +102,40 @@ class VMState BASE_EMBEDDED {
 };
 
 
+#define LOG_EVENTS_AND_TAGS_LIST(V) \
+  V(CODE_CREATION_EVENT,            "code-creation",          "cc")       \
+  V(CODE_MOVE_EVENT,                "code-move",              "cm")       \
+  V(CODE_DELETE_EVENT,              "code-delete",            "cd")       \
+  V(TICK_EVENT,                     "tick",                   "t")        \
+  V(BUILTIN_TAG,                    "Builtin",                "bi")       \
+  V(CALL_DEBUG_BREAK_TAG,           "CallDebugBreak",         "cdb")      \
+  V(CALL_DEBUG_PREPARE_STEP_IN_TAG, "CallDebugPrepareStepIn", "cdbsi")    \
+  V(CALL_IC_TAG,                    "CallIC",                 "cic")      \
+  V(CALL_INITIALIZE_TAG,            "CallInitialize",         "ci")       \
+  V(CALL_MEGAMORPHIC_TAG,           "CallMegamorphic",        "cmm")      \
+  V(CALL_MISS_TAG,                  "CallMiss",               "cm")       \
+  V(CALL_NORMAL_TAG,                "CallNormal",             "cn")       \
+  V(CALL_PRE_MONOMORPHIC_TAG,       "CallPreMonomorphic",     "cpm")      \
+  V(EVAL_TAG,                       "Eval",                   "e")        \
+  V(FUNCTION_TAG,                   "Function",               "f")        \
+  V(KEYED_LOAD_IC_TAG,              "KeyedLoadIC",            "klic")     \
+  V(KEYED_STORE_IC_TAG,             "KeyedStoreIC",           "ksic")     \
+  V(LAZY_COMPILE_TAG,               "LazyCompile",            "lc")       \
+  V(LOAD_IC_TAG,                    "LoadIC",                 "lic")      \
+  V(REG_EXP_TAG,                    "RegExp",                 "re")       \
+  V(SCRIPT_TAG,                     "Script",                 "sc")       \
+  V(STORE_IC_TAG,                   "StoreIC",                "sic")      \
+  V(STUB_TAG,                       "Stub",                   "s")
+
 class Logger {
  public:
+#define DECLARE_ENUM(enum_item, ignore1, ignore2) enum_item,
+  enum LogEventsAndTags {
+    LOG_EVENTS_AND_TAGS_LIST(DECLARE_ENUM)
+    NUMBER_OF_LOG_EVENTS
+  };
+#undef DECLARE_ENUM
+
   // Acquires resources for logging if the right flags are set.
   static bool Setup();
 
@@ -163,14 +195,14 @@ class Logger {
 
   // ==== Events logged by --log-code. ====
   // Emits a code create event.
-  static void CodeCreateEvent(const char* tag, Code* code, const char* source);
-  static void CodeCreateEvent(const char* tag, Code* code, String* name);
-  static void CodeCreateEvent(const char* tag, Code* code, String* name,
+  static void CodeCreateEvent(LogEventsAndTags tag,
+                              Code* code, const char* source);
+  static void CodeCreateEvent(LogEventsAndTags tag, Code* code, String* name);
+  static void CodeCreateEvent(LogEventsAndTags tag, Code* code, String* name,
                               String* source, int line);
-  static void CodeCreateEvent(const char* tag, Code* code, int args_count);
+  static void CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count);
   // Emits a code create event for a RegExp.
   static void RegExpCodeCreateEvent(Code* code, String* source);
-  static void CodeAllocateEvent(Code* code, Assembler* assem);
   // Emits a code move event.
   static void CodeMoveEvent(Address from, Address to);
   // Emits a code delete event.
@@ -226,6 +258,9 @@ class Logger {
   // Emits the profiler's first message.
   static void ProfilerBeginEvent();
 
+  // Emits aliases for compressed messages.
+  static void LogAliases();
+
   // Emits the source code of a regexp. Used by regexp events.
   static void LogRegExpSource(Handle<JSRegExp> regexp);
 
@@ -261,6 +296,9 @@ class Logger {
   // recent VM states.
   static SlidingStateWindow* sliding_state_window_;
 
+  // An array of log events names.
+  static const char** log_events_;
+
   // Internal implementation classes with access to
   // private members.
   friend class EventLog;

src/x64/assembler-x64.cc

@@ -140,7 +140,8 @@ void CpuFeatures::Probe()  {
   Object* code =
       Heap::CreateCode(desc, NULL, Code::ComputeFlags(Code::STUB), NULL);
   if (!code->IsCode()) return;
-  LOG(CodeCreateEvent("Builtin", Code::cast(code), "CpuFeatures::Probe"));
+  LOG(CodeCreateEvent(Logger::BUILTIN_TAG,
+                      Code::cast(code), "CpuFeatures::Probe"));
   typedef uint64_t (*F0)();
   F0 probe = FUNCTION_CAST<F0>(Code::cast(code)->entry());
   supported_ = probe();

tools/tickprocessor.js

@@ -86,6 +86,7 @@ function TickProcessor(
   // Count each tick as a time unit.
   this.viewBuilder_ = new devtools.profiler.ViewBuilder(1);
   this.lastLogFileName_ = null;
+  this.aliases_ = {};
 };
 
 
@@ -116,6 +117,7 @@ TickProcessor.RecordsDispatch = {
   'code-delete': { parsers: [parseInt], processor: 'processCodeDelete' },
   'tick': { parsers: [parseInt, parseInt, parseInt, 'var-args'],
             processor: 'processTick' },
+  'alias': { parsers: [null, null], processor: 'processAlias' },
   'profiler': null,
   // Obsolete row types.
   'code-allocate': null,
@@ -123,7 +125,6 @@ TickProcessor.RecordsDispatch = {
   'end-code-region': null
 };
 
-
 TickProcessor.CALL_PROFILE_CUTOFF_PCT = 2.0;
 
 
@@ -218,8 +219,21 @@ TickProcessor.prototype.processSharedLibrary = function(
 };
 
 
+TickProcessor.prototype.processAlias = function(symbol, expansion) {
+  if (expansion in TickProcessor.RecordsDispatch) {
+    TickProcessor.RecordsDispatch[symbol] =
+      TickProcessor.RecordsDispatch[expansion];
+  } else {
+    this.aliases_[symbol] = expansion;
+  }
+};
+
+
 TickProcessor.prototype.processCodeCreation = function(
     type, start, size, name) {
+  if (type in this.aliases_) {
+    type = this.aliases_[type];
+  }
   var entry = this.profile_.addCode(type, name, start, size);
 };
 
@@ -248,11 +262,17 @@ TickProcessor.prototype.processTick = function(pc, sp, vmState, stack) {
   }
 
   var fullStack = [pc];
+  var prevFrame = pc;
   for (var i = 0, n = stack.length; i < n; ++i) {
     var frame = stack[i];
+    var firstChar = frame.charAt(0);
     // Leave only numbers starting with 0x. Filter possible 'overflow' string.
-    if (frame.charAt(0) == '0') {
+    if (firstChar == '0') {
       fullStack.push(parseInt(frame, 16));
+    } else if (firstChar == '+' || firstChar == '-') {
+      // An offset from the previous frame.
+      prevFrame += parseInt(frame, 16);
+      fullStack.push(prevFrame);
     }
   }
   this.profile_.recordTick(fullStack);