tools/tickprocessor.js

// 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
//       with the distribution.
//     * Neither the name of Google Inc. nor the names of its
//       contributors may be used to endorse or promote products derived
//       from this software without specific prior written permission.
//
// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.


function Profile(separateIc) {
  devtools.profiler.Profile.call(this);
  if (!separateIc) {
    this.skipThisFunction = function(name) { return Profile.IC_RE.test(name); };
  }
};
Profile.prototype = devtools.profiler.Profile.prototype;


Profile.IC_RE =
    /^(?:CallIC|LoadIC|StoreIC)|(?:Builtin: (?:Keyed)?(?:Call|Load|Store)IC_)/;


/**
 * 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;
  }
}


function TickProcessor(
    cppEntriesProvider, separateIc, ignoreUnknown, stateFilter) {
  this.cppEntriesProvider_ = cppEntriesProvider;
  this.ignoreUnknown_ = ignoreUnknown;
  this.stateFilter_ = stateFilter;
  var ticks = this.ticks_ =
    { total: 0, unaccounted: 0, excluded: 0, gc: 0 };

  Profile.prototype.handleUnknownCode = function(
      operation, addr, opt_stackPos) {
    var op = devtools.profiler.Profile.Operation;
    switch (operation) {
      case op.MOVE:
        print('Code move event for unknown code: 0x' + addr.toString(16));
        break;
      case op.DELETE:
        print('Code delete event for unknown code: 0x' + addr.toString(16));
        break;
      case op.TICK:
        // Only unknown PCs (the first frame) are reported as unaccounted,
        // otherwise tick balance will be corrupted (this behavior is compatible
        // with the original tickprocessor.py script.)
        if (opt_stackPos == 0) {
          ticks.unaccounted++;
        }
        break;
    }
  };

  this.profile_ = new Profile(separateIc);
  this.codeTypes_ = {};
  // Count each tick as a time unit.
  this.viewBuilder_ = new devtools.profiler.ViewBuilder(1);
  this.lastLogFileName_ = null;
};


TickProcessor.VmStates = {
  JS: 0,
  GC: 1,
  COMPILER: 2,
  OTHER: 3,
  EXTERNAL: 4
};


TickProcessor.CodeTypes = {
  JS: 0,
  CPP: 1,
  SHARED_LIB: 2
};


TickProcessor.RecordsDispatch = {
  'shared-library': { parsers: [null, parseInt, parseInt],
                      processor: 'processSharedLibrary' },
  'code-creation': { parsers: [null, parseInt, parseInt, null],
                   processor: 'processCodeCreation' },
  'code-move': { parsers: [parseInt, parseInt],
                 processor: 'processCodeMove' },
  'code-delete': { parsers: [parseInt], processor: 'processCodeDelete' },
  'tick': { parsers: [parseInt, parseInt, parseInt, 'var-args'],
            processor: 'processTick' },
  'profiler': null,
  // Obsolete row types.
  'code-allocate': null,
  'begin-code-region': null,
  'end-code-region': null
};


TickProcessor.CALL_PROFILE_CUTOFF_PCT = 2.0;


TickProcessor.prototype.setCodeType = function(name, type) {
  this.codeTypes_[name] = TickProcessor.CodeTypes[type];
};


TickProcessor.prototype.isSharedLibrary = function(name) {
  return this.codeTypes_[name] == TickProcessor.CodeTypes.SHARED_LIB;
};


TickProcessor.prototype.isCppCode = function(name) {
  return this.codeTypes_[name] == TickProcessor.CodeTypes.CPP;
};


TickProcessor.prototype.isJsCode = function(name) {
  return this.codeTypes_[name] == TickProcessor.CodeTypes.JS;
};


TickProcessor.prototype.processLogFile = function(fileName) {
  this.lastLogFileName_ = fileName;
  var contents = readFile(fileName);
  this.processLog(contents.split('\n'));
};


TickProcessor.prototype.processLog = function(lines) {
  var csvParser = new devtools.profiler.CsvParser();
  try {
    for (var i = 0, n = lines.length; i < n; ++i) {
      var line = lines[i];
      if (!line) {
        continue;
      }
      var fields = csvParser.parseLine(line);
      this.dispatchLogRow(fields);
    }
  } catch (e) {
    print('line ' + (i + 1) + ': ' + (e.message || e));
    throw e;
  }
};


TickProcessor.prototype.dispatchLogRow = function(fields) {
  // Obtain the dispatch.
  var command = fields[0];
  if (!(command in TickProcessor.RecordsDispatch)) {
    throw new Error('unknown command: ' + command);
  }
  var dispatch = TickProcessor.RecordsDispatch[command];

  if (dispatch === null) {
    return;
  }

  // Parse fields.
  var parsedFields = [];
  for (var i = 0; i < dispatch.parsers.length; ++i) {
    var parser = dispatch.parsers[i];
    if (parser === null) {
      parsedFields.push(fields[1 + i]);
    } else if (typeof parser == 'function') {
      parsedFields.push(parser(fields[1 + i]));
    } else {
      // var-args
      parsedFields.push(fields.slice(1 + i));
      break;
    }
  }

  // Run the processor.
  this[dispatch.processor].apply(this, parsedFields);
};


TickProcessor.prototype.processSharedLibrary = function(
    name, startAddr, endAddr) {
  var entry = this.profile_.addStaticCode(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, start, size, name) {
  var entry = this.profile_.addCode(type, name, start, size);
  this.setCodeType(entry.getName(), 'JS');
};


TickProcessor.prototype.processCodeMove = function(from, to) {
  this.profile_.moveCode(from, to);
};


TickProcessor.prototype.processCodeDelete = function(start) {
  this.profile_.deleteCode(start);
};


TickProcessor.prototype.includeTick = function(vmState) {
  return this.stateFilter_ == null || this.stateFilter_ == vmState;
};


TickProcessor.prototype.processTick = function(pc, sp, vmState, stack) {
  this.ticks_.total++;
  if (vmState == TickProcessor.VmStates.GC) this.ticks_.gc++;
  if (!this.includeTick(vmState)) {
    this.ticks_.excluded++;
    return;
  }

  var fullStack = [pc];
  for (var i = 0, n = stack.length; i < n; ++i) {
    var frame = stack[i];
    // Leave only numbers starting with 0x. Filter possible 'overflow' string.
    if (frame.charAt(0) == '0') {
      fullStack.push(parseInt(frame, 16));
    }
  }
  this.profile_.recordTick(fullStack);
};


TickProcessor.prototype.printStatistics = function() {
  print('Statistical profiling result from ' + this.lastLogFileName_ +
        ', (' + this.ticks_.total +
        ' ticks, ' + this.ticks_.unaccounted + ' unaccounted, ' +
        this.ticks_.excluded + ' excluded).');

  if (this.ticks_.total == 0) return;

  // Print the unknown ticks percentage if they are not ignored.
  if (!this.ignoreUnknown_ && this.ticks_.unaccounted > 0) {
    this.printHeader('Unknown');
    this.printCounter(this.ticks_.unaccounted, this.ticks_.total);
  }

  // Disable initialization of 'funcName', 'url', 'lineNumber' as
  // we don't use it and it just wastes time.
  devtools.profiler.ProfileView.Node.prototype.initFuncInfo = function() {};

  var flatProfile = this.profile_.getFlatProfile();
  var flatView = this.viewBuilder_.buildView(flatProfile);
  // Sort by self time, desc, then by name, desc.
  flatView.sort(function(rec1, rec2) {
      return rec2.selfTime - rec1.selfTime ||
          (rec2.internalFuncName < rec1.internalFuncName ? -1 : 1); });
  var totalTicks = this.ticks_.total;
  if (this.ignoreUnknown_) {
    totalTicks -= this.ticks_.unaccounted;
  }
  // Our total time contains all the ticks encountered,
  // while profile only knows about the filtered ticks.
  flatView.head.totalTime = totalTicks;

  // Count library ticks
  var flatViewNodes = flatView.head.children;
  var self = this;
  var libraryTicks = 0;
  this.processProfile(flatViewNodes,
      function(name) { return self.isSharedLibrary(name); },
      function(rec) { libraryTicks += rec.selfTime; });
  var nonLibraryTicks = totalTicks - libraryTicks;

  this.printHeader('Shared libraries');
  this.printEntries(flatViewNodes, null,
      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.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);
};


function padLeft(s, len) {
  s = s.toString();
  if (s.length < len) {
    s = (new Array(len - s.length + 1).join(' ')) + s;
  }
  return s;
};


TickProcessor.prototype.printHeader = function(headerTitle) {
  print('\n [' + headerTitle + ']:');
  print('   ticks  total  nonlib   name');
};


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.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);
  }
};


TickProcessor.prototype.printEntries = function(
    profile, nonLibTicks, filterP) {
  this.processProfile(profile, filterP, function (rec) {
    if (rec.selfTime == 0) return;
    var nonLibPct = nonLibTicks != null ?
        rec.selfTime * 100.0 / nonLibTicks : 0.0;
    print('  ' + padLeft(rec.selfTime, 5) + '  ' +
          padLeft(rec.selfPercent.toFixed(1), 5) + '%  ' +
          padLeft(nonLibPct.toFixed(1), 5) + '%  ' +
          rec.internalFuncName);
  });
};


TickProcessor.prototype.printHeavyProfile = function(profile, opt_indent) {
  var self = this;
  var indent = opt_indent || 0;
  var indentStr = padLeft('', indent);
  this.processProfile(profile, function() { return true; }, function (rec) {
    // Cut off too infrequent callers.
    if (rec.parentTotalPercent < TickProcessor.CALL_PROFILE_CUTOFF_PCT) return;
    print('  ' + padLeft(rec.totalTime, 5) + '  ' +
          padLeft(rec.parentTotalPercent.toFixed(1), 5) + '%  ' +
          indentStr + rec.internalFuncName);
    // Limit backtrace depth.
    if (indent < 10) {
      self.printHeavyProfile(rec.children, indent + 2);
    }
    // Delimit top-level functions.
    if (indent == 0) {
      print('');
    }
  });
};


function CppEntriesProvider() {
};


CppEntriesProvider.prototype.parseVmSymbols = function(
    libName, libStart, libEnd, processorFunc) {
  var syms = this.loadSymbols(libName);
  if (syms.length == 0) return;

  var prevEntry;

  function addPrevEntry(end) {
    // Several functions can be mapped onto the same address. To avoid
    // creating zero-sized entries, skip such duplicates.
    if (prevEntry && prevEntry.start != end) {
      processorFunc(prevEntry.name, prevEntry.start, end);
    }
  }

  for (var i = 0, n = syms.length; i < n; ++i) {
    var line = syms[i];
    var funcInfo = this.parseLine(line);
    if (!funcInfo) {
      continue;
    }
    if (funcInfo.start < libStart && funcInfo.start < libEnd - libStart) {
      funcInfo.start += libStart;
    }
    addPrevEntry(funcInfo.start);
    prevEntry = funcInfo;
  }
  addPrevEntry(libEnd);
};


CppEntriesProvider.prototype.loadSymbols = function(libName) {
  return [];
};


CppEntriesProvider.prototype.parseLine = function(line) {
  return { name: '', start: 0 };
};


function inherits(childCtor, parentCtor) {
  function tempCtor() {};
  tempCtor.prototype = parentCtor.prototype;
  childCtor.prototype = new tempCtor();
};


function UnixCppEntriesProvider() {
};
inherits(UnixCppEntriesProvider, CppEntriesProvider);


UnixCppEntriesProvider.FUNC_RE = /^([0-9a-fA-F]{8}) . (.*)$/;


UnixCppEntriesProvider.prototype.loadSymbols = function(libName) {
  var normalSyms = os.system('nm', ['-C', '-n', libName], -1, -1);
  var dynaSyms = os.system('nm', ['-C', '-n', '-D', libName], -1, -1);
  var syms = (normalSyms + dynaSyms).split('\n');
  return syms;
};


UnixCppEntriesProvider.prototype.parseLine = function(line) {
  var fields = line.match(UnixCppEntriesProvider.FUNC_RE);
  return fields ? { name: fields[2], start: parseInt(fields[1], 16) } : null;
};


function WindowsCppEntriesProvider() {
};
inherits(WindowsCppEntriesProvider, CppEntriesProvider);


WindowsCppEntriesProvider.FILENAME_RE = /^(.*)\.exe$/;


WindowsCppEntriesProvider.FUNC_RE =
    /^ 0001:[0-9a-fA-F]{8}\s+([_\?@$0-9a-zA-Z]+)\s+([0-9a-fA-F]{8}).*$/;


WindowsCppEntriesProvider.prototype.loadSymbols = function(libName) {
  var fileNameFields = libName.match(WindowsCppEntriesProvider.FILENAME_RE);
  // Only try to load symbols for the .exe file.
  if (!fileNameFields) return [];
  var mapFileName = fileNameFields[1] + '.map';
  return readFile(mapFileName).split('\r\n');
};


WindowsCppEntriesProvider.prototype.parseLine = function(line) {
  var fields = line.match(WindowsCppEntriesProvider.FUNC_RE);
  return fields ?
      { name: this.unmangleName(fields[1]), start: parseInt(fields[2], 16) } :
      null;
};


/**
 * Performs very simple unmangling of C++ names.
 *
 * Does not handle arguments and template arguments. The mangled names have
 * the form:
 *
 *   ?LookupInDescriptor@JSObject@internal@v8@@...arguments info...
 */
