Home | History | Annotate | Download | only in quipper
      1 // Copyright (c) 2013 The Chromium OS Authors. All rights reserved.
      2 // Use of this source code is governed by a BSD-style license that can be
      3 // found in the LICENSE file.
      4 
      5 #include "perf_parser.h"
      6 
      7 #include <algorithm>
      8 #include <cstdio>
      9 #include <set>
     10 
     11 #include "base/logging.h"
     12 
     13 #include "address_mapper.h"
     14 #include "quipper_string.h"
     15 #include "perf_utils.h"
     16 
     17 namespace quipper {
     18 
     19 namespace {
     20 
     21 struct EventAndTime {
     22   ParsedEvent* event;
     23   uint64_t time;
     24 };
     25 
     26 // Returns true if |e1| has an earlier timestamp than |e2|.  The args are const
     27 // pointers instead of references because of the way this function is used when
     28 // calling std::stable_sort.
     29 bool CompareParsedEventTimes(const std::unique_ptr<EventAndTime>& e1,
     30                              const std::unique_ptr<EventAndTime>& e2) {
     31   return (e1->time < e2->time);
     32 }
     33 
     34 // Kernel MMAP entry pid appears as -1
     35 const uint32_t kKernelPid = UINT32_MAX;
     36 
     37 // Name and ID of the kernel swapper process.
     38 const char kSwapperCommandName[] = "swapper";
     39 const uint32_t kSwapperPid = 0;
     40 
     41 bool IsNullBranchStackEntry(const struct branch_entry& entry) {
     42   return (!entry.from && !entry.to);
     43 }
     44 
     45 }  // namespace
     46 
     47 PerfParser::PerfParser()
     48     : kernel_mapper_(new AddressMapper)
     49 {}
     50 
     51 PerfParser::~PerfParser() {}
     52 
     53 PerfParser::PerfParser(const PerfParser::Options& options) {
     54   options_ = options;
     55 }
     56 
     57 void PerfParser::set_options(const PerfParser::Options& options) {
     58   options_ = options;
     59 }
     60 
     61 bool PerfParser::ParseRawEvents() {
     62   process_mappers_.clear();
     63   parsed_events_.resize(events_.size());
     64   for (size_t i = 0; i < events_.size(); ++i) {
     65     ParsedEvent& parsed_event = parsed_events_[i];
     66     parsed_event.raw_event = events_[i].get();
     67   }
     68   MaybeSortParsedEvents();
     69   if (!ProcessEvents()) {
     70     return false;
     71   }
     72 
     73   if (!options_.discard_unused_events)
     74     return true;
     75 
     76   // Some MMAP/MMAP2 events' mapped regions will not have any samples. These
     77   // MMAP/MMAP2 events should be dropped. |parsed_events_| should be
     78   // reconstructed without these events.
     79   size_t write_index = 0;
     80   size_t read_index;
     81   for (read_index = 0; read_index < parsed_events_.size(); ++read_index) {
     82     const ParsedEvent& event = parsed_events_[read_index];
     83     if ((event.raw_event->header.type == PERF_RECORD_MMAP ||
     84          event.raw_event->header.type == PERF_RECORD_MMAP2) &&
     85         event.num_samples_in_mmap_region == 0) {
     86       continue;
     87     }
     88     if (read_index != write_index)
     89       parsed_events_[write_index] = event;
     90     ++write_index;
     91   }
     92   CHECK_LE(write_index, parsed_events_.size());
     93   parsed_events_.resize(write_index);
     94 
     95   // Now regenerate the sorted event list again.  These are pointers to events
     96   // so they must be regenerated after a resize() of the ParsedEvent vector.
     97   MaybeSortParsedEvents();
     98 
     99   return true;
    100 }
    101 
    102 void PerfParser::MaybeSortParsedEvents() {
    103   if (!(sample_type_ & PERF_SAMPLE_TIME)) {
    104     parsed_events_sorted_by_time_.resize(parsed_events_.size());
    105     for (size_t i = 0; i < parsed_events_.size(); ++i) {
    106       parsed_events_sorted_by_time_[i] = &parsed_events_[i];
    107     }
    108     return;
    109   }
    110   std::vector<std::unique_ptr<EventAndTime>> events_and_times;
    111   events_and_times.resize(parsed_events_.size());
    112   for (size_t i = 0; i < parsed_events_.size(); ++i) {
    113     std::unique_ptr<EventAndTime> event_and_time(new EventAndTime);
    114 
    115     // Store the timestamp and event pointer in an array.
    116     event_and_time->event = &parsed_events_[i];
    117 
    118     struct perf_sample sample_info;
    119     PerfSampleCustodian custodian(sample_info);
    120     CHECK(ReadPerfSampleInfo(*parsed_events_[i].raw_event, &sample_info));
    121     event_and_time->time = sample_info.time;
    122 
    123     events_and_times[i] = std::move(event_and_time);
    124   }
    125   // Sort the events based on timestamp, and then populate the sorted event
    126   // vector in sorted order.
    127   std::stable_sort(events_and_times.begin(), events_and_times.end(),
    128                    CompareParsedEventTimes);
    129 
    130   parsed_events_sorted_by_time_.resize(events_and_times.size());
    131   for (unsigned int i = 0; i < events_and_times.size(); ++i) {
    132     parsed_events_sorted_by_time_[i] = events_and_times[i]->event;
    133   }
    134 }
    135 
    136 bool PerfParser::ProcessEvents() {
    137   memset(&stats_, 0, sizeof(stats_));
    138 
    139   stats_.did_remap = false;   // Explicitly clear the remap flag.
    140 
    141   // Pid 0 is called the swapper process. Even though perf does not record a
    142   // COMM event for pid 0, we act like we did receive a COMM event for it. Perf
    143   // does this itself, example:
    144   //   http://lxr.free-electrons.com/source/tools/perf/util/session.c#L1120
    145   commands_.insert(kSwapperCommandName);
    146   pidtid_to_comm_map_[std::make_pair(kSwapperPid, kSwapperPid)] =
    147       &(*commands_.find(kSwapperCommandName));
    148 
    149   // NB: Not necessarily actually sorted by time.
    150   for (unsigned int i = 0; i < parsed_events_sorted_by_time_.size(); ++i) {
    151     ParsedEvent& parsed_event = *parsed_events_sorted_by_time_[i];
    152     event_t& event = *parsed_event.raw_event;
    153     switch (event.header.type) {
    154       case PERF_RECORD_SAMPLE:
    155         // SAMPLE doesn't have any fields to log at a fixed,
    156         // previously-endian-swapped location. This used to log ip.
    157         VLOG(1) << "SAMPLE";
    158         ++stats_.num_sample_events;
    159 
    160         if (MapSampleEvent(&parsed_event)) {
    161           ++stats_.num_sample_events_mapped;
    162         }
    163         break;
    164       case PERF_RECORD_MMAP: {
    165         VLOG(1) << "MMAP: " << event.mmap.filename;
    166         ++stats_.num_mmap_events;
    167         // Use the array index of the current mmap event as a unique identifier.
    168         CHECK(MapMmapEvent(&event.mmap, i)) << "Unable to map MMAP event!";
    169         // No samples in this MMAP region yet, hopefully.
    170         parsed_event.num_samples_in_mmap_region = 0;
    171         DSOInfo dso_info;
    172         // TODO(sque): Add Build ID as well.
    173         dso_info.name = event.mmap.filename;
    174         dso_set_.insert(dso_info);
    175         break;
    176       }
    177       case PERF_RECORD_MMAP2: {
    178         VLOG(1) << "MMAP2: " << event.mmap2.filename;
    179         ++stats_.num_mmap_events;
    180         // Use the array index of the current mmap event as a unique identifier.
    181         CHECK(MapMmapEvent(&event.mmap2, i)) << "Unable to map MMAP2 event!";
    182         // No samples in this MMAP region yet, hopefully.
    183         parsed_event.num_samples_in_mmap_region = 0;
    184         DSOInfo dso_info;
    185         // TODO(sque): Add Build ID as well.
    186         dso_info.name = event.mmap2.filename;
    187         dso_set_.insert(dso_info);
    188         break;
    189       }
    190       case PERF_RECORD_FORK:
    191         VLOG(1) << "FORK: " << event.fork.ppid << ":" << event.fork.ptid
    192                 << " -> " << event.fork.pid << ":" << event.fork.tid;
    193         ++stats_.num_fork_events;
    194         CHECK(MapForkEvent(event.fork)) << "Unable to map FORK event!";
    195         break;
    196       case PERF_RECORD_EXIT:
    197         // EXIT events have the same structure as FORK events.
    198         VLOG(1) << "EXIT: " << event.fork.ppid << ":" << event.fork.ptid;
    199         ++stats_.num_exit_events;
    200         break;
    201       case PERF_RECORD_COMM:
    202         VLOG(1) << "COMM: " << event.comm.pid << ":" << event.comm.tid << ": "
    203                 << event.comm.comm;
    204         ++stats_.num_comm_events;
    205         CHECK(MapCommEvent(event.comm));
    206         commands_.insert(event.comm.comm);
    207         pidtid_to_comm_map_[std::make_pair(event.comm.pid, event.comm.tid)] =
    208             &(*commands_.find(event.comm.comm));
    209         break;
    210       case PERF_RECORD_LOST:
    211       case PERF_RECORD_THROTTLE:
    212       case PERF_RECORD_UNTHROTTLE:
    213       case PERF_RECORD_READ:
    214       case PERF_RECORD_MAX:
    215         VLOG(1) << "Parsed event type: " << event.header.type
    216                 << ". Doing nothing.";
    217         break;
    218       default:
    219         LOG(ERROR) << "Unknown event type: " << event.header.type;
    220         return false;
    221     }
    222   }
    223 
    224   // Print stats collected from parsing.
    225   DLOG(INFO) << "Parser processed: "
    226             << stats_.num_mmap_events << " MMAP/MMAP2 events, "
    227             << stats_.num_comm_events << " COMM events, "
    228             << stats_.num_fork_events << " FORK events, "
    229             << stats_.num_exit_events << " EXIT events, "
    230             << stats_.num_sample_events << " SAMPLE events, "
    231             << stats_.num_sample_events_mapped << " of these were mapped";
    232 
    233   float sample_mapping_percentage =
    234       static_cast<float>(stats_.num_sample_events_mapped) /
    235       stats_.num_sample_events * 100.;
    236   float threshold = options_.sample_mapping_percentage_threshold;
    237   if (sample_mapping_percentage < threshold) {
    238     LOG(WARNING) << "Mapped " << static_cast<int>(sample_mapping_percentage)
    239                << "% of samples, expected at least "
    240                << static_cast<int>(threshold) << "%";
    241     return false;
    242   }
    243   stats_.did_remap = options_.do_remap;
    244   return true;
    245 }
    246 
    247 bool PerfParser::MapSampleEvent(ParsedEvent* parsed_event) {
    248   bool mapping_failed = false;
    249 
    250   // Find the associated command.
    251   if (!(sample_type_ & PERF_SAMPLE_IP && sample_type_ & PERF_SAMPLE_TID))
    252     return false;
    253   perf_sample sample_info;
    254   PerfSampleCustodian custodian(sample_info);
    255   if (!ReadPerfSampleInfo(*parsed_event->raw_event, &sample_info))
    256     return false;
    257   PidTid pidtid = std::make_pair(sample_info.pid, sample_info.tid);
    258   const auto comm_iter = pidtid_to_comm_map_.find(pidtid);
    259   if (comm_iter != pidtid_to_comm_map_.end()) {
    260     parsed_event->set_command(comm_iter->second);
    261   }
    262 
    263   const uint64_t unmapped_event_ip = sample_info.ip;
    264 
    265   // Map the event IP itself.
    266   if (!MapIPAndPidAndGetNameAndOffset(sample_info.ip,
    267                                       sample_info.pid,
    268                                       &sample_info.ip,
    269                                       &parsed_event->dso_and_offset)) {
    270     mapping_failed = true;
    271   }
    272 
    273   if (sample_info.callchain &&
    274       !MapCallchain(sample_info.ip,
    275                     sample_info.pid,
    276                     unmapped_event_ip,
    277                     sample_info.callchain,
    278                     parsed_event)) {
    279     mapping_failed = true;
    280   }
    281 
    282   if (sample_info.branch_stack &&
    283       !MapBranchStack(sample_info.pid,
    284                       sample_info.branch_stack,
    285                       parsed_event)) {
    286     mapping_failed = true;
    287   }
    288 
    289   // Write the remapped data back to the raw event regardless of whether it was
    290   // entirely successfully remapped.  A single failed remap should not
    291   // invalidate all the other remapped entries.
    292   if (!WritePerfSampleInfo(sample_info, parsed_event->raw_event)) {
    293     LOG(ERROR) << "Failed to write back remapped sample info.";
    294     return false;
    295   }
    296 
    297   return !mapping_failed;
    298 }
    299 
    300 bool PerfParser::MapCallchain(const uint64_t ip,
    301                               const uint32_t pid,
    302                               const uint64_t original_event_addr,
    303                               struct ip_callchain* callchain,
    304                               ParsedEvent* parsed_event) {
    305   if (!callchain) {
    306     LOG(ERROR) << "NULL call stack data.";
    307     return false;
    308   }
    309 
    310   bool mapping_failed = false;
    311 
    312   // If the callchain's length is 0, there is no work to do.
    313   if (callchain->nr == 0)
    314     return true;
    315 
    316   // Keeps track of whether the current entry is kernel or user.
    317   parsed_event->callchain.resize(callchain->nr);
    318   int num_entries_mapped = 0;
    319   for (unsigned int j = 0; j < callchain->nr; ++j) {
    320     uint64_t entry = callchain->ips[j];
    321     // When a callchain context entry is found, do not attempt to symbolize it.
    322     if (entry >= PERF_CONTEXT_MAX) {
    323       continue;
    324     }
    325     // The sample address has already been mapped so no need to map it.
    326     if (entry == original_event_addr) {
    327       callchain->ips[j] = ip;
    328       continue;
    329     }
    330     if (!MapIPAndPidAndGetNameAndOffset(
    331             entry,
    332             pid,
    333             &callchain->ips[j],
    334             &parsed_event->callchain[num_entries_mapped++])) {
    335       mapping_failed = true;
    336     }
    337   }
    338   // Not all the entries were mapped.  Trim |parsed_event->callchain| to
    339   // remove unused entries at the end.
    340   parsed_event->callchain.resize(num_entries_mapped);
    341 
    342   return !mapping_failed;
    343 }
    344 
    345 bool PerfParser::MapBranchStack(const uint32_t pid,
    346                                 struct branch_stack* branch_stack,
    347                                 ParsedEvent* parsed_event) {
    348   if (!branch_stack) {
    349     LOG(ERROR) << "NULL branch stack data.";
    350     return false;
    351   }
    352 
    353   // First, trim the branch stack to remove trailing null entries.
    354   size_t trimmed_size = 0;
    355   for (size_t i = 0; i < branch_stack->nr; ++i) {
    356     // Count the number of non-null entries before the first null entry.
    357     if (IsNullBranchStackEntry(branch_stack->entries[i])) {
    358       break;
    359     }
    360     ++trimmed_size;
    361   }
    362 
    363   // If a null entry was found, make sure all subsequent null entries are NULL
    364   // as well.
    365   for (size_t i = trimmed_size; i < branch_stack->nr; ++i) {
    366     const struct branch_entry& entry = branch_stack->entries[i];
    367     if (!IsNullBranchStackEntry(entry)) {
    368       LOG(ERROR) << "Non-null branch stack entry found after null entry: "
    369                  << reinterpret_cast<void*>(entry.from) << " -> "
    370                  << reinterpret_cast<void*>(entry.to);
    371       return false;
    372     }
    373   }
    374 
    375   // Map branch stack addresses.
    376   parsed_event->branch_stack.resize(trimmed_size);
    377   for (unsigned int i = 0; i < trimmed_size; ++i) {
    378     struct branch_entry& entry = branch_stack->entries[i];
    379     ParsedEvent::BranchEntry& parsed_entry = parsed_event->branch_stack[i];
    380     if (!MapIPAndPidAndGetNameAndOffset(entry.from,
    381                                         pid,
    382                                         &entry.from,
    383                                         &parsed_entry.from)) {
    384       return false;
    385     }
    386     if (!MapIPAndPidAndGetNameAndOffset(entry.to,
    387                                         pid,
    388                                         &entry.to,
    389                                         &parsed_entry.to)) {
    390       return false;
    391     }
    392     parsed_entry.predicted = entry.flags.predicted;
    393     // Either predicted or mispredicted, not both. But don't use a CHECK here,
    394     // just exit gracefully because it's a minor issue.
    395     if (entry.flags.predicted == entry.flags.mispred) {
    396       LOG(ERROR) << "Branch stack entry predicted and mispred flags "
    397                  << "both have value " << entry.flags.mispred;
    398       return false;
    399     }
    400   }
    401 
    402   return true;
    403 }
    404 
    405 bool PerfParser::MapIPAndPidAndGetNameAndOffset(
    406     uint64_t ip,
    407     uint32_t pid,
    408     uint64_t* new_ip,
    409     ParsedEvent::DSOAndOffset* dso_and_offset) {
    410 
    411   // Attempt to find the synthetic address of the IP sample in this order:
    412   // 1. Address space of its own process.
    413   // 2. Address space of the kernel.
    414 
    415   uint64_t mapped_addr = 0;
    416 
    417   // Sometimes the first event we see is a SAMPLE event and we don't have the
    418   // time to create an address mapper for a process. Example, for pid 0.
    419   AddressMapper* mapper = GetOrCreateProcessMapper(pid).first;
    420   bool mapped = mapper->GetMappedAddress(ip, &mapped_addr);
    421   if (!mapped) {
    422     mapper = kernel_mapper_.get();
    423     mapped = mapper->GetMappedAddress(ip, &mapped_addr);
    424   }
    425 
    426   // TODO(asharif): What should we do when we cannot map a SAMPLE event?
    427   if (mapped) {
    428     if (dso_and_offset) {
    429       uint64_t id = kuint64max;
    430       CHECK(mapper->GetMappedIDAndOffset(ip, &id, &dso_and_offset->offset_));
    431       // Make sure the ID points to a valid event.
    432       CHECK_LE(id, parsed_events_sorted_by_time_.size());
    433       ParsedEvent* parsed_event = parsed_events_sorted_by_time_[id];
    434       const event_t* raw_event = parsed_event->raw_event;
    435 
    436       DSOInfo dso_info;
    437       if (raw_event->header.type == PERF_RECORD_MMAP) {
    438         dso_info.name = raw_event->mmap.filename;
    439       } else if (raw_event->header.type == PERF_RECORD_MMAP2) {
    440         dso_info.name = raw_event->mmap2.filename;
    441       } else {
    442         LOG(FATAL) << "Expected MMAP or MMAP2 event";
    443       }
    444 
    445       // Find the mmap DSO filename in the set of known DSO names.
    446       // TODO(sque): take build IDs into account.
    447       std::set<DSOInfo>::const_iterator dso_iter = dso_set_.find(dso_info);
    448       CHECK(dso_iter != dso_set_.end());
    449       dso_and_offset->dso_info_ = &(*dso_iter);
    450 
    451       ++parsed_event->num_samples_in_mmap_region;
    452     }
    453     if (options_.do_remap)
    454       *new_ip = mapped_addr;
    455   }
    456   return mapped;
    457 }
    458 
    459 bool PerfParser::MapMmapEvent(uint64_t id,
    460                               uint32_t pid,
    461                               uint64_t* p_start,
    462                               uint64_t* p_len,
    463                               uint64_t* p_pgoff)
    464 {
    465   // We need to hide only the real kernel addresses.  However, to make things
    466   // more secure, and make the mapping idempotent, we should remap all
    467   // addresses, both kernel and non-kernel.
    468   AddressMapper* mapper =
    469       (pid == kKernelPid ? kernel_mapper_.get() :
    470        GetOrCreateProcessMapper(pid).first);
    471 
    472   uint64_t start = *p_start;
    473   uint64_t len = *p_len;
    474   uint64_t pgoff = *p_pgoff;
    475 
    476   // |id| == 0 corresponds to the kernel mmap. We have several cases here:
    477   //
    478   // For ARM and x86, in sudo mode, pgoff == start, example:
    479   // start=0x80008200
    480   // pgoff=0x80008200
    481   // len  =0xfffffff7ff7dff
    482   //
    483   // For x86-64, in sudo mode, pgoff is between start and start + len. SAMPLE
    484   // events lie between pgoff and pgoff + length of the real kernel binary,
    485   // example:
    486   // start=0x3bc00000
    487   // pgoff=0xffffffffbcc00198
    488   // len  =0xffffffff843fffff
    489   // SAMPLE events will be found after pgoff. For kernels with ASLR, pgoff will
    490   // be something only visible to the root user, and will be randomized at
    491   // startup. With |remap| set to true, we should hide pgoff in this case. So we
    492   // normalize all SAMPLE events relative to pgoff.
    493   //
    494   // For non-sudo mode, the kernel will be mapped from 0 to the pointer limit,
    495   // example:
    496   // start=0x0
    497   // pgoff=0x0
    498   // len  =0xffffffff
    499   if (id == 0) {
    500     // If pgoff is between start and len, we normalize the event by setting
    501     // start to be pgoff just like how it is for ARM and x86. We also set len to
    502     // be a much smaller number (closer to the real length of the kernel binary)
    503     // because SAMPLEs are actually only seen between |event->pgoff| and
    504     // |event->pgoff + kernel text size|.
    505     if (pgoff > start && pgoff < start + len) {
    506       len = len + start - pgoff;
    507       start = pgoff;
    508     }
    509     // For kernels with ALSR pgoff is critical information that should not be
    510     // revealed when |remap| is true.
    511     pgoff = 0;
    512   }
    513 
    514   if (!mapper->MapWithID(start, len, id, pgoff, true)) {
    515     mapper->DumpToLog();
    516     return false;
    517   }
    518 
    519   if (options_.do_remap) {
    520     uint64_t mapped_addr;
    521     CHECK(mapper->GetMappedAddress(start, &mapped_addr));
    522     *p_start = mapped_addr;
    523     *p_len = len;
    524     *p_pgoff = pgoff;
    525   }
    526   return true;
    527 }
    528 
    529 std::pair<AddressMapper*, bool> PerfParser::GetOrCreateProcessMapper(
    530     uint32_t pid, uint32_t *ppid) {
    531   const auto& search = process_mappers_.find(pid);
    532   if (search != process_mappers_.end()) {
    533     return std::make_pair(search->second.get(), false);
    534   }
    535 
    536   std::unique_ptr<AddressMapper> mapper;
    537   const auto& parent_mapper = (ppid ? process_mappers_.find(*ppid) : process_mappers_.end());
    538   if (parent_mapper != process_mappers_.end())
    539       mapper.reset(new AddressMapper(*parent_mapper->second));
    540   else
    541     mapper.reset(new AddressMapper());
    542 
    543   const auto inserted =
    544       process_mappers_.insert(search, std::make_pair(pid, std::move(mapper)));
    545   return std::make_pair(inserted->second.get(), true);
    546 }
    547 
    548 bool PerfParser::MapCommEvent(const struct comm_event& event) {
    549   GetOrCreateProcessMapper(event.pid);
    550   return true;
    551 }
    552 
    553 bool PerfParser::MapForkEvent(const struct fork_event& event) {
    554   PidTid parent = std::make_pair(event.ppid, event.ptid);
    555   PidTid child = std::make_pair(event.pid, event.tid);
    556   if (parent != child &&
    557       pidtid_to_comm_map_.find(parent) != pidtid_to_comm_map_.end()) {
    558     pidtid_to_comm_map_[child] = pidtid_to_comm_map_[parent];
    559   }
    560 
    561   const uint32_t pid = event.pid;
    562 
    563   // If the parent and child pids are the same, this is just a new thread
    564   // within the same process, so don't do anything.
    565   if (event.ppid == pid)
    566     return true;
    567 
    568   uint32_t ppid = event.ppid;
    569   if (!GetOrCreateProcessMapper(pid, &ppid).second) {
    570     DLOG(INFO) << "Found an existing process mapper with pid: " << pid;
    571   }
    572 
    573   return true;
    574 }
    575 
    576 }  // namespace quipper
    577