Add an API for additional profile log records

tools/tickprocessor.js

 // Copyright 2012 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 26 matching lines @@
     this.skipThisFunction = function(name) { return V8Profile.IC_RE.test(name); };
   }
 };
 inherits(V8Profile, Profile);
 
 
 V8Profile.IC_RE =
     /^(?:CallIC|LoadIC|StoreIC)|(?:Builtin: (?:Keyed)?(?:Call|Load|Store)IC_)/;
 
 
+function ProfileMark(name, ticks, codeGenerated) {
+  this.name = name;
+  this.ticks = ticks;
+  this.codeGenerated = codeGenerated;
+}
+
+
 /**
  * A thin wrapper around shell's 'read' function showing a file name on error.
  */
 function readFile(fileName) {
   try {
     return read(fileName);
   } catch (e) {
     print(fileName + ': ' + (e.message || e));
     throw e;
   }
@@ skipping 117 matching lines @@
                     parseInt, parseInt, 'var-args'],
           processor: this.processTick },
       'heap-sample-begin': { parsers: [null, null, parseInt],
           processor: this.processHeapSampleBegin },
       'heap-sample-end': { parsers: [null, null],
           processor: this.processHeapSampleEnd },
       'timer-event-start' : { parsers: [null, null, null],
                               processor: this.advanceDistortion },
       'timer-event-end' : { parsers: [null, null, null],
                             processor: this.advanceDistortion },
+      'mark' : { parsers: [null], processor: this.processMark },
       // Ignored events.
       'profiler': null,
       'function-creation': null,
       'function-move': null,
       'function-delete': null,
       'heap-sample-item': null,
       // Obsolete row types.
       'code-allocate': null,
       'begin-code-region': null,
       'end-code-region': null });
 
   this.cppEntriesProvider_ = cppEntriesProvider;
   this.callGraphSize_ = callGraphSize;
   this.ignoreUnknown_ = ignoreUnknown;
   this.stateFilter_ = stateFilter;
   this.snapshotLogProcessor_ = snapshotLogProcessor;
   this.sourceMap = sourceMap;
   this.deserializedEntriesNames_ = [];
   var ticks = this.ticks_ =
-    { total: 0, unaccounted: 0, excluded: 0, gc: 0 };
+      { total: 0, unaccounted: 0, excluded: 0, states: [0, 0, 0, 0, 0, 0]};
+  this.codeGenerated_ = 0;
 
   distortion = parseInt(distortion);
   // Convert picoseconds to nanoseconds.
   this.distortion_per_entry = isNaN(distortion) ? 0 : (distortion / 1000);
   this.distortion = 0;
   var rangelimits = range ? range.split(",") : [];
   var range_start = parseInt(rangelimits[0]);
   var range_end = parseInt(rangelimits[1]);
   // Convert milliseconds to nanoseconds.
   this.range_start = isNaN(range_start) ? -Infinity : (range_start * 1000);
@@ skipping 21 matching lines @@
   };
 
   this.profile_ = new V8Profile(separateIc);
   this.codeTypes_ = {};
   // Count each tick as a time unit.
   this.viewBuilder_ = new ViewBuilder(1);
   this.lastLogFileName_ = null;
 
   this.generation_ = 1;
   this.currentProducerProfile_ = null;
+
+  this.marks_ = [];
 };
 inherits(TickProcessor, LogReader);
 
 
 TickProcessor.VmStates = {
+  FIRST: 0,
   JS: 0,
   GC: 1,
   COMPILER: 2,
   OTHER: 3,
   EXTERNAL: 4,
-  IDLE: 5
+  IDLE: 5,
+  COUNT: 6
 };
 
 
 TickProcessor.CodeTypes = {
   CPP: 0,
   SHARED_LIB: 1
 };
 // Otherwise, this is JS-related code. We are not adding it to
 // codeTypes_ map because there can be zillions of them.
 
