Fix issue 571: display descriptive names for code objects from snapshot.

As this is only needed for internal profiling (not for DevTools),
the following approach had been chosen:

 - during snapshot creation, positions of serialized objects inside
   a snapshot are logged;

 - then during V8 initialization, positions of deserealized objects
   are logged;

 - those positions are used for retrieving code objects names from
   snapshot creation log, which needs to be supplied to tick processor
   script.

Positions logging is controlled with the new flag: --log_snapshot_positions.
This flag is turned off by default, and this adds no startup penalty.

To plug this fix to Golem, the following actions are needed:

 - logs created using 'mksnapshot' need to be stored along with VM images;

 - tick processor script needs to be run with '--snapshot-log=...' cmdline
   argument.

BUG=571

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

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

src/SConscript

@@ -235,7 +235,7 @@ def ConfigureObjectFiles():
   env.Replace(**context.flags['v8'])
   context.ApplyEnvOverrides(env)
   env['BUILDERS']['JS2C'] = Builder(action=js2c.JS2C)
-  env['BUILDERS']['Snapshot'] = Builder(action='$SOURCE $TARGET --logfile "$LOGFILE"')
+  env['BUILDERS']['Snapshot'] = Builder(action='$SOURCE $TARGET --logfile "$LOGFILE" --log-snapshot-positions')
 
   # Build the standard platform-independent source files.
   source_files = context.GetRelevantSources(SOURCES)

src/flag-definitions.h

