bin/insntrace/print/third_party/simple-pt/call-printer.cc

/*
 * Copyright (c) 2015, Intel Corporation
 * Author: Andi Kleen
 * All rights reserved.
 *
 * Redistribution and use in source and binary forms, with or without
 * modification, are permitted provided that the following conditions are met:
 *
 * 1. Redistributions of source code must retain the above copyright notice,
 * this list of conditions and the following disclaimer.
 *
 * 2. 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.
 *
 * 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 HOLDER 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.
 */

#include "call-printer.h"

#include <inttypes.h>
#include <stddef.h>
#include <stdio.h>
#include <string.h>

#include <string>
#include <vector>

#include "garnet/lib/intel_pt_decode/decoder.h"

#include <lib/fit/defer.h>

#include "lib/fxl/command_line.h"
#include "lib/fxl/log_settings.h"
#include "lib/fxl/logging.h"
#include "lib/fxl/strings/string_number_conversions.h"
#include "lib/fxl/strings/string_printf.h"

#include "third_party/processor-trace/libipt/include/intel-pt.h"

#include "printer-util.h"

#ifdef HAVE_UDIS86  // TODO(dje): Add disassembly support
#include <udis86.h>
#endif

#define ARRAY_SIZE(x) (sizeof(x) / sizeof(*(x)))
#define container_of(ptr, type, member) \
  ((type*)((char*)(ptr)-offsetof(type, member)))