WindowsCppEntriesProvider.prototype.unmangleName = function(name) {
  // Empty or non-mangled name.
  if (name.length < 1 || name.charAt(0) != '?') return name;
  var nameEndPos = name.indexOf('@@');
  var components = name.substring(1, nameEndPos).split('@');
  components.reverse();
  return components.join('::');
};


function padRight(s, len) {
  s = s.toString();
  if (s.length < len) {
    s = s + (new Array(len - s.length + 1).join(' '));
  }
  return s;
};


function processArguments(args) {
  var result = {
    logFileName: 'v8.log',
    platform: 'unix',
    stateFilter: null,
    ignoreUnknown: false,
    separateIc: false
  };
  var argsDispatch = {
    '-j': ['stateFilter', TickProcessor.VmStates.JS,
        'Show only ticks from JS VM state'],
    '-g': ['stateFilter', TickProcessor.VmStates.GC,
        'Show only ticks from GC VM state'],
    '-c': ['stateFilter', TickProcessor.VmStates.COMPILER,
        'Show only ticks from COMPILER VM state'],
    '-o': ['stateFilter', TickProcessor.VmStates.OTHER,
        'Show only ticks from OTHER VM state'],
    '-e': ['stateFilter', TickProcessor.VmStates.EXTERNAL,
        'Show only ticks from EXTERNAL VM state'],
    '--ignore-unknown': ['ignoreUnknown', true,
        'Exclude ticks of unknown code entries from processing'],
    '--separate-ic': ['separateIc', true,
        'Separate IC entries'],
    '--unix': ['platform', 'unix',
        'Specify that we are running on *nix platform'],
    '--windows': ['platform', 'windows',
        'Specify that we are running on Windows platform']
  };
  argsDispatch['--js'] = argsDispatch['-j'];
  argsDispatch['--gc'] = argsDispatch['-g'];
  argsDispatch['--compiler'] = argsDispatch['-c'];
  argsDispatch['--other'] = argsDispatch['-o'];
  argsDispatch['--external'] = argsDispatch['-e'];

  function printUsageAndExit() {
    print('Cmdline args: [options] [log-file-name]\n' +
          'Default log file name is "v8.log".\n');
    print('Options:');
    for (var arg in argsDispatch) {
      var synonims = [arg];
      var dispatch = argsDispatch[arg];
      for (var synArg in argsDispatch) {
        if (arg !== synArg && dispatch === argsDispatch[synArg]) {
          synonims.push(synArg);
          delete argsDispatch[synArg];
        }
      }
      print('  ' + padRight(synonims.join(', '), 20) + dispatch[2]);
    }
    quit(2);
  }

  while (args.length) {
    var arg = args[0];
    if (arg.charAt(0) != '-') {
      break;
    }
    args.shift();
    if (arg in argsDispatch) {
      var dispatch = argsDispatch[arg];
      result[dispatch[0]] = dispatch[1];
    } else {
      printUsageAndExit();
    }
  }

  if (args.length >= 1) {
      result.logFileName = args.shift();
  }
  return result;
};


var params = processArguments(arguments);
var tickProcessor = new TickProcessor(
    params.platform == 'unix' ? new UnixCppEntriesProvider() :
        new WindowsCppEntriesProvider(),
    params.separateIc,
    params.ignoreUnknown,
    params.stateFilter);
tickProcessor.processLogFile(params.logFileName);
tickProcessor.printStatistics();