@@ skipping 29 matching lines @@
   return !(name in this.codeTypes_);
 };
 
 
 TickProcessor.prototype.processLogFile = function(fileName) {
   this.lastLogFileName_ = fileName;
   var line;
   while (line = readline()) {
     this.processLogLine(line);
   }
+  // If marks are present add a final marker.
+  if (this.marks_.length > 0) {
+    this.processMark("<end of log file>");
+  }
 };
 
 
 TickProcessor.prototype.processLogFileInTest = function(fileName) {
    // Hack file name to avoid dealing with platform specifics.
   this.lastLogFileName_ = 'v8.log';
   var contents = readFile(fileName);
   this.processLogChunk(contents);
 };
 
 
 TickProcessor.prototype.processSharedLibrary = function(
     name, startAddr, endAddr) {
   var entry = this.profile_.addLibrary(name, startAddr, endAddr);
   this.setCodeType(entry.getName(), 'SHARED_LIB');
 
   var self = this;
   var libFuncs = this.cppEntriesProvider_.parseVmSymbols(
       name, startAddr, endAddr, function(fName, fStart, fEnd) {
     self.profile_.addStaticCode(fName, fStart, fEnd);
     self.setCodeType(fName, 'CPP');
   });
 };
 
 
 TickProcessor.prototype.processCodeCreation = function(
     type, kind, start, size, name, maybe_func) {
+  this.codeGenerated_ += size;
   name = this.deserializedEntriesNames_[start] || name;
   if (maybe_func.length) {
     var funcAddr = parseInt(maybe_func[0]);
     var state = parseState(maybe_func[1]);
     this.profile_.addFuncCode(type, name, start, size, funcAddr, state);
   } else {
     this.profile_.addCode(type, name, start, size);
   }
 };
 
@@ skipping 30 matching lines @@
                                                is_external_callback,
                                                tos_or_external_callback,
                                                vmState,
                                                stack) {
   this.distortion += this.distortion_per_entry;
   ns_since_start -= this.distortion;
   if (ns_since_start < this.range_start || ns_since_start > this.range_end) {
     return;
   }
   this.ticks_.total++;
-  if (vmState == TickProcessor.VmStates.GC) this.ticks_.gc++;
+  this.ticks_.states[vmState]++;
   if (!this.includeTick(vmState)) {
     this.ticks_.excluded++;
     return;
   }
   if (is_external_callback) {
     // Don't use PC when in external callback code, as it can point
     // inside callback's code, and we will erroneously report
     // that a callback calls itself. Instead we use tos_or_external_callback,
     // as simply resetting PC will produce unaccounted ticks.
     pc = tos_or_external_callback;
     tos_or_external_callback = 0;
   } else if (tos_or_external_callback) {
     // Find out, if top of stack was pointing inside a JS function
     // meaning that we have encountered a frameless invocation.
     var funcEntry = this.profile_.findEntry(tos_or_external_callback);
     if (!funcEntry || !funcEntry.isJSFunction || !funcEntry.isJSFunction()) {
       tos_or_external_callback = 0;
     }
   }
 
   this.profile_.recordTick(this.processStack(pc, tos_or_external_callback, stack));
 };
 
 
+TickProcessor.prototype.processMark = function(name) {
+  this.marks_.push(
+      new ProfileMark(name, this.ticks_.total, this.codeGenerated_));
+}
+
+
 TickProcessor.prototype.advanceDistortion = function() {
   this.distortion += this.distortion_per_entry;
 }
 
 
 TickProcessor.prototype.processHeapSampleBegin = function(space, state, ticks) {
   if (space != 'Heap') return;
   this.currentProducerProfile_ = new CallTree();
 };
 
@@ skipping 58 matching lines @@
       function(name) { return self.isSharedLibrary(name); });
 
   this.printHeader('JavaScript');
   this.printEntries(flatViewNodes, nonLibraryTicks,
       function(name) { return self.isJsCode(name); });
 
   this.printHeader('C++');
   this.printEntries(flatViewNodes, nonLibraryTicks,
       function(name) { return self.isCppCode(name); });
 
-  this.printHeader('GC');
-  this.printCounter(this.ticks_.gc, totalTicks);
+  this.printTicksListHeader('States', 20);
+  var vmStateNames = [
+    "JavaScript",
+    "GC",
+    "Compiler",
+    "Other",
+    "External",
+    "Idle"
+  ];
+
+  for (var state = TickProcessor.VmStates.FIRST;
+       state < TickProcessor.VmStates.COUNT;
+       state++) {
+    if (this.stateFilter_ == null || this.stateFilter_ == state) {
+      this.printLabledCounter(
+         vmStateNames[state], this.ticks_.states[state], totalTicks);
+    }
+  }
 
   this.printHeavyProfHeader();
   var heavyProfile = this.profile_.getBottomUpProfile();
   var heavyView = this.viewBuilder_.buildView(heavyProfile);
   // To show the same percentages as in the flat profile.
   heavyView.head.totalTime = totalTicks;
   // Sort by total time, desc, then by name, desc.
   heavyView.sort(function(rec1, rec2) {
       return rec2.totalTime - rec1.totalTime ||
           (rec2.internalFuncName < rec1.internalFuncName ? -1 : 1); });
   this.printHeavyProfile(heavyView.head.children);
