garnet/bin/insntrace/control.cc

// Copyright 2016 The Fuchsia 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 "garnet/bin/insntrace/control.h"

#include <fcntl.h>
#include <fuchsia/hardware/cpu/insntrace/cpp/fidl.h>
#include <lib/fdio/directory.h>
#include <lib/fdio/fd.h>
#include <lib/fdio/fdio.h>
#include <lib/syslog/cpp/macros.h>
#include <lib/zircon-internal/device/cpu-trace/intel-pt.h>
#include <lib/zircon-internal/ktrace.h>
#include <lib/zx/handle.h>
#include <lib/zx/vmo.h>
#include <link.h>
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <zircon/syscalls.h>

#include <cinttypes>
#include <iostream>

#include <fbl/unique_fd.h>

#include "garnet/bin/insntrace/config.h"
#include "garnet/bin/insntrace/ktrace_controller.h"
#include "garnet/bin/insntrace/utils.h"
#include "garnet/lib/debugger_utils/util.h"
#include "garnet/lib/debugger_utils/x86_cpuid.h"
#include "garnet/lib/debugger_utils/x86_pt.h"
#include "src/lib/fxl/strings/string_printf.h"

namespace insntrace {

using Allocation = ::fuchsia::hardware::cpu::insntrace::Allocation;
using BufferConfig = ::fuchsia::hardware::cpu::insntrace::BufferConfig;
using BufferState = ::fuchsia::hardware::cpu::insntrace::BufferState;
using ControllerSyncPtr = ::fuchsia::hardware::cpu::insntrace::ControllerSyncPtr;

// This isn't emitted by the fidl compiler.
using BufferDescriptor = uint32_t;

static constexpr char ipt_device_path[] = "/dev/sys/cpu-trace/insntrace";

static constexpr char buffer_output_path_suffix[] = "pt";
static constexpr char ktrace_output_path_suffix[] = "ktrace";
static constexpr char cpuid_output_path_suffix[] = "cpuid";
static constexpr char pt_list_output_path_suffix[] = "ptlist";

static constexpr uint32_t kKtraceGroupMask = KTRACE_GRP_ARCH | KTRACE_GRP_TASKS;

static ControllerSyncPtr OpenDevice() {
  ControllerSyncPtr controller_ptr;
  zx_status_t status =
      fdio_service_connect(ipt_device_path, controller_ptr.NewRequest().TakeChannel().release());
  if (status != ZX_OK) {
    FX_LOGS(ERROR) << "Error connecting to " << ipt_device_path << ": " << status;
    return ControllerSyncPtr();
  }
  return controller_ptr;
}

bool AllocTrace(const IptConfig& config) {
  FX_LOGS(INFO) << "AllocTrace called";

  ControllerSyncPtr ipt{OpenDevice()};
  if (!ipt) {
    return false;
  }

  Allocation allocation;
  // TODO(61706): memset is done as the padding is set to 0xAA in release builds and encoding of the
  // FIDL request fails as the non-zero padding is also copied to the FIDL message.
  // Remove this once the bug is fixed.
  memset(&allocation, 0x0, sizeof(Allocation));
  allocation.mode = config.mode;
  allocation.num_traces = (config.mode == Mode::CPU ? config.num_cpus : config.max_threads);
  FX_VLOGS(2) << fxl::StringPrintf("mode=%u, num_traces=0x%x",
                                   static_cast<unsigned>(allocation.mode), allocation.num_traces);

  ::fuchsia::hardware::cpu::insntrace::Controller_Initialize_Result result;
  zx_status_t status = ipt->Initialize(allocation, &result);
  if (status != ZX_OK || result.is_err()) {
    LogFidlFailure("Initialize", status, result.err());
    return false;
  }

  return true;
}

static void InitIptBufferConfig(BufferConfig* ipt_config, const IptConfig& config) {
  memset(ipt_config, 0, sizeof(*ipt_config));
  ipt_config->num_chunks = config.num_chunks;
  ipt_config->chunk_order = config.chunk_order;
  ipt_config->is_circular = config.is_circular;
  ipt_config->ctl = config.CtlMsr();
  ipt_config->address_space_match = config.cr3_match;
  ipt_config->address_range_0.start = config.AddrBegin(0);
  ipt_config->address_range_0.end = config.AddrEnd(0);
  ipt_config->address_range_1.start = config.AddrBegin(1);
  ipt_config->address_range_1.end = config.AddrEnd(1);
}

bool InitTrace(const IptConfig& config) {
  FX_LOGS(INFO) << "InitTrace called";
  FX_DCHECK(config.mode == Mode::CPU);

  ControllerSyncPtr ipt{OpenDevice()};
  if (!ipt) {
    return false;
  }

  for (uint32_t cpu = 0; cpu < config.num_cpus; ++cpu) {
    BufferConfig ipt_config;
    InitIptBufferConfig(&ipt_config, config);

    ::fuchsia::hardware::cpu::insntrace::Controller_AllocateBuffer_Result result;
    zx_status_t status = ipt->AllocateBuffer(ipt_config, &result);
    if (status != ZX_OK || result.is_err()) {
      LogFidlFailure("AllocateBuffer", status, result.err());
      return false;
    }
    // Buffers are automagically assigned to cpus, descriptor == cpu#,
    // so we can just ignore descriptor here.
  }

  return true;
}

// This must be called before a process is started so we emit a ktrace
// process start record for it.

bool InitProcessTrace(const IptConfig& config) {
  FX_LOGS(INFO) << "InitProcessTrace called";

  fuchsia::tracing::kernel::ControllerSyncPtr ktrace;
  if (OpenKtraceControllerChannel(&ktrace) != ZX_OK) {
    return false;
  }

  // If tracing cpus we may want all the records for processes that were
  // started during boot, so don't reset ktrace here. If tracing threads it
  // doesn't much matter other than hopefully the necessary records don't get
  // over run, which is handled below by only enabling the collection groups
  // we need. So for now leave existing records alone.
  // A better solution would be to collect the data we need at the time we
  // need it.
#if 0  // TODO(dje)
  if (config.mode == Mode::THREAD) {
    RequestKtraceStop(ktrace);
    RequestKtraceRewind(ktrace);
  }
#endif

  // We definitely need ktrace turned on in order to get cr3->pid mappings,
  // which we need to map trace cr3 values to ld.so mappings, which we need in
  // order to be able to find the ELFs, which are required by the decoder.
  // So this isn't a nice-to-have, we need it. It's possible ktrace is
  // currently off, so ensure it's turned on.
  // For now just include arch info in the ktrace - we need it, and we don't
  // want to risk the ktrace buffer filling without it.
  // Also include task info to get process exit records - we need to know when
  // a cr3 value becomes invalid. Hopefully this won't cause the buffer to
  // overrun. It it does we could consider having special ktrace records just
  // for this, but that's a last resort kind of thing.
  if (RequestKtraceStart(ktrace, kKtraceGroupMask)) {
    return true;
  }

  // TODO(dje): Resume original ktracing? Need ability to get old value.
  RequestKtraceStop(ktrace);
  return false;
}

bool StartTrace(const IptConfig& config) {
  FX_LOGS(INFO) << "StartTrace called";
  FX_DCHECK(config.mode == Mode::CPU);

  ControllerSyncPtr ipt{OpenDevice()};
  if (!ipt) {
    return false;
  }

  zx_status_t status = ipt->Start();
  if (status != ZX_OK) {
    LogFidlFailure("Start", status);
    return false;
  }

  return true;
}

void StopTrace(const IptConfig& config) {
  FX_LOGS(INFO) << "StopTrace called";
  FX_DCHECK(config.mode == Mode::CPU);

  ControllerSyncPtr ipt{OpenDevice()};
  if (!ipt) {
    return;
  }

  [[maybe_unused]] zx_status_t status = ipt->Stop();
  FX_DCHECK(status == ZX_OK);
}

void StopSidebandDataCollection(const IptConfig& config) {
  FX_LOGS(INFO) << "StopSidebandDataCollection called";

  fuchsia::tracing::kernel::ControllerSyncPtr ktrace;
  if (OpenKtraceControllerChannel(&ktrace) != ZX_OK) {
    return;
  }

  // Avoid having the records we need overrun by the time we collect them by
  // stopping ktrace here. It will get turned back on by "reset".
  RequestKtraceStop(ktrace);
}

static std::string GetCpuPtFileName(const std::string& output_path_prefix, uint64_t id) {
  const char* name_prefix = "cpu";
  return fxl::StringPrintf("%s.%s%" PRIu64 ".%s", output_path_prefix.c_str(), name_prefix, id,
                           buffer_output_path_suffix);
}

static std::string GetThreadPtFileName(const std::string& output_path_prefix, uint64_t id) {
  const char* name_prefix = "thr";
  return fxl::StringPrintf("%s.%s%" PRIu64 ".%s", output_path_prefix.c_str(), name_prefix, id,
                           buffer_output_path_suffix);
}

// Write the contents of buffer |descriptor| to a file.
// The file's name is $output_path_prefix.$name_prefix$id.pt.

static zx_status_t WriteBufferData(const IptConfig& config, const ControllerSyncPtr& ipt,
                                   uint32_t descriptor, uint64_t id) {
  std::string output_path;
  if (config.mode == Mode::CPU)
    output_path = GetCpuPtFileName(config.output_path_prefix, id);
  else
    output_path = GetThreadPtFileName(config.output_path_prefix, id);
  const char* c_path = output_path.c_str();

  // Refetch the buffer config as we can be invoked in a separate process,
  // after tracing has started, and shouldn't rely on what the user thinks
  // the config is.
  std::unique_ptr<BufferConfig> buffer_config;
  zx_status_t status = ipt->GetBufferConfig(descriptor, &buffer_config);
  if (status != ZX_OK) {
    LogFidlFailure("GetBufferConfig", status);
    return status;
  }
  if (!buffer_config) {
    FX_LOGS(ERROR) << "Failed getting buffer config";
    return ZX_ERR_INTERNAL;
  }

  std::unique_ptr<BufferState> buffer_state;
  status = ipt->GetBufferState(descriptor, &buffer_state);
  if (status != ZX_OK) {
    LogFidlFailure("GetBufferState", status);
    return status;
  }
  if (!buffer_state) {
    FX_LOGS(ERROR) << "Failed getting buffer state";
    return ZX_ERR_INTERNAL;
  }

  fbl::unique_fd fd(open(c_path, O_CREAT | O_TRUNC | O_RDWR, S_IRUSR | S_IWUSR));
  if (!fd.is_valid()) {
    FX_LOGS(ERROR) << fxl::StringPrintf("Failed writing file: %s", c_path) << ", "
                   << debugger_utils::ErrnoString(errno);
    return ZX_ERR_BAD_PATH;
  }

  // TODO(dje): Fetch from vmo?
  size_t chunk_size = (1 << buffer_config->chunk_order) * PAGE_SIZE;
  uint32_t num_chunks = buffer_config->num_chunks;

  // If using a circular buffer there's (currently) no way to know if
  // tracing wrapped, so for now we just punt and always dump the entire
  // buffer. It's highly likely it wrapped anyway.
  size_t bytes_left;
  if (buffer_config->is_circular)
    bytes_left = num_chunks * chunk_size;
  else
    bytes_left = buffer_state->capture_end;

  FX_LOGS(INFO) << fxl::StringPrintf("Writing %zu bytes to %s", bytes_left, c_path);

  char buf[4096];

  for (uint32_t i = 0; i < num_chunks && bytes_left > 0; ++i) {
    zx::vmo vmo;
    status = ipt->GetChunkHandle(descriptor, i, &vmo);
    if (status != ZX_OK) {
      LogFidlFailure("GetChunkHandle", status);
      FX_LOGS(ERROR) << "Buffer " << descriptor << ", chunk " << i;
      goto Fail;
    }

    size_t buffer_remaining = chunk_size;
    size_t offset = 0;
    while (buffer_remaining && bytes_left) {
      size_t to_write = sizeof(buf);
      if (to_write > buffer_remaining)
        to_write = buffer_remaining;
      if (to_write > bytes_left)
        to_write = bytes_left;
      // TODO(dje): Mapping into process and reading directly from that
      // left for another day.
      status = vmo.read(buf, offset, to_write);
      if (status != ZX_OK) {
        FX_LOGS(ERROR) << fxl::StringPrintf("zx_vmo_read: buffer %u, buffer %u, offset %zu: ",
                                            descriptor, i, offset)
                       << debugger_utils::ZxErrorString(status);
        goto Fail;
      }
      if (write(fd.get(), buf, to_write) != (ssize_t)to_write) {
        FX_LOGS(ERROR) << fxl::StringPrintf("Short write, file: %s\n", c_path);
        status = ZX_ERR_IO;
        goto Fail;
      }
      offset += to_write;
      buffer_remaining -= to_write;
      bytes_left -= to_write;
    }
  }

  assert(bytes_left == 0);
  status = ZX_OK;
  // fallthrough

Fail:
  // We don't delete the file on failure on purpose, it is kept for
  // debugging purposes.
  return status;
}

// Write all output files.
// This assumes tracing has already been stopped.

void DumpTrace(const IptConfig& config) {
  FX_LOGS(INFO) << "DumpTrace called";
  FX_DCHECK(config.mode == Mode::CPU);

  ControllerSyncPtr ipt{OpenDevice()};
  if (!ipt) {
    return;
  }

  for (uint32_t cpu = 0; cpu < config.num_cpus; ++cpu) {
    // Buffer descriptors for cpus is the cpu number.
    auto status = WriteBufferData(config, ipt, cpu, cpu);
    if (status != ZX_OK) {
      FX_LOGS(ERROR) << fxl::StringPrintf("Dump perf of cpu %u: ", cpu)
                     << debugger_utils::ZxErrorString(status);
      // Keep trying to dump other cpu's data.
    }
  }
}

void DumpSidebandData(const IptConfig& config) {
  FX_LOGS(INFO) << "DumpSidebandData called";

  DumpKtraceBuffer(config.output_path_prefix.c_str(), ktrace_output_path_suffix);

  // TODO(dje): UniqueFILE?
  {
    std::string cpuid_output_path =
        fxl::StringPrintf("%s.%s", config.output_path_prefix.c_str(), cpuid_output_path_suffix);
    const char* cpuid_c_path = cpuid_output_path.c_str();

    FILE* f = fopen(cpuid_c_path, "w");
    if (f != nullptr) {
      debugger_utils::x86_feature_debug(f);
      // Also put the mtc_freq value in the cpuid file, it's as good a place
      // for it as any. See intel-pt.h:pt_config.
      // Alternatively this could be added to the ktrace record.
      // TODO(dje): Put constants in zircon/device/intel-pt.h.
      unsigned mtc_freq = config.mtc_freq;
      fprintf(f, "mtc_freq: %u\n", mtc_freq);
      // TODO(dje): verify writes succeed
      fclose(f);
    } else {
      FX_LOGS(ERROR) << "unable to write PT config to " << cpuid_c_path;
    }
  }

  // TODO(dje): UniqueFILE?
  // TODO(dje): Handle Mode::THREAD
  if (config.mode == Mode::CPU) {
    std::string pt_list_output_path =
        fxl::StringPrintf("%s.%s", config.output_path_prefix.c_str(), pt_list_output_path_suffix);
    const char* pt_list_c_path = pt_list_output_path.c_str();

    FILE* f = fopen(pt_list_c_path, "w");
    if (f != nullptr) {
      for (uint32_t cpu = 0; cpu < config.num_cpus; ++cpu) {
        std::string pt_file = GetCpuPtFileName(config.output_path_prefix, cpu);
        fprintf(f, "%u %s\n", cpu, pt_file.c_str());
      }
      // TODO(dje): verify writes succeed
      fclose(f);
    } else {
      FX_LOGS(ERROR) << "unable to write PT list to " << pt_list_c_path;
    }
  }
}

void ResetTrace(const IptConfig& config) {
  FX_LOGS(INFO) << "ResetTrace called";
  FX_DCHECK(config.mode == Mode::CPU);

  // TODO(dje): Nothing to do currently. There use to be. So keep this
  // function around for a bit.
}

// Free all resources associated with the true.
// This means restoring ktrace to its original state.
// This assumes tracing has already been stopped.

void FreeTrace(const IptConfig& config) {
  FX_LOGS(INFO) << "FreeTrace called";

  ControllerSyncPtr ipt{OpenDevice()};
  if (!ipt) {
    return;
  }

  ::fuchsia::hardware::cpu::insntrace::Controller_Terminate_Result result;
  zx_status_t status = ipt->Terminate(&result);
  if (status != ZX_OK || result.is_err()) {
    LogFidlFailure("Terminate", status, result.err());
  }

  // TODO(dje): Resume original ktracing? Need ability to get old value.
  // For now set the values to what we need: A later run might still need
  // the boot time records.

  fuchsia::tracing::kernel::ControllerSyncPtr ktrace;
  if (OpenKtraceControllerChannel(&ktrace) != ZX_OK) {
    return;
  }

  RequestKtraceStop(ktrace);
#if 0  // TODO(dje): See rewind comments in InitProcessTrace.
  RequestKtraceRewind(ktrace);
#endif
  RequestKtraceStart(ktrace, kKtraceGroupMask);
}

}  // namespace insntrace