trace-viewer/src/linux_perf_importer.js

// Copyright (c) 2012 The Chromium Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

/**
 * @fileoverview Imports text files in the Linux event trace format into the
 * timeline model. This format is output both by sched_trace and by Linux's perf
 * tool.
 *
 * This importer assumes the events arrive as a string. The unit tests provide
 * examples of the trace format.
 *
 * Linux scheduler traces use a definition for 'pid' that is different than
 * tracing uses. Whereas tracing uses pid to identify a specific process, a pid
 * in a linux trace refers to a specific thread within a process. Within this
 * file, we the definition used in Linux traces, as it improves the importing
 * code's readability.
 */
base.require('timeline_model');
base.require('timeline_color_scheme');
base.require('linux_perf_bus_parser');
base.require('linux_perf_clock_parser');
base.require('linux_perf_cpufreq_parser');
base.require('linux_perf_drm_parser');
base.require('linux_perf_exynos_parser');
base.require('linux_perf_gesture_parser');
base.require('linux_perf_i915_parser');
base.require('linux_perf_mali_parser');
base.require('linux_perf_power_parser');
base.require('linux_perf_sched_parser');
base.require('linux_perf_workqueue_parser');
base.require('linux_perf_android_parser');

base.exportTo('tracing', function() {
  /**
   * Represents the scheduling state for a single thread.
   * @constructor
   */
  function CpuState(cpu) {
    this.cpu = cpu;
  }

  CpuState.prototype = {
    __proto__: Object.prototype,

    /**
     * Switches the active pid on this Cpu. If necessary, add a TimelineSlice
     * to the cpu representing the time spent on that Cpu since the last call to
     * switchRunningLinuxPid.
     */
    switchRunningLinuxPid: function(importer, prevState, ts, pid, comm, prio) {
      // Generate a slice if the last active pid was not the idle task
      if (this.lastActivePid !== undefined && this.lastActivePid != 0) {
        var duration = ts - this.lastActiveTs;
        var thread = importer.threadsByLinuxPid[this.lastActivePid];
        if (thread)
          name = thread.userFriendlyName;
        else
          name = this.lastActiveComm;

        var slice = new tracing.TimelineSlice('', name,
                                              tracing.getStringColorId(name),
                                              this.lastActiveTs,
                                              {
                                                comm: this.lastActiveComm,
                                                tid: this.lastActivePid,
                                                prio: this.lastActivePrio,
                                                stateWhenDescheduled: prevState
                                              },
                                              duration);
        this.cpu.slices.push(slice);
      }

      this.lastActiveTs = ts;
      this.lastActivePid = pid;
      this.lastActiveComm = comm;
      this.lastActivePrio = prio;
    }
  };

  /**
   * Imports linux perf events into a specified model.
   * @constructor
   */
  function LinuxPerfImporter(model, events) {
    this.importPriority = 2;
    this.model_ = model;
    this.events_ = events;
    this.clockSyncRecords_ = [];
    this.cpuStates_ = {};
    this.kernelThreadStates_ = {};
    this.buildMapFromLinuxPidsToTimelineThreads();
    this.lineNumber = -1;
    this.pseudoThreadCounter = 1;
    this.parsers_ = [];
    this.eventHandlers_ = {};
  }

  TestExports = {};

  // Matches the default trace record in 3.2 and later (includes irq-info):
  //          <idle>-0     [001] d...  1.23: sched_switch
  var lineREWithIRQInfo = new RegExp(
      '^\\s*(.+?)\\s+\\[(\\d+)\\]' + '\\s+[dX.][N.][Hhs.][0-9a-f.]' +
      '\\s+(\\d+\\.\\d+):\\s+(\\S+):\\s(.*)$');
  TestExports.lineREWithIRQInfo = lineREWithIRQInfo;

  // Matches the default trace record pre-3.2:
  //          <idle>-0     [001]  1.23: sched_switch
  var lineRE = /^\s*(.+?)\s+\[(\d+)\]\s*(\d+\.\d+):\s+(\S+):\s(.*)$/;
  TestExports.lineRE = lineRE;

  // Matches the trace_event_clock_sync record
  //  0: trace_event_clock_sync: parent_ts=19581477508
  var traceEventClockSyncRE = /trace_event_clock_sync: parent_ts=(\d+\.?\d*)/;
  TestExports.traceEventClockSyncRE = traceEventClockSyncRE;

  // Some kernel trace events are manually classified in slices and
  // hand-assigned a pseudo PID.
  var pseudoKernelPID = 0;

  /**
   * Deduce the format of trace data. Linix kernels prior to 3.3 used
   * one format (by default); 3.4 and later used another.
   *
   * @return {string} the regular expression for parsing data when
   * the format is recognized; otherwise null.
   */
  function autoDetectLineRE(line) {
    if (lineREWithIRQInfo.test(line))
      return lineREWithIRQInfo;
    if (lineRE.test(line))
      return lineRE;
    return null;
  };
  TestExports.autoDetectLineRE = autoDetectLineRE;

  /**
   * Guesses whether the provided events is a Linux perf string.
   * Looks for the magic string "# tracer" at the start of the file,
   * or the typical task-pid-cpu-timestamp-function sequence of a typical
   * trace's body.
   *
   * @return {boolean} True when events is a linux perf array.
   */
  LinuxPerfImporter.canImport = function(events) {
    if (!(typeof(events) === 'string' || events instanceof String))
      return false;

    if (/^# tracer:/.test(events))
      return true;

    var m = /^(.+)\n/.exec(events);
    if (m)
      events = m[1];
    if (autoDetectLineRE(events))
      return true;

    return false;
  };

  LinuxPerfImporter.prototype = {
    __proto__: Object.prototype,

    /**
     * Precomputes a lookup table from linux pids back to existing
     * TimelineThreads. This is used during importing to add information to each
     * timeline thread about whether it was running, descheduled, sleeping, et
     * cetera.
     */
    buildMapFromLinuxPidsToTimelineThreads: function() {
      this.threadsByLinuxPid = {};
      this.model_.getAllThreads().forEach(
          function(thread) {
            this.threadsByLinuxPid[thread.tid] = thread;
          }.bind(this));
    },

    /**
     * @return {CpuState} A CpuState corresponding to the given cpuNumber.
     */
    getOrCreateCpuState: function(cpuNumber) {
      if (!this.cpuStates_[cpuNumber]) {
        var cpu = this.model_.getOrCreateCpu(cpuNumber);
        this.cpuStates_[cpuNumber] = new CpuState(cpu);
      }
      return this.cpuStates_[cpuNumber];
    },

    /**
     * @return {TimelinThread} A thread corresponding to the kernelThreadName.
     */
    getOrCreateKernelThread: function(kernelThreadName, opt_pid, opt_tid) {
      if (!this.kernelThreadStates_[kernelThreadName]) {
        var pid = opt_pid;
        if (pid == undefined) {
          pid = /.+-(\d+)/.exec(kernelThreadName)[1];
          pid = parseInt(pid, 10);
        }
        var tid = opt_tid;
        if (tid == undefined)
          tid = pid;

        var thread = this.model_.getOrCreateProcess(pid).getOrCreateThread(tid);
        thread.name = kernelThreadName;
        this.kernelThreadStates_[kernelThreadName] = {
          pid: pid,
          thread: thread,
          openSlice: undefined,
          openSliceTS: undefined
        };
        this.threadsByLinuxPid[pid] = thread;
      }
      return this.kernelThreadStates_[kernelThreadName];
    },

    /**
     * @return {TimelinThread} A pseudo thread corresponding to the
     * threadName.  Pseudo threads are for events that we want to break
     * out to a separate timeline but would not otherwise happen.
     * These threads are assigned to pseudoKernelPID and given a
     * unique (incrementing) TID.
     */
    getOrCreatePseudoThread: function(threadName) {
      var thread = this.kernelThreadStates_[threadName];
      if (!thread) {
        thread = this.getOrCreateKernelThread(threadName, pseudoKernelPID,
            this.pseudoThreadCounter);
        this.pseudoThreadCounter++;
      }
      return thread;
    },

    /**
     * Imports the data in this.events_ into model_.
     */
    importEvents: function(isSecondaryImport) {
      this.createParsers();
      this.importCpuData();
      if (!this.alignClocks(isSecondaryImport))
        return;
      this.buildMapFromLinuxPidsToTimelineThreads();
      this.buildPerThreadCpuSlicesFromCpuState();
    },

    /**
     * Called by the TimelineModel after all other importers have imported their
     * events.
     */
    finalizeImport: function() {
    },

    /**
     * Builds the cpuSlices array on each thread based on our knowledge of what
     * each Cpu is doing.  This is done only for TimelineThreads that are
     * already in the model, on the assumption that not having any traced data
     * on a thread means that it is not of interest to the user.
     */
    buildPerThreadCpuSlicesFromCpuState: function() {
      // Push the cpu slices to the threads that they run on.
      for (var cpuNumber in this.cpuStates_) {
        var cpuState = this.cpuStates_[cpuNumber];
        var cpu = cpuState.cpu;

        for (var i = 0; i < cpu.slices.length; i++) {
          var slice = cpu.slices[i];

          var thread = this.threadsByLinuxPid[slice.args.tid];
          if (!thread)
            continue;
          if (!thread.tempCpuSlices)
            thread.tempCpuSlices = [];
          thread.tempCpuSlices.push(slice);
        }
      }

      // Create slices for when the thread is not running.
      var runningId = tracing.getColorIdByName('running');
      var runnableId = tracing.getColorIdByName('runnable');
      var sleepingId = tracing.getColorIdByName('sleeping');
      var ioWaitId = tracing.getColorIdByName('iowait');
      this.model_.getAllThreads().forEach(function(thread) {
        if (!thread.tempCpuSlices)
          return;
        var origSlices = thread.tempCpuSlices;
        delete thread.tempCpuSlices;

        origSlices.sort(function(x, y) {
          return x.start - y.start;
        });

        // Walk the slice list and put slices between each original slice
        // to show when the thread isn't running
        var slices = [];
        if (origSlices.length) {
          var slice = origSlices[0];
          slices.push(new tracing.TimelineSlice('', 'Running', runningId,
              slice.start, {}, slice.duration));
        }
        for (var i = 1; i < origSlices.length; i++) {
          var prevSlice = origSlices[i - 1];
          var nextSlice = origSlices[i];
          var midDuration = nextSlice.start - prevSlice.end;
          if (prevSlice.args.stateWhenDescheduled == 'S') {
            slices.push(new tracing.TimelineSlice('', 'Sleeping', sleepingId,
                prevSlice.end, {}, midDuration));
          } else if (prevSlice.args.stateWhenDescheduled == 'R' ||
                     prevSlice.args.stateWhenDescheduled == 'R+') {
            slices.push(new tracing.TimelineSlice('', 'Runnable', runnableId,
                prevSlice.end, {}, midDuration));
          } else if (prevSlice.args.stateWhenDescheduled == 'D') {
            slices.push(new tracing.TimelineSlice(
                '', 'Uninterruptible Sleep', ioWaitId,
                prevSlice.end, {}, midDuration));
          } else if (prevSlice.args.stateWhenDescheduled == 'T') {
            slices.push(new tracing.TimelineSlice('', '__TASK_STOPPED',
                ioWaitId, prevSlice.end, {}, midDuration));
          } else if (prevSlice.args.stateWhenDescheduled == 't') {
            slices.push(new tracing.TimelineSlice('', 'debug', ioWaitId,
                prevSlice.end, {}, midDuration));
          } else if (prevSlice.args.stateWhenDescheduled == 'Z') {
            slices.push(new tracing.TimelineSlice('', 'Zombie', ioWaitId,
                prevSlice.end, {}, midDuration));
          } else if (prevSlice.args.stateWhenDescheduled == 'X') {
            slices.push(new tracing.TimelineSlice('', 'Exit Dead', ioWaitId,
                prevSlice.end, {}, midDuration));
          } else if (prevSlice.args.stateWhenDescheduled == 'x') {
            slices.push(new tracing.TimelineSlice('', 'Task Dead', ioWaitId,
                prevSlice.end, {}, midDuration));
          } else if (prevSlice.args.stateWhenDescheduled == 'W') {
            slices.push(new tracing.TimelineSlice('', 'WakeKill', ioWaitId,
                prevSlice.end, {}, midDuration));
          } else if (prevSlice.args.stateWhenDescheduled == 'D|W') {
            slices.push(new tracing.TimelineSlice(
                '', 'Uninterruptable Sleep | WakeKill', ioWaitId,
                prevSlice.end, {}, midDuration));
          } else {
            throw new Error('Unrecognized state: ') +
                prevSlice.args.stateWhenDescheduled;
          }

          slices.push(new tracing.TimelineSlice('', 'Running', runningId,
              nextSlice.start, {}, nextSlice.duration));
        }
        thread.cpuSlices = slices;
      });
    },

    /**
     * Walks the slices stored on this.cpuStates_ and adjusts their timestamps
     * based on any alignment metadata we discovered.
     */
    alignClocks: function(isSecondaryImport) {
      if (this.clockSyncRecords_.length == 0) {
        // If this is a secondary import, and no clock syncing records were
        // found, then abort the import. Otherwise, just skip clock alignment.
        if (!isSecondaryImport)
          return true;

        // Remove the newly imported CPU slices from the model.
        this.abortImport();
        return false;
      }

      // Shift all the slice times based on the sync record.
      var sync = this.clockSyncRecords_[0];
      // NB: parentTS of zero denotes no times-shift; this is
      // used when user and kernel event clocks are identical.
      if (sync.parentTS == 0 || sync.parentTS == sync.perfTS)
        return true;
      var timeShift = sync.parentTS - sync.perfTS;
      for (var cpuNumber in this.cpuStates_) {
        var cpuState = this.cpuStates_[cpuNumber];
        var cpu = cpuState.cpu;

        for (var i = 0; i < cpu.slices.length; i++) {
          var slice = cpu.slices[i];
          slice.start = slice.start + timeShift;
          slice.duration = slice.duration;
        }

        for (var counterName in cpu.counters) {
          var counter = cpu.counters[counterName];
          for (var sI = 0; sI < counter.timestamps.length; sI++)
            counter.timestamps[sI] = (counter.timestamps[sI] + timeShift);
        }
      }
      for (var kernelThreadName in this.kernelThreadStates_) {
        var kthread = this.kernelThreadStates_[kernelThreadName];
        var thread = kthread.thread;
        thread.shiftTimestampsForward(timeShift);
      }
      return true;
    },

    /**
     * Removes any data that has been added to the model because of an error
     * detected during the import.
     */
    abortImport: function() {
      if (this.pushedEventsToThreads)
        throw new Error('Cannot abort, have alrady pushedCpuDataToThreads.');

      for (var cpuNumber in this.cpuStates_)
        delete this.model_.cpus[cpuNumber];
      for (var kernelThreadName in this.kernelThreadStates_) {
        var kthread = this.kernelThreadStates_[kernelThreadName];
        var thread = kthread.thread;
        var process = thread.parent;
        delete process.threads[thread.tid];
        delete this.model_.processes[process.pid];
      }
      this.model_.importErrors.push(
          'Cannot import kernel trace without a clock sync.');
    },

    /**
     * Creates an instance of each registered linux perf event parser.
     * This allows the parsers to register handlers for the events they
     * understand.  We also register our own special handlers (for the
     * timestamp synchronization markers).
     */
    createParsers: function() {
      // Instantiate the parsers; this will register handlers for known events
      var parserConstructors = tracing.LinuxPerfParser.getSubtypeConstructors();
      for (var i = 0; i < parserConstructors.length; ++i) {
        var parserConstructor = parserConstructors[i];
        this.parsers_.push(new parserConstructor(this));
      }

      this.registerEventHandler('tracing_mark_write:trace_event_clock_sync',
          LinuxPerfImporter.prototype.traceClockSyncEvent.bind(this));
      this.registerEventHandler('tracing_mark_write',
          LinuxPerfImporter.prototype.traceMarkingWriteEvent.bind(this));
      // NB: old-style trace markers; deprecated
      this.registerEventHandler('0:trace_event_clock_sync',
          LinuxPerfImporter.prototype.traceClockSyncEvent.bind(this));
      this.registerEventHandler('0',
          LinuxPerfImporter.prototype.traceMarkingWriteEvent.bind(this));
    },

    /**
     * Registers a linux perf event parser used by importCpuData.
     */
    registerEventHandler: function(eventName, handler) {
      // TODO(sleffler) how to handle conflicts?
      this.eventHandlers_[eventName] = handler;
    },

    /**
     * Records the fact that a pid has become runnable. This data will
     * eventually get used to derive each thread's cpuSlices array.
     */
    markPidRunnable: function(ts, pid, comm, prio) {
      // TODO(nduca): implement this functionality.
    },

    importError: function(message) {
      this.model_.importErrors.push('Line ' + (this.lineNumber + 1) +
          ': ' + message);
    },

    /**
     * Processes a trace_event_clock_sync event.
     */
    traceClockSyncEvent: function(eventName, cpuNumber, pid, ts, eventBase) {
      var event = /parent_ts=(\d+\.?\d*)/.exec(eventBase[2]);
      if (!event)
        return false;

      this.clockSyncRecords_.push({
        perfTS: ts,
        parentTS: event[1] * 1000
      });
      return true;
    },

    /**
     * Processes a trace_marking_write event.
     */
    traceMarkingWriteEvent: function(eventName, cpuNumber, pid, ts, eventBase,
                                     threadName) {
      var event = /^\s*(\w+):\s*(.*)$/.exec(eventBase[5]);
      if (!event) {
        // Check if the event matches events traced by the Android framework
        if (eventBase[5].lastIndexOf('B|', 0) === 0 ||
            eventBase[5] === 'E' ||
            eventBase[5].lastIndexOf('C|', 0) === 0)
          event = [eventBase[5], 'android', eventBase[5]];
        else
          return false;
      }

      var writeEventName = eventName + ':' + event[1];
      var threadName = (/(.+)-\d+/.exec(eventBase[1]))[1];
      var handler = this.eventHandlers_[writeEventName];
      if (!handler) {
        this.importError('Unknown trace_marking_write event ' + writeEventName);
        return true;
      }
      return handler(writeEventName, cpuNumber, pid, ts, event, threadName);
    },

    /**
     * Walks the this.events_ structure and creates TimelineCpu objects.
     */
    importCpuData: function() {
      this.lines_ = this.events_.split('\n');

      var lineRE = null;
      for (this.lineNumber = 0; this.lineNumber < this.lines_.length;
          ++this.lineNumber) {
        var line = this.lines_[this.lineNumber];
        if (line.length == 0 || /^#/.test(line))
          continue;
        if (lineRE == null) {
          lineRE = autoDetectLineRE(line);
          if (lineRE == null) {
            this.importError('Cannot parse line: ' + line);
            continue;
          }
        }
        var eventBase = lineRE.exec(line);
        if (!eventBase) {
          this.importError('Unrecognized line: ' + line);
          continue;
        }

        var pid = parseInt((/.+-(\d+)/.exec(eventBase[1]))[1]);
        var cpuNumber = parseInt(eventBase[2]);
        var ts = parseFloat(eventBase[3]) * 1000;
        var eventName = eventBase[4];

        var handler = this.eventHandlers_[eventName];
        if (!handler) {
          this.importError('Unknown event ' + eventName + ' (' + line + ')');
          continue;
        }
        if (!handler(eventName, cpuNumber, pid, ts, eventBase))
          this.importError('Malformed ' + eventName + ' event (' + line + ')');
      }
    }
  };

  tracing.TimelineModel.registerImporter(LinuxPerfImporter);

  return {
    LinuxPerfImporter: LinuxPerfImporter,
    _LinuxPerfImporterTestExports: TestExports
  };

});