+
+  if (this.marks_.length > 0) {
+    var maxLength = 0;
+    this.marks_.forEach(function (mark) {
+      maxLength = Math.max(maxLength, mark.name.length);
+    });
+    print(' [Marks]');
+    print('  ' + padRight('Name', 20) +
+      ' ' + padLeft('Ticks', 6) +

[Yang, 2013/09/30 11:25:02]

Please align those lines like the print below.

+      ' ' + padLeft('Delta', 6) +
+      ' ' + padLeft('Code (kb)', 10) +
+      ' ' + padLeft('Delta (kb)', 11));
+    var lastTicks = 0;
+    var lastCodeGenerated = 0;
+    this.marks_.forEach(function (mark) {
+      var ticksDelta = mark.ticks - lastTicks;
+      var codeGeneratedDelta =
+          Math.round((mark.codeGenerated - lastCodeGenerated) / 1024);
+      print('  ' + padRight(mark.name, 20) +
+            ' ' + padLeft(mark.ticks, 6) +
+            ' ' + padLeft(ticksDelta, 6) +
+            ' ' + padLeft(Math.round(mark.codeGenerated / 1024), 10) +
+            ' ' + padLeft(codeGeneratedDelta, 11));
+      lastTicks = mark.ticks;
+      lastCodeGenerated = mark.codeGenerated;
+    });
+  }
+
+  print(' [Code statistics]');
+  var generatedCode = Math.round(this.profile_.generatedCode / 1024);
+  print('  Generated code: ' + generatedCode + ' kb');
 };
 
 
 function padLeft(s, len) {
   s = s.toString();
   if (s.length < len) {
     var padLength = len - s.length;
     if (!(padLength in padLeft)) {
       padLeft[padLength] = new Array(padLength + 1).join(' ');
     }
     s = padLeft[padLength] + s;
   }
   return s;
 };
 
 
+function padRight(s, len) {
+  s = s.toString();
+  if (s.length < len) {
+    s = s + (new Array(len - s.length + 1).join(' '));
+  }
+  return s;
+}
+
+
 TickProcessor.prototype.printHeader = function(headerTitle) {
   print('\n [' + headerTitle + ']:');
   print('   ticks  total  nonlib   name');
 };
 
 
+TickProcessor.prototype.printTicksListHeader = function(headerTitle, padding) {
+  print('\n [' + headerTitle + ']:');
+  print('  ' + padRight('category', padding) + ' ticks  percentage');
+};
+
+
 TickProcessor.prototype.printHeavyProfHeader = function() {
   print('\n [Bottom up (heavy) profile]:');
   print('  Note: percentage shows a share of a particular caller in the ' +
         'total\n' +
         '  amount of its parent calls.');
   print('  Callers occupying less than ' +
         TickProcessor.CALL_PROFILE_CUTOFF_PCT.toFixed(1) +
         '% are not shown.\n');
   print('   ticks parent  name');
 };
 
 
 TickProcessor.prototype.printCounter = function(ticksCount, totalTicksCount) {
   var pct = ticksCount * 100.0 / totalTicksCount;
   print('  ' + padLeft(ticksCount, 5) + '  ' + padLeft(pct.toFixed(1), 5) + '%');
 };
 
 
+TickProcessor.prototype.printLabledCounter = function(
+    label, ticksCount, totalTicksCount) {
+  var pct = ticksCount * 100.0 / totalTicksCount;
+  print('  ' + padRight(label, 20) + ' ' +
+        padLeft(ticksCount, 5) + ' ' +
+        padLeft(pct.toFixed(1), 10) + '%');
+};
+
+
 TickProcessor.prototype.processProfile = function(
     profile, filterP, func) {
   for (var i = 0, n = profile.length; i < n; ++i) {
     var rec = profile[i];
     if (!filterP(rec.internalFuncName)) {
       continue;
     }
     func(rec);
   }
 };
@@ skipping 370 matching lines @@
 };
 
 
 ArgumentsProcessor.prototype.result = function() {
   return this.result_;
 };
 
 
 ArgumentsProcessor.prototype.printUsageAndExit = function() {
 
-  function padRight(s, len) {
-    s = s.toString();
-    if (s.length < len) {
-      s = s + (new Array(len - s.length + 1).join(' '));
-    }
-    return s;
-  }
-
   print('Cmdline args: [options] [log-file-name]\n' +
         'Default log file name is "' +
         ArgumentsProcessor.DEFAULTS.logFileName + '".\n');
   print('Options:');
   for (var arg in this.argsDispatch_) {
     var synonims = [arg];
     var dispatch = this.argsDispatch_[arg];
     for (var synArg in this.argsDispatch_) {
       if (arg !== synArg && dispatch === this.argsDispatch_[synArg]) {
         synonims.push(synArg);
         delete this.argsDispatch_[synArg];
       }
     }
     print('  ' + padRight(synonims.join(', '), 20) + dispatch[2]);
   }
   quit(2);
 };
-