perfprofd/quipper/perf_parser.cc

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

#include "perf_parser.h"

#include <algorithm>
#include <cstdio>
#include <set>

#include "base/logging.h"

#include "address_mapper.h"
#include "quipper_string.h"
#include "perf_utils.h"

namespace quipper {

namespace {

struct EventAndTime {
  ParsedEvent* event;
  uint64_t time;
};

// Returns true if |e1| has an earlier timestamp than |e2|.  The args are const
// pointers instead of references because of the way this function is used when
// calling std::stable_sort.
bool CompareParsedEventTimes(const std::unique_ptr<EventAndTime>& e1,
                             const std::unique_ptr<EventAndTime>& e2) {
  return (e1->time < e2->time);
}

// Kernel MMAP entry pid appears as -1
const uint32_t kKernelPid = UINT32_MAX;

// Name and ID of the kernel swapper process.
const char kSwapperCommandName[] = "swapper";
const uint32_t kSwapperPid = 0;

bool IsNullBranchStackEntry(const struct branch_entry& entry) {
  return (!entry.from && !entry.to);
}

}  // namespace

PerfParser::PerfParser()
    : kernel_mapper_(new AddressMapper)
{}

PerfParser::~PerfParser() {}

PerfParser::PerfParser(const PerfParser::Options& options) {
  options_ = options;
}

void PerfParser::set_options(const PerfParser::Options& options) {
  options_ = options;
}

bool PerfParser::ParseRawEvents() {
  process_mappers_.clear();
  parsed_events_.resize(events_.size());
  for (size_t i = 0; i < events_.size(); ++i) {
    ParsedEvent& parsed_event = parsed_events_[i];
    parsed_event.raw_event = events_[i].get();
  }
  MaybeSortParsedEvents();
  if (!ProcessEvents()) {
    return false;
  }

  if (!options_.discard_unused_events)
    return true;

  // Some MMAP/MMAP2 events' mapped regions will not have any samples. These
  // MMAP/MMAP2 events should be dropped. |parsed_events_| should be
  // reconstructed without these events.
  size_t write_index = 0;
  size_t read_index;
  for (read_index = 0; read_index < parsed_events_.size(); ++read_index) {
    const ParsedEvent& event = parsed_events_[read_index];
    if ((event.raw_event->header.type == PERF_RECORD_MMAP ||
         event.raw_event->header.type == PERF_RECORD_MMAP2) &&
        event.num_samples_in_mmap_region == 0) {
      continue;
    }
    if (read_index != write_index)
      parsed_events_[write_index] = event;
    ++write_index;
  }
  CHECK_LE(write_index, parsed_events_.size());
  parsed_events_.resize(write_index);

  // Now regenerate the sorted event list again.  These are pointers to events
  // so they must be regenerated after a resize() of the ParsedEvent vector.
  MaybeSortParsedEvents();

  return true;
}

void PerfParser::MaybeSortParsedEvents() {
  if (!(sample_type_ & PERF_SAMPLE_TIME)) {
    parsed_events_sorted_by_time_.resize(parsed_events_.size());
    for (size_t i = 0; i < parsed_events_.size(); ++i) {
      parsed_events_sorted_by_time_[i] = &parsed_events_[i];
    }
    return;
  }
  std::vector<std::unique_ptr<EventAndTime>> events_and_times;
  events_and_times.resize(parsed_events_.size());
  for (size_t i = 0; i < parsed_events_.size(); ++i) {
    std::unique_ptr<EventAndTime> event_and_time(new EventAndTime);

    // Store the timestamp and event pointer in an array.
    event_and_time->event = &parsed_events_[i];

    struct perf_sample sample_info;
    PerfSampleCustodian custodian(sample_info);
    CHECK(ReadPerfSampleInfo(*parsed_events_[i].raw_event, &sample_info));
    event_and_time->time = sample_info.time;

    events_and_times[i] = std::move(event_and_time);
  }
  // Sort the events based on timestamp, and then populate the sorted event
  // vector in sorted order.
  std::stable_sort(events_and_times.begin(), events_and_times.end(),
                   CompareParsedEventTimes);

  parsed_events_sorted_by_time_.resize(events_and_times.size());
  for (unsigned int i = 0; i < events_and_times.size(); ++i) {
    parsed_events_sorted_by_time_[i] = events_and_times[i]->event;
  }
}

bool PerfParser::ProcessEvents() {
  memset(&stats_, 0, sizeof(stats_));

  stats_.did_remap = false;   // Explicitly clear the remap flag.

  // Pid 0 is called the swapper process. Even though perf does not record a
  // COMM event for pid 0, we act like we did receive a COMM event for it. Perf
  // does this itself, example:
  //   http://lxr.free-electrons.com/source/tools/perf/util/session.c#L1120
  commands_.insert(kSwapperCommandName);
  pidtid_to_comm_map_[std::make_pair(kSwapperPid, kSwapperPid)] =
      &(*commands_.find(kSwapperCommandName));

  // NB: Not necessarily actually sorted by time.
  for (unsigned int i = 0; i < parsed_events_sorted_by_time_.size(); ++i) {
    ParsedEvent& parsed_event = *parsed_events_sorted_by_time_[i];
    event_t& event = *parsed_event.raw_event;
    switch (event.header.type) {
      case PERF_RECORD_SAMPLE:
        // SAMPLE doesn't have any fields to log at a fixed,
        // previously-endian-swapped location. This used to log ip.
        VLOG(1) << "SAMPLE";
        ++stats_.num_sample_events;

        if (MapSampleEvent(&parsed_event)) {
          ++stats_.num_sample_events_mapped;
        }
        break;
      case PERF_RECORD_MMAP: {
        VLOG(1) << "MMAP: " << event.mmap.filename;
        ++stats_.num_mmap_events;
        // Use the array index of the current mmap event as a unique identifier.
        CHECK(MapMmapEvent(&event.mmap, i)) << "Unable to map MMAP event!";
        // No samples in this MMAP region yet, hopefully.
        parsed_event.num_samples_in_mmap_region = 0;
        DSOInfo dso_info;
        // TODO(sque): Add Build ID as well.
        dso_info.name = event.mmap.filename;
        dso_set_.insert(dso_info);
        break;
      }
      case PERF_RECORD_MMAP2: {
        VLOG(1) << "MMAP2: " << event.mmap2.filename;
        ++stats_.num_mmap_events;
        // Use the array index of the current mmap event as a unique identifier.
        CHECK(MapMmapEvent(&event.mmap2, i)) << "Unable to map MMAP2 event!";
        // No samples in this MMAP region yet, hopefully.
        parsed_event.num_samples_in_mmap_region = 0;
        DSOInfo dso_info;
        // TODO(sque): Add Build ID as well.
        dso_info.name = event.mmap2.filename;
        dso_set_.insert(dso_info);
        break;
      }
      case PERF_RECORD_FORK:
        VLOG(1) << "FORK: " << event.fork.ppid << ":" << event.fork.ptid
                << " -> " << event.fork.pid << ":" << event.fork.tid;
        ++stats_.num_fork_events;
        CHECK(MapForkEvent(event.fork)) << "Unable to map FORK event!";
        break;
      case PERF_RECORD_EXIT:
        // EXIT events have the same structure as FORK events.
        VLOG(1) << "EXIT: " << event.fork.ppid << ":" << event.fork.ptid;
        ++stats_.num_exit_events;
        break;
      case PERF_RECORD_COMM:
        VLOG(1) << "COMM: " << event.comm.pid << ":" << event.comm.tid << ": "
                << event.comm.comm;
        ++stats_.num_comm_events;
        CHECK(MapCommEvent(event.comm));
        commands_.insert(event.comm.comm);
        pidtid_to_comm_map_[std::make_pair(event.comm.pid, event.comm.tid)] =
            &(*commands_.find(event.comm.comm));
        break;
      case PERF_RECORD_LOST:
      case PERF_RECORD_THROTTLE:
      case PERF_RECORD_UNTHROTTLE:
      case PERF_RECORD_READ:
      case PERF_RECORD_MAX:
        VLOG(1) << "Parsed event type: " << event.header.type
                << ". Doing nothing.";
        break;
    case SIMPLE_PERF_RECORD_KERNEL_SYMBOL:
    case SIMPLE_PERF_RECORD_DSO:
    case SIMPLE_PERF_RECORD_SYMBOL:
    case SIMPLE_PERF_RECORD_SPLIT:
    case SIMPLE_PERF_RECORD_SPLIT_END:
      break;
      default:
        LOG(ERROR) << "Unknown event type: " << event.header.type;
        return false;
    }
  }

  // Print stats collected from parsing.
  DLOG(INFO) << "Parser processed: "
            << stats_.num_mmap_events << " MMAP/MMAP2 events, "
            << stats_.num_comm_events << " COMM events, "
            << stats_.num_fork_events << " FORK events, "
            << stats_.num_exit_events << " EXIT events, "
            << stats_.num_sample_events << " SAMPLE events, "
            << stats_.num_sample_events_mapped << " of these were mapped";

  float sample_mapping_percentage =
      static_cast<float>(stats_.num_sample_events_mapped) /
      stats_.num_sample_events * 100.;
  float threshold = options_.sample_mapping_percentage_threshold;
  if (sample_mapping_percentage < threshold) {
    LOG(WARNING) << "Mapped " << static_cast<int>(sample_mapping_percentage)
               << "% of samples, expected at least "
               << static_cast<int>(threshold) << "%";
    return false;
  }
  stats_.did_remap = options_.do_remap;
  return true;
}

bool PerfParser::MapSampleEvent(ParsedEvent* parsed_event) {
  bool mapping_failed = false;

  // Find the associated command.
  if (!(sample_type_ & PERF_SAMPLE_IP && sample_type_ & PERF_SAMPLE_TID))
    return false;
  perf_sample sample_info;
  PerfSampleCustodian custodian(sample_info);
  if (!ReadPerfSampleInfo(*parsed_event->raw_event, &sample_info))
    return false;
  PidTid pidtid = std::make_pair(sample_info.pid, sample_info.tid);
  const auto comm_iter = pidtid_to_comm_map_.find(pidtid);
  if (comm_iter != pidtid_to_comm_map_.end()) {
    parsed_event->set_command(comm_iter->second);
  }

  const uint64_t unmapped_event_ip = sample_info.ip;

  // Map the event IP itself.
  if (!MapIPAndPidAndGetNameAndOffset(sample_info.ip,
                                      sample_info.pid,
                                      &sample_info.ip,
                                      &parsed_event->dso_and_offset)) {
    mapping_failed = true;
  }

  if (sample_info.callchain &&
      !MapCallchain(sample_info.ip,
                    sample_info.pid,
                    unmapped_event_ip,
                    sample_info.callchain,
                    parsed_event)) {
    mapping_failed = true;
  }

  if (sample_info.branch_stack &&
      !MapBranchStack(sample_info.pid,
                      sample_info.branch_stack,
                      parsed_event)) {
    mapping_failed = true;
  }

  if (options_.do_remap) {
    // Write the remapped data back to the raw event regardless of
    // whether it was entirely successfully remapped.  A single failed
    // remap should not invalidate all the other remapped entries.
    if (!WritePerfSampleInfo(sample_info, parsed_event->raw_event)) {
      LOG(ERROR) << "Failed to write back remapped sample info.";
      return false;
    }
  }

  return !mapping_failed;
}

bool PerfParser::MapCallchain(const uint64_t ip,
                              const uint32_t pid,
                              const uint64_t original_event_addr,
                              struct ip_callchain* callchain,
                              ParsedEvent* parsed_event) {
  if (!callchain) {
    LOG(ERROR) << "NULL call stack data.";
    return false;
  }

  bool mapping_failed = false;

  // If the callchain's length is 0, there is no work to do.
  if (callchain->nr == 0)
    return true;

  // Keeps track of whether the current entry is kernel or user.
  parsed_event->callchain.resize(callchain->nr);
  int num_entries_mapped = 0;
  for (unsigned int j = 0; j < callchain->nr; ++j) {
    uint64_t entry = callchain->ips[j];
    // When a callchain context entry is found, do not attempt to symbolize it.
    if (entry >= PERF_CONTEXT_MAX) {
      continue;
    }
    // The sample address has already been mapped so no need to map it.
    if (entry == original_event_addr) {
      callchain->ips[j] = ip;
      continue;
    }
    if (!MapIPAndPidAndGetNameAndOffset(
            entry,
            pid,
            &callchain->ips[j],
            &parsed_event->callchain[num_entries_mapped++])) {
      mapping_failed = true;
    }
  }
  // Not all the entries were mapped.  Trim |parsed_event->callchain| to
  // remove unused entries at the end.
  parsed_event->callchain.resize(num_entries_mapped);

  return !mapping_failed;
}

bool PerfParser::MapBranchStack(const uint32_t pid,
                                struct branch_stack* branch_stack,
                                ParsedEvent* parsed_event) {
  if (!branch_stack) {
    LOG(ERROR) << "NULL branch stack data.";
    return false;
  }

  // First, trim the branch stack to remove trailing null entries.
  size_t trimmed_size = 0;
  for (size_t i = 0; i < branch_stack->nr; ++i) {
    // Count the number of non-null entries before the first null entry.
    if (IsNullBranchStackEntry(branch_stack->entries[i])) {
      break;
    }
    ++trimmed_size;
  }

  // If a null entry was found, make sure all subsequent null entries are NULL
  // as well.
  for (size_t i = trimmed_size; i < branch_stack->nr; ++i) {
    const struct branch_entry& entry = branch_stack->entries[i];
    if (!IsNullBranchStackEntry(entry)) {
      LOG(ERROR) << "Non-null branch stack entry found after null entry: "
                 << reinterpret_cast<void*>(entry.from) << " -> "
                 << reinterpret_cast<void*>(entry.to);
      return false;
    }
  }

  // Map branch stack addresses.
  parsed_event->branch_stack.resize(trimmed_size);
  for (unsigned int i = 0; i < trimmed_size; ++i) {
    struct branch_entry& entry = branch_stack->entries[i];
    ParsedEvent::BranchEntry& parsed_entry = parsed_event->branch_stack[i];
    if (!MapIPAndPidAndGetNameAndOffset(entry.from,
                                        pid,
                                        &entry.from,
                                        &parsed_entry.from)) {
      return false;
    }
    if (!MapIPAndPidAndGetNameAndOffset(entry.to,
                                        pid,
                                        &entry.to,
                                        &parsed_entry.to)) {
      return false;
    }
    parsed_entry.predicted = entry.flags.predicted;
    // Either predicted or mispredicted, not both. But don't use a CHECK here,
    // just exit gracefully because it's a minor issue.
    if (entry.flags.predicted == entry.flags.mispred) {
      LOG(ERROR) << "Branch stack entry predicted and mispred flags "
                 << "both have value " << entry.flags.mispred;
      return false;
    }
  }

  return true;
}

bool PerfParser::MapIPAndPidAndGetNameAndOffset(
    uint64_t ip,
    uint32_t pid,
    uint64_t* new_ip,
    ParsedEvent::DSOAndOffset* dso_and_offset) {

  // Attempt to find the synthetic address of the IP sample in this order:
  // 1. Address space of its own process.
  // 2. Address space of the kernel.

  uint64_t mapped_addr = 0;

  // Sometimes the first event we see is a SAMPLE event and we don't have the
  // time to create an address mapper for a process. Example, for pid 0.
  AddressMapper* mapper = GetOrCreateProcessMapper(pid).first;
  bool mapped = mapper->GetMappedAddress(ip, &mapped_addr);
  if (!mapped) {
    mapper = kernel_mapper_.get();
    mapped = mapper->GetMappedAddress(ip, &mapped_addr);
  }

  // TODO(asharif): What should we do when we cannot map a SAMPLE event?
  if (mapped) {
    if (dso_and_offset) {
      uint64_t id = kuint64max;
      CHECK(mapper->GetMappedIDAndOffset(ip, &id, &dso_and_offset->offset_));
      // Make sure the ID points to a valid event.
      CHECK_LE(id, parsed_events_sorted_by_time_.size());
      ParsedEvent* parsed_event = parsed_events_sorted_by_time_[id];
      const event_t* raw_event = parsed_event->raw_event;

      DSOInfo dso_info;
      if (raw_event->header.type == PERF_RECORD_MMAP) {
        dso_info.name = raw_event->mmap.filename;
      } else if (raw_event->header.type == PERF_RECORD_MMAP2) {
        dso_info.name = raw_event->mmap2.filename;
      } else {
        LOG(FATAL) << "Expected MMAP or MMAP2 event";
      }

      // Find the mmap DSO filename in the set of known DSO names.
      // TODO(sque): take build IDs into account.
      std::set<DSOInfo>::const_iterator dso_iter = dso_set_.find(dso_info);
      CHECK(dso_iter != dso_set_.end());
      dso_and_offset->dso_info_ = &(*dso_iter);

      ++parsed_event->num_samples_in_mmap_region;
    }
    if (options_.do_remap)
      *new_ip = mapped_addr;
  }
  return mapped;
}

bool PerfParser::MapMmapEvent(uint64_t id,
                              uint32_t pid,
                              uint64_t* p_start,
                              uint64_t* p_len,
                              uint64_t* p_pgoff)
{
  // We need to hide only the real kernel addresses.  However, to make things
  // more secure, and make the mapping idempotent, we should remap all
  // addresses, both kernel and non-kernel.
  AddressMapper* mapper =
      (pid == kKernelPid ? kernel_mapper_.get() :
       GetOrCreateProcessMapper(pid).first);

  uint64_t start = *p_start;
  uint64_t len = *p_len;
  uint64_t pgoff = *p_pgoff;

  // |id| == 0 corresponds to the kernel mmap. We have several cases here:
  //
  // For ARM and x86, in sudo mode, pgoff == start, example:
  // start=0x80008200
  // pgoff=0x80008200
  // len  =0xfffffff7ff7dff
  //
  // For x86-64, in sudo mode, pgoff is between start and start + len. SAMPLE
  // events lie between pgoff and pgoff + length of the real kernel binary,
  // example:
  // start=0x3bc00000
  // pgoff=0xffffffffbcc00198
  // len  =0xffffffff843fffff
  // SAMPLE events will be found after pgoff. For kernels with ASLR, pgoff will
  // be something only visible to the root user, and will be randomized at
  // startup. With |remap| set to true, we should hide pgoff in this case. So we
  // normalize all SAMPLE events relative to pgoff.
  //
  // For non-sudo mode, the kernel will be mapped from 0 to the pointer limit,
  // example:
  // start=0x0
  // pgoff=0x0
  // len  =0xffffffff
  if (id == 0) {
    // If pgoff is between start and len, we normalize the event by setting
    // start to be pgoff just like how it is for ARM and x86. We also set len to
    // be a much smaller number (closer to the real length of the kernel binary)
    // because SAMPLEs are actually only seen between |event->pgoff| and
    // |event->pgoff + kernel text size|.
    if (pgoff > start && pgoff < start + len) {
      len = len + start - pgoff;
      start = pgoff;
    }
    // For kernels with ALSR pgoff is critical information that should not be
    // revealed when |remap| is true.
    pgoff = 0;
  }

  if (!mapper->MapWithID(start, len, id, pgoff, true)) {
    mapper->DumpToLog();
    return false;
  }

  if (options_.do_remap) {
    uint64_t mapped_addr;
    CHECK(mapper->GetMappedAddress(start, &mapped_addr));
    *p_start = mapped_addr;
    *p_len = len;
    *p_pgoff = pgoff;
  }
  return true;
}

std::pair<AddressMapper*, bool> PerfParser::GetOrCreateProcessMapper(
    uint32_t pid, uint32_t *ppid) {
  const auto& search = process_mappers_.find(pid);
  if (search != process_mappers_.end()) {
    return std::make_pair(search->second.get(), false);
  }

  std::unique_ptr<AddressMapper> mapper;
  const auto& parent_mapper = (ppid ? process_mappers_.find(*ppid) : process_mappers_.end());
  if (parent_mapper != process_mappers_.end())
      mapper.reset(new AddressMapper(*parent_mapper->second));
  else
    mapper.reset(new AddressMapper());

  const auto inserted =
      process_mappers_.insert(search, std::make_pair(pid, std::move(mapper)));
  return std::make_pair(inserted->second.get(), true);
}

bool PerfParser::MapCommEvent(const struct comm_event& event) {
  GetOrCreateProcessMapper(event.pid);
  return true;
}

bool PerfParser::MapForkEvent(const struct fork_event& event) {
  PidTid parent = std::make_pair(event.ppid, event.ptid);
  PidTid child = std::make_pair(event.pid, event.tid);
  if (parent != child &&
      pidtid_to_comm_map_.find(parent) != pidtid_to_comm_map_.end()) {
    pidtid_to_comm_map_[child] = pidtid_to_comm_map_[parent];
  }

  const uint32_t pid = event.pid;

  // If the parent and child pids are the same, this is just a new thread
  // within the same process, so don't do anything.
  if (event.ppid == pid)
    return true;

  uint32_t ppid = event.ppid;
  if (!GetOrCreateProcessMapper(pid, &ppid).second) {
    DLOG(INFO) << "Found an existing process mapper with pid: " << pid;
  }

  return true;
}

}  // namespace quipper