@@ -358,6 +358,8 @@ DEFINE_bool(log_code, false,
 DEFINE_bool(log_gc, false,
             "Log heap samples on garbage collection for the hp2ps tool.")
 DEFINE_bool(log_handles, false, "Log global handle events.")
+DEFINE_bool(log_snapshot_positions, false,
+            "log positions of (de)serialized objects in the snapshot.")
 DEFINE_bool(log_state_changes, false, "Log state changes.")
 DEFINE_bool(log_suspect, false, "Log suspect operations.")
 DEFINE_bool(log_producers, false, "Log stack traces of JS objects allocations.")

src/log.cc

@@ -871,6 +871,23 @@ void Logger::CodeDeleteEvent(Address from) {
 }
 
 
+void Logger::SnapshotPositionEvent(Address addr, int pos) {
+#ifdef ENABLE_LOGGING_AND_PROFILING
+  if (!Log::IsEnabled() || !FLAG_log_snapshot_positions) return;
+  LogMessageBuilder msg;
+  msg.Append("%s,", log_events_[SNAPSHOT_POSITION_EVENT]);
+  msg.AppendAddress(addr);
+  msg.Append(",%d", pos);
+  if (FLAG_compress_log) {
+    ASSERT(compression_helper_ != NULL);
+    if (!compression_helper_->HandleMessage(&msg)) return;
+  }
+  msg.Append('\n');
+  msg.WriteToLogFile();
+#endif
+}
+
+
 void Logger::ResourceEvent(const char* name, const char* tag) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (!Log::IsEnabled() || !FLAG_log) return;

src/log.h

@@ -116,6 +116,7 @@ class VMState BASE_EMBEDDED {
   V(CODE_CREATION_EVENT,            "code-creation",          "cc")       \
   V(CODE_MOVE_EVENT,                "code-move",              "cm")       \
   V(CODE_DELETE_EVENT,              "code-delete",            "cd")       \
+  V(SNAPSHOT_POSITION_EVENT,        "snapshot-pos",           "sp")       \
   V(TICK_EVENT,                     "tick",                   "t")        \
   V(REPEAT_META_EVENT,              "repeat",                 "r")        \
   V(BUILTIN_TAG,                    "Builtin",                "bi")       \
@@ -224,6 +225,8 @@ class Logger {
   // Emits a code delete event.
   static void CodeDeleteEvent(Address from);
 
+  static void SnapshotPositionEvent(Address addr, int pos);
+
   // ==== Events logged by --log-gc. ====
   // Heap sampling events: start, end, and individual types.
   static void HeapSampleBeginEvent(const char* space, const char* kind);

src/mksnapshot.cc

@@ -130,6 +130,10 @@ class CppByteSink : public i::SnapshotByteSink {
     }
   }
 
+  virtual int Position() {
+    return bytes_written_;
+  }
+
  private:
   FILE* fp_;
   int bytes_written_;

src/serialize.cc

@@ -697,6 +697,9 @@ void Deserializer::ReadObject(int space_number,
   *write_back = HeapObject::FromAddress(address);
   Object** current = reinterpret_cast<Object**>(address);
   Object** limit = current + (size >> kPointerSizeLog2);
+  if (FLAG_log_snapshot_positions) {
+    LOG(SnapshotPositionEvent(address, source_->position()));
+  }
   ReadChunk(current, limit, space_number, address);
 }
 
@@ -1089,6 +1092,8 @@ void Serializer::ObjectSerializer::Serialize() {
   }
   sink_->PutInt(size >> kObjectAlignmentBits, "Size in words");
 
+  LOG(SnapshotPositionEvent(object_->address(), sink_->Position()));
+
   // Mark this object as already serialized.
   bool start_new_page;
   SerializationAddressMapper::Map(

src/serialize.h

@@ -147,6 +147,8 @@ class SnapshotByteSource {
     return position_ == length_;
   }
 
+  const int position() { return position_; }
+
  private:
   const byte* data_;
   int length_;
@@ -294,6 +296,7 @@ class SnapshotByteSink {
     Put(byte, description);
   }
   void PutInt(uintptr_t integer, const char* description);
+  virtual int Position() = 0;
 };
 
 

src/snapshot-common.cc

@@ -79,6 +79,9 @@ class FileByteSink : public SnapshotByteSink {
       fputc(byte, fp_);
     }
   }
+  virtual int Position() {
+    return ftell(fp_);
+  }
 
  private:
   FILE* fp_;

tools/profile.js

@@ -162,6 +162,16 @@ devtools.profiler.Profile.prototype.deleteCode = function(start) {
 };
 
 
+/**
+ * Retrieves a code entry by an address.
+ *
+ * @param {number} addr Entry address.
+ */
+devtools.profiler.Profile.prototype.findEntry = function(addr) {
+  return this.codeMap_.findEntry(addr);
+};
+
+
 /**
  * Records a tick event. Stack must contain a sequence of
  * addresses starting with the program counter value.
@@ -344,6 +354,14 @@ devtools.profiler.Profile.DynamicCodeEntry.prototype.getName = function() {
 };
 
 
+/**
+ * Returns raw node name (without type decoration).
+ */
+devtools.profiler.Profile.DynamicCodeEntry.prototype.getRawName = function() {
+  return this.name;
+};
+
+
 /**
  * Constructs a call graph.
  *

tools/tickprocessor-driver.js

@@ -44,10 +44,16 @@ var entriesProviders = {
 };
 
 var params = processArguments(arguments);
+var snapshotLogProcessor;
+if (params.snapshotLogFileName) {
+  snapshotLogProcessor = new SnapshotLogProcessor();
+  snapshotLogProcessor.processLogFile(params.snapshotLogFileName);
+}
 var tickProcessor = new TickProcessor(
   new (entriesProviders[params.platform])(params.nm),
   params.separateIc,
   params.ignoreUnknown,
-  params.stateFilter);
+  params.stateFilter,
+  snapshotLogProcessor);
 tickProcessor.processLogFile(params.logFileName);
 tickProcessor.printStatistics();

tools/tickprocessor.js

@@ -53,14 +53,79 @@ function readFile(fileName) {
 
 
 function inherits(childCtor, parentCtor) {
-  function tempCtor() {};
-  tempCtor.prototype = parentCtor.prototype;
-  childCtor.prototype = new tempCtor();
+  childCtor.prototype.__proto__ = parentCtor.prototype;
+};
+
+
+function SnapshotLogProcessor() {
+  devtools.profiler.LogReader.call(this, {
+      'code-creation': {
+          parsers: [null, this.createAddressParser('code'), parseInt, null],
+          processor: this.processCodeCreation, backrefs: true },
+      'code-move': { parsers: [this.createAddressParser('code'),
+          this.createAddressParser('code-move-to')],
+          processor: this.processCodeMove, backrefs: true },
+      'code-delete': { parsers: [this.createAddressParser('code')],
+          processor: this.processCodeDelete, backrefs: true },
+      'snapshot-pos': { parsers: [this.createAddressParser('code'), parseInt],
+          processor: this.processSnapshotPosition, backrefs: true }});
+
+  Profile.prototype.handleUnknownCode = function(operation, addr) {
+    var op = devtools.profiler.Profile.Operation;
+    switch (operation) {
+      case op.MOVE:
+        print('Snapshot: Code move event for unknown code: 0x' +
+              addr.toString(16));
+        break;
+      case op.DELETE:
+        print('Snapshot: Code delete event for unknown code: 0x' +
+              addr.toString(16));
+        break;
+    }
+  };
+
+  this.profile_ = new Profile();
+  this.serializedEntries_ = [];
+}
+inherits(SnapshotLogProcessor, devtools.profiler.LogReader);
+
+
+SnapshotLogProcessor.prototype.processCodeCreation = function(
+    type, start, size, name) {
+  var entry = this.profile_.addCode(
+      this.expandAlias(type), name, start, size);
+};
+
+
+SnapshotLogProcessor.prototype.processCodeMove = function(from, to) {
+  this.profile_.moveCode(from, to);
+};
+
+
+SnapshotLogProcessor.prototype.processCodeDelete = function(start) {
+  this.profile_.deleteCode(start);
+};
+
+
+SnapshotLogProcessor.prototype.processSnapshotPosition = function(addr, pos) {
+  this.serializedEntries_[pos] = this.profile_.findEntry(addr);
+};
+
+
+SnapshotLogProcessor.prototype.processLogFile = function(fileName) {
+  var contents = readFile(fileName);
+  this.processLogChunk(contents);
+};
+
+
+SnapshotLogProcessor.prototype.getSerializedEntryName = function(pos) {
+  var entry = this.serializedEntries_[pos];
+  return entry ? entry.getRawName() : null;
 };
 
 
 function TickProcessor(
-    cppEntriesProvider, separateIc, ignoreUnknown, stateFilter) {
+    cppEntriesProvider, separateIc, ignoreUnknown, stateFilter, snapshotLogProcessor) {
   devtools.profiler.LogReader.call(this, {
       'shared-library': { parsers: [null, parseInt, parseInt],
           processor: this.processSharedLibrary },
@@ -72,6 +137,8 @@ function TickProcessor(
           processor: this.processCodeMove, backrefs: true },
       'code-delete': { parsers: [this.createAddressParser('code')],
           processor: this.processCodeDelete, backrefs: true },
+      'snapshot-pos': { parsers: [this.createAddressParser('code'), parseInt],
+          processor: this.processSnapshotPosition, backrefs: true },
       'tick': { parsers: [this.createAddressParser('code'),
           this.createAddressParser('stack'), parseInt, 'var-args'],
           processor: this.processTick, backrefs: true },
@@ -95,6 +162,8 @@ function TickProcessor(
   this.cppEntriesProvider_ = cppEntriesProvider;
   this.ignoreUnknown_ = ignoreUnknown;
   this.stateFilter_ = stateFilter;
+  this.snapshotLogProcessor_ = snapshotLogProcessor;
+  this.deserializedEntriesNames_ = [];
   var ticks = this.ticks_ =
     { total: 0, unaccounted: 0, excluded: 0, gc: 0 };
 
@@ -202,6 +271,7 @@ TickProcessor.prototype.processSharedLibrary = function(
 
 TickProcessor.prototype.processCodeCreation = function(
     type, start, size, name) {
+  name = this.deserializedEntriesNames_[start] || name;
   var entry = this.profile_.addCode(
       this.expandAlias(type), name, start, size);
 };
@@ -217,6 +287,14 @@ TickProcessor.prototype.processCodeDelete = function(start) {
 };
 
 
+TickProcessor.prototype.processSnapshotPosition = function(addr, pos) {
+  if (this.snapshotLogProcessor_) {
+    this.deserializedEntriesNames_[addr] =
+      this.snapshotLogProcessor_.getSerializedEntryName(pos);
+  }
+};
+
+
 TickProcessor.prototype.includeTick = function(vmState) {
   return this.stateFilter_ == null || this.stateFilter_ == vmState;
 };
@@ -648,7 +726,9 @@ function ArgumentsProcessor(args) {
     '--mac': ['platform', 'mac',
         'Specify that we are running on Mac OS X platform'],
     '--nm': ['nm', 'nm',
-        'Specify the \'nm\' executable to use (e.g. --nm=/my_dir/nm)']
+        'Specify the \'nm\' executable to use (e.g. --nm=/my_dir/nm)'],
+    '--snapshot-log': ['snapshotLogFileName', 'snapshot.log',
+        'Specify snapshot log file to use (e.g. --snapshot-log=snapshot.log)']
   };
   this.argsDispatch_['--js'] = this.argsDispatch_['-j'];
   this.argsDispatch_['--gc'] = this.argsDispatch_['-g'];
@@ -660,6 +740,7 @@ function ArgumentsProcessor(args) {
 
 ArgumentsProcessor.DEFAULTS = {
   logFileName: 'v8.log',
+  snapshotLogFileName: null,
   platform: 'unix',
   stateFilter: null,
   ignoreUnknown: false,