namespace simple_pt {

// The number of instructions we process at a time.
constexpr uint32_t kInsnsPerIteration = 256u;

std::unique_ptr<CallPrinter> CallPrinter::Create(DecoderState* state,
                                                 const Config& config) {
  FILE* f = stdout;
  if (config.output_file_name != "") {
    f = fopen(config.output_file_name.c_str(), "w");
    if (!f) {
      FXL_LOG(ERROR) << "Unable to open file for writing: "
                     << config.output_file_name;
      return nullptr;
    }
  }

  auto printer =
      std::unique_ptr<CallPrinter>(new CallPrinter(f, state, config));
  return printer;
}

CallPrinter::CallPrinter(FILE* output, DecoderState* state,
                         const Config& config)
    : out_file_(output), state_(state), config_(config) {}

CallPrinter::~CallPrinter() {
  if (config_.output_file_name != "")
    fclose(out_file_);
}

void CallPrinter::Printf(const char* format, ...) {
  va_list args;
  va_start(args, format);
  vfprintf(out_file_, format, args);
  va_end(args);
}

void CallPrinter::PrintPc(const SymbolTable* symtab, const Symbol* sym,
                          uint64_t pc, uint64_t cr3, bool print_cr3) {
  if (sym) {
    Printf("%s", sym->name);
    uint64_t sym_addr = sym->addr + symtab->offset();
    if (pc - sym_addr > 0)
      Printf("+%ld", pc - sym_addr);
    if (config_.dump_pc) {
      Printf(" [");
      if (print_cr3)
        Printf("%lx:", cr3);
      Printf("%lx]", pc);
    }
  } else {
    if (print_cr3)
      Printf("%lx:", cr3);
    Printf("%lx", pc);
  }
}

void CallPrinter::PrintPc(uint64_t pc, uint64_t cr3, bool print_cr3) {
  const SymbolTable* symtab;
  const Symbol* sym = state_->FindSymbol(cr3, pc, &symtab);
  PrintPc(symtab, sym, pc, cr3, print_cr3);
}

void CallPrinter::PrintEv(const char* name, const Instruction* insn) {
  Printf("%s ", name);
  PrintPc(insn->pc, insn->cr3, true);
  Printf("\n");
}

void CallPrinter::PrintEvent(const Instruction* insn) {
#if 0  // TODO(dje) Until these flags are reliable in libipt...
  if (insn->enabled)
    PrintEv("enabled", insn);
  if (insn->disabled)
    PrintEv("disabled", insn);
  if (insn->resumed)
    PrintEv("resumed", insn);
#endif
  if (insn->interrupted)
    PrintEv("interrupted", insn);
  if (insn->resynced)
    PrintEv("resynced", insn);
  if (insn->stopped)
    PrintEv("stopped", insn);
}

static bool HasSpeculativeEvent(const Instruction* insn) {
  return insn->speculative || insn->aborted || insn->committed;
}

void CallPrinter::PrintSpeculativeEvent(const Instruction* insn,
                                        int* prev_spec, int* indent) {
  if (insn->speculative != *prev_spec) {
    *prev_spec = insn->speculative;
    Printf("%*stransaction\n", *indent, "");
    *indent += 4;
  }
  if (insn->aborted) {
    Printf("%*saborted\n", *indent, "");
    *indent -= 4;
  }
  if (insn->committed) {
    Printf("%*scommitted\n", *indent, "");
    *indent -= 4;
  }
  if (*indent < 0)
    *indent = 0;
}

void CallPrinter::PrintTic(uint64_t tic) {
  Printf("[%8" PRIu64 "] ", tic);
}

void CallPrinter::PrintTimeIndent() {
  Printf("%*s", 24, "");
}

void CallPrinter::PrintTime(uint64_t ts,
                            uint64_t* first_ts, uint64_t* last_ts) {
  if (!*first_ts && !config_.abstime)
    *first_ts = ts;
  if (!*last_ts)
    *last_ts = ts;
  uint64_t relative_time = ts - *first_ts;
  uint64_t delta_time = ts - *last_ts;
  Printf("%-24s",
         fxl::StringPrintf("%-9" PRIu64 " [%-" PRIu64 "]",
                           relative_time, delta_time).c_str());
  *last_ts = ts;
}

#ifdef HAVE_UDIS86

struct dis {
  ud_t ud_obj;
  DecoderState* state;
  uint64_t cr3;
};

static const char* DisResolve(struct ud* u, uint64_t addr, int64_t* off) {
  struct dis* d = container_of(u, struct dis, ud_obj);
  Sym* sym = d->state->FindSym(d->cr3, addr);
  if (sym) {
    *off = addr - sym->val;
    return sym->name;
  } else {
    return nullptr;
  }
}

static void InitDis(struct dis* d) {
  ud_init(&d->ud_obj);
  ud_set_syntax(&d->ud_obj, UD_SYN_ATT);
  ud_set_sym_resolver(&d->ud_obj, DisResolve);
}

#else

struct dis {};
static void InitDis(struct dis* d) {}

#endif

#define NUM_WIDTH 35

void CallPrinter::PrintInsn(const struct pt_insn* insn,
                            uint64_t total_insn_count,
                            uint64_t ts, struct dis* d, uint64_t cr3) {
  int i;
  int n;
  Printf("[%8" PRIu64 "] %" PRIx64 " %" PRIu64 " %7s: ",
         total_insn_count, insn->ip, ts, InsnClassName(insn->iclass));
  n = 0;
  for (i = 0; i < insn->size; i++) {
    Printf("%02x ", insn->raw[i]);
    n += 3;
  }
#ifdef HAVE_UDIS86
  d->state = state;
  d->cr3 = cr3;
  if (insn->mode == ptem_32bit)
    ud_set_mode(&d->ud_obj, 32);
  else
    ud_set_mode(&d->ud_obj, 64);
  ud_set_pc(&d->ud_obj, insn->pc);
  ud_set_input_buffer(&d->ud_obj, insn->raw, insn->size);
  ud_disassemble(&d->ud_obj);
  Printf("%*s%s", NUM_WIDTH - n, "", ud_insn_asm(&d->ud_obj));
#endif
  if (insn->enabled)
    Printf("\tENA");
  if (insn->disabled)
    Printf("\tDIS");
  if (insn->resumed)
    Printf("\tRES");
  if (insn->interrupted)
    Printf("\tINT");
  Printf("\n");
#if 0  // TODO(dje): use libbacktrace?
  if (dump_dwarf)
    print_addr(state->FindIpFn(insn->pc, cr3), insn->pc);
#endif
}

void CallPrinter::PrintKernelMarker(const Instruction* insn,
                                    const SymbolTable* symtab) {
  if (symtab) {
    if (symtab->is_kernel())
      Printf(" K");
    else
      Printf(" U");
  } else if (insn->cr3 != pt_asid_no_cr3) {
    // If we're in kernel space on behalf of userspace then that is intended to
    // be caught by the preceding case (symtab != nullptr).
    if (insn->cr3 == state_->kernel_cr3())
      Printf(" K");
    else
      Printf(" U");
  } else {
    Printf(" ?");
  }
}

void CallPrinter::PrintInsnTime(const Instruction* insn,
                                GlobalPrintState* gps) {
  if (insn->ts)
    PrintTime(insn->ts, &gps->first_ts, &gps->last_ts);
  else
    PrintTimeIndent();
}

void CallPrinter::ReportLost(const Instruction* insn) {
  if (config_.report_lost_mtc_cyc && insn->ts) {
    if (insn->lost_mtc)
      Printf("  [lost-mtc:%u]", insn->lost_mtc);
    if (insn->lost_cyc)
      Printf("  [lost-cyc:%u]", insn->lost_cyc);
  }
}

void CallPrinter::PrintOutput(const Instruction* insnbuf, uint32_t count,
                              GlobalPrintState* gps, LocalPrintState* lps) {
  for (uint32_t i = 0; i < count; i++) {
    const Instruction* insn = &insnbuf[i];

    if (insn->core_bus_ratio && insn->core_bus_ratio != gps->core_bus_ratio) {
      Printf("frequency %d\n", insn->core_bus_ratio);
      gps->core_bus_ratio = insn->core_bus_ratio;
    }
    if (HasSpeculativeEvent(insn))
      PrintSpeculativeEvent(insn, &lps->prev_speculative, &lps->indent);
    if (insn->enabled || insn->disabled || insn->resumed || insn->interrupted ||
        insn->resynced || insn->stopped)
      PrintEvent(insn);

    // Note: For accurate output, the collection of instructions we do
    // here needs to match the records printed by decode.
    switch (insn->iclass) {
      case ptic_call:
      case ptic_far_call: {
        PrintTic(insn->tic);
        PrintInsnTime(insn, gps);
        Printf("[+%4u]", insn->insn_delta);
        const SymbolTable* symtab = state_->FindSymbolTable(insn->cr3, insn->pc);
        const Symbol* sym = symtab ? symtab->FindSymbol(insn->pc) : nullptr;
        PrintKernelMarker(insn, symtab);
        Printf(" %-7s", InsnClassName(insn->iclass));
        Printf(" %*s", lps->indent, "");
        PrintPc(symtab, sym, insn->pc, insn->cr3, true);
        Printf(" -> ");
        PrintPc(insn->dst, insn->cr3, false);
        ReportLost(insn);
        Printf("\n");
        lps->indent += 4;
        break;
      }
      case ptic_return:
      case ptic_far_return: {
        PrintTic(insn->tic);
        PrintInsnTime(insn, gps);
        Printf("[+%4u]", insn->insn_delta);
        const SymbolTable* symtab = state_->FindSymbolTable(insn->cr3, insn->pc);
        const Symbol* sym = symtab ? symtab->FindSymbol(insn->pc) : nullptr;
        PrintKernelMarker(insn, symtab);
        Printf(" %-7s", InsnClassName(insn->iclass));
        Printf(" %*s", lps->indent, "");
        PrintPc(symtab, sym, insn->pc, insn->cr3, true);
        ReportLost(insn);
        Printf("\n");
        lps->indent -= 4;
        if (lps->indent < 0)
          lps->indent = 0;
        break;
      }
      default: {
        // Always print if we have a time (for now).
        // Also print error records so that insn counts in the output are
        // easier to follow (more accurate).
        if (insn->ts || insn->iclass == ptic_error) {
          PrintTic(insn->tic);
          PrintInsnTime(insn, gps);
          Printf("[+%4u]", insn->insn_delta);
          const SymbolTable* symtab = state_->FindSymbolTable(insn->cr3, insn->pc);
          const Symbol* sym = symtab ? symtab->FindSymbol(insn->pc) : nullptr;
          PrintKernelMarker(insn, symtab);
          Printf(" %-7s", InsnClassName(insn->iclass));
          Printf(" %*s", lps->indent, "");
          PrintPc(symtab, sym, insn->pc, insn->cr3, true);
          ReportLost(insn);
          Printf("\n");
        }
        break;
      }
    }  // switch
  }
}

void CallPrinter::PrintHeader(uint64_t id) {
  Printf("PT dump for id %" PRIu64 "\n", id);
  Printf("%-10s %-9s %-13s %-7s %c %-7s %s\n", "REF#", "TIME", "DELTA", "INSNs",
         '@', "ICLASS", "LOCATION");
}

uint64_t CallPrinter::PrintOneFile(const PtFile& pt_file) {
  if (!state_->AllocDecoder(pt_file.file)) {
    FXL_LOG(ERROR) << "Unable to open pt file: " << pt_file.file;
    return 0;
  }
  auto free_decoder = fit::defer([&]() {
      state_->FreeDecoder();
    });

  struct pt_insn_decoder* pt_decoder = state_->decoder();
  GlobalPrintState gps = {};
  // While scanning instructions, keep track of updates from the PT decoder.
  // A value of zero means "unknown".
  uint64_t last_ts = 0;
  struct dis dis;

  PrintHeader(pt_file.id);

  // These values are used to guide the printed output.
  gps.first_ts = 0;
  gps.last_ts = 0;

  // This doesn't need to be accurate, it's main purpose is to generate
  // referenceable numbers in the output. It's also used as a measure of
  // the number of instructions we've processed.
  uint64_t total_insn_count = 0;

  InitDis(&dis);

  for (;;) {
    // Every time we get an error while reading the trace we start over
    // at the top of this loop.

    LocalPrintState lps = {};

    int err = pt_insn_sync_forward(pt_decoder);
    if (err < 0) {
      uint64_t pos;
      pt_insn_get_offset(pt_decoder, &pos);
      Printf("%" PRIx64 ": sync forward: %s\n",
             pos, pt_errstr(pt_errcode(err)));
      break;
    }

    // For error reporting.
    uint64_t errcr3 = 0;
    uint64_t errip = 0;

    // Reset core bus ratio calculations.
    uint32_t prev_ratio = 0;

    // A count of the number of instructions since the last emitted record.
    unsigned int insns_since_last_emission = 0;

    do {
      // Instructions processed in this iteration.
      Instruction insnbuf[kInsnsPerIteration];
      // Index into |insnbuf|.
      uint32_t count = 0;

      // For calls we peek ahead to the next insn to see what function
      // was called. If true |insn| is already filled in.
      bool peeked_ahead = false;
      struct pt_insn raw_insn;

      while (!err && count < kInsnsPerIteration) {
        Instruction* insn = &insnbuf[count];

        // Do the increment before checking the result of pt_insn_next so that
        // error lines have reference numbers as well.
        ++total_insn_count;

        // TODO(dje): Verify this always stores values in the arguments even
        // if there's an error (which according to intel-pt.h can only be
        // -pte_no_time).
        pt_insn_time(pt_decoder, &insn->ts, &insn->lost_mtc, &insn->lost_cyc);
        if (insn->ts && insn->ts == last_ts) {
          // No change in the timestamp value, mark as unknown.
          insn->ts = 0;
        }

        if (!peeked_ahead) {
          raw_insn.ip = 0;
          err = pt_insn_next(pt_decoder, &raw_insn, sizeof(raw_insn));
          if (err < 0) {
            pt_insn_get_cr3(pt_decoder, &errcr3);
            errip = raw_insn.ip;
            if (insns_since_last_emission > 0) {
              // Emit a record for the first error in a sequence of them,
              // in part so we don't lose track of the instructions counted
              // so far.
              insn->iclass = ptic_error;
              insn->ts = 0;
              insn->tic = total_insn_count;
              insn->cr3 = errcr3;
              insn->pc = errip;
              insn->insn_delta = insns_since_last_emission;
              insns_since_last_emission = 0;
              ++count;
            }
            break;
          }
        }
        peeked_ahead = false;
        ++insns_since_last_emission;

        pt_insn_get_cr3(pt_decoder, &insn->cr3);
        if (config_.dump_insn)
          PrintInsn(&raw_insn, total_insn_count, insn->ts, &dis, insn->cr3);

        // Watch for changes to the core bus ratio recorded in the trace.
        uint32_t ratio;
        insn->core_bus_ratio = 0;
        pt_insn_core_bus_ratio(pt_decoder, &ratio);
        if (ratio != prev_ratio) {
          insn->core_bus_ratio = ratio;
          prev_ratio = ratio;
        }

        insn->iclass = raw_insn.iclass;

        // Note: For accurate output, the collection of instructions we do
        // here needs to match the records printed by PrintOutput.
        if (raw_insn.iclass == ptic_call || raw_insn.iclass == ptic_far_call) {
          insn->tic = total_insn_count;
          insn->pc = raw_insn.ip;
          insn->insn_delta = insns_since_last_emission;
          insns_since_last_emission = 0;
          ++count;
          TransferEvents(insn, &raw_insn);
          // Peek at the next insn to see what subroutine we called.
          raw_insn.ip = 0;
          err = pt_insn_next(pt_decoder, &raw_insn, sizeof(raw_insn));
          if (err < 0) {
            insn->dst = 0;
            pt_insn_get_cr3(pt_decoder, &errcr3);
            errip = raw_insn.ip;
            break;
          }
          peeked_ahead = true;
          insn->dst = raw_insn.ip;
        } else if (raw_insn.iclass == ptic_return ||
                   raw_insn.iclass == ptic_far_return ||
                   // Always print if we have a time (for now).
                   insn->ts) {
          insn->tic = total_insn_count;
          insn->pc = raw_insn.ip;
          insn->insn_delta = insns_since_last_emission;
          insns_since_last_emission = 0;
          ++count;
          TransferEvents(insn, &raw_insn);
        } else if (raw_insn.enabled || raw_insn.disabled || raw_insn.resumed ||
                   raw_insn.interrupted || raw_insn.resynced
                   || raw_insn.stopped || raw_insn.aborted) {
#if 0  // TODO(dje): experiment to get accurate instruction counts in output
          insn->tic = total_insn_count;
          insn->pc = raw_insn.ip;
          insn->insn_delta = insns_since_last_emission;
          insns_since_last_emission = 0;
          ++count;
          TransferEvents(insn, &raw_insn);
#else
          continue;
#endif
        } else {
          // not interesting
          continue;
        }

        if (insn->ts)
          last_ts = insn->ts;
      }  // while (!err && count < kInsnsPerIteration)

      PrintOutput(insnbuf, count, &gps, &lps);
    } while (err == 0);

    if (err == -pte_eos)
      break;

    {
      uint64_t pos;
      pt_insn_get_offset(pt_decoder, &pos);
      Printf("[%8" PRIu64 "] %" PRIx64 ":%" PRIx64 ":%" PRIx64 ": error %s\n",
             total_insn_count, pos, errcr3, errip, pt_errstr(pt_errcode(err)));
    }
  }

  return total_insn_count;
}

uint64_t CallPrinter::PrintFiles() {
  uint64_t total_insn_count = 0;

  for (const auto& file : state_->pt_files()) {
    total_insn_count += PrintOneFile(file);
  }

  return total_insn_count;
}

}  // namespace simple_pt