src/testing/loadbench/loadbench.cc

// Copyright 2019 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 <getopt.h>
#include <lib/syslog/cpp/macros.h>
#include <zircon/errors.h>
#include <zircon/syscalls.h>
#include <zircon/syscalls/object.h>
#include <zircon/time.h>
#include <zircon/types.h>

#include <algorithm>
#include <chrono>
#include <cstdint>
#include <cstdio>
#include <fstream>
#include <iostream>
#include <map>
#include <optional>
#include <ratio>
#include <string>
#include <thread>
#include <unordered_map>
#include <vector>

#include "action.h"
#include "object.h"
#include "tracing.h"
#include "utility.h"
#include "worker.h"
#include "workload.h"

using std::chrono_literals::operator""ms;
using std::chrono_literals::operator""s;

constexpr char kShortOptions[] = "hitv::";

// clang-format off
constexpr struct option kLongOptions[] = {
    { "help",       no_argument,        nullptr, 'h' },
    { "interval",   required_argument,  nullptr, 'i' },
    { "terse",      no_argument,        nullptr, 't' },
    { "verbose",    no_argument,        nullptr, 'v' },
    { nullptr, 0, nullptr, 0 }
};
// clang-format on
constexpr auto kDefaultWorkloadInterval = 10s;

void PrintUsage(const char* program_name) {
  printf(
      "Usage: %s [-hitv] [--help] [--interval <INTERVAL>] [--terse] [--verbose]\n"
      "Executes a synthetic workload and reports benchmarks.\n"
      "With --help or -h, display this help and exit.\n"
      "With --interval <INTERVAL> or -i <INTERVAL>, run workload for <INTERVAL> time.\n"
      "With --terse or -t, show simplified output.\n"
      "With --verbose or -v, show verbose output.\n"
      "\n"
      "The default workload interval is %llu seconds, unless specified in the\n"
      "workload config or using --interval.\n",
      program_name, kDefaultWorkloadInterval.count());
}

int main(int argc, char** argv) {
  std::optional<std::chrono::nanoseconds> default_interval;
  std::string workload_path;
  bool help_flag = false;
  bool verbose_flag = false;

  int opt;
  while ((opt = getopt_long(argc, argv, kShortOptions, kLongOptions, nullptr)) != -1) {
    switch (opt) {
      case 'h':
        help_flag = true;
        break;
      case 'v':
        verbose_flag = true;
        break;
      case 'i':
        default_interval = ParseDurationString(optarg);
        break;
      default:
        PrintUsage(argv[0]);
        return 1;
    }
  }

  if (help_flag) {
    PrintUsage(argv[0]);
    return 0;
  }

  // If there is exactly one non-optional argument, that must be the path to the
  // workload config
  if (optind == argc - 1) {
    workload_path = argv[optind];
  } else {
    PrintUsage(argv[0]);
    return 0;
  }

  std::cout << "Loading workload config from: " << workload_path << std::endl;
  Workload workload = Workload::Load(workload_path);

  if (workload.priority().has_value()) {
    auto profile = GetProfile(workload.priority().value());
    const auto status = zx::thread::self()->set_profile(*profile, 0);
    FX_CHECK(status == ZX_OK) << "Failed to set the priority of the main thread!";
  }

  std::vector<std::thread> threads;
  std::vector<std::unique_ptr<Worker>> workers;
  for (auto& worker_config : workload.workers()) {
    auto [thread, worker] = Worker::Create(std::move(worker_config));
    threads.emplace_back(std::move(thread));
    workers.emplace_back(std::move(worker));
  }

  // Setup to sample CPU stats.
  const size_t cpu_count = ReadCpuCount();
  std::vector<zx_info_cpu_stats_t> cpu_stats_start(cpu_count);
  std::vector<zx_info_cpu_stats_t> cpu_stats_end(cpu_count);

  std::cout << "Waiting for workers to start up..." << std::endl;
  Worker::WaitForAllReady(threads.size());

  Tracing tracing;
  if (workload.tracing().has_value()) {
    tracing.Rewind();
    tracing.Start(workload.tracing().value().group_mask);
    std::cout << "Tracing started." << std::endl;
  }

  std::cout << "Kicking off workload..." << std::endl;
  Worker::StartAll();

  ReadCpuStats(cpu_stats_start.data(), cpu_stats_start.size());

  const std::chrono::nanoseconds interval_ns =
      default_interval.has_value()      ? default_interval.value()
      : workload.interval().has_value() ? workload.interval().value()
                                        : kDefaultWorkloadInterval;
  const auto interval_s = double_seconds{interval_ns}.count();
  std::cout << "Waiting for " << interval_s << " s..." << std::endl;
  std::this_thread::sleep_for(interval_ns);

  ReadCpuStats(cpu_stats_end.data(), cpu_stats_end.size());

  std::cout << "Terminating workload..." << std::endl;
  Worker::TerminateAll();

  if (workload.tracing().has_value()) {
    tracing.Stop();
    std::cout << "Tracing stopped." << std::endl;
  }

  for (auto& thread : threads) {
    thread.join();
  }
  threads.clear();

  std::cout << "CPU Stats:" << std::endl;
  for (size_t i = 0; i < cpu_stats_start.size(); i++) {
    const std::chrono::nanoseconds idle_time_ns{cpu_stats_end[i].idle_time -
                                                cpu_stats_start[i].idle_time};

    const auto idle_time_s = double_seconds{idle_time_ns}.count();
    const auto active_time_s = interval_s - idle_time_s;

    std::cout << "  CPU " << i << ":" << std::endl;
    std::cout << "    Average Utilization: " << active_time_s << " s ("
              << (active_time_s * 100.0 / interval_s) << "%)" << std::endl;
  }

  struct GroupStats {
    size_t count{0};
    uint64_t iterations{0};
    std::chrono::nanoseconds runtime{0};

    uint64_t AverageIterations() const { return iterations / count; }
    double_seconds AverageRuntime() const { return double_seconds{runtime / count}; }
  };

  std::map<std::string, GroupStats> group_stats;

  for (auto& worker : workers) {
    if (verbose_flag) {
      worker->Dump();
    }

    // Add an entry for each unique group.
    auto [iter, okay] = group_stats.emplace(worker->group(), GroupStats{});

    // Accumulate group stats.
    iter->second.count++;
    iter->second.iterations += worker->spin_iterations();
    iter->second.runtime += worker->total_runtime();
  }
  workers.clear();

  std::cout << "Group stats:" << std::endl;
  for (auto& group : group_stats) {
    const auto& group_name = group.first;
    const auto thread_count = group.second.count;
    const auto average_iterations = group.second.AverageIterations();
    const auto average_runtime = group.second.AverageRuntime().count();

    std::cout << "Group: " << group_name << std::endl;
    std::cout << "  Threads: " << thread_count << std::endl;
    std::cout << "  Average Iterations: " << average_iterations << " per thread ("
              << (average_iterations * thread_count / cpu_count) << " per cpu)" << std::endl;
    std::cout << "  Average Runtime: " << average_runtime << " s/thread ("
              << (average_runtime * static_cast<double>(thread_count) /
                  static_cast<double>(cpu_count))
              << " s/cpu)" << std::endl;
  }

  using MapItem = decltype(group_stats)::value_type;
  std::vector<std::reference_wrapper<MapItem>> group_list{group_stats.begin(), group_stats.end()};
  std::sort(group_list.begin(), group_list.end(),
            [](const MapItem& a, const MapItem& b) { return a.second.runtime > b.second.runtime; });

  std::cout << "Relative stats:" << std::endl;
  for (auto i = group_list.cbegin(); i != group_list.cend(); ++i) {
    for (auto j = i + 1; j != group_list.cend(); ++j) {
      const MapItem& group_a = *i;
      const MapItem& group_b = *j;

      std::cout << "Group " << group_a.first << " vs " << group_b.first << std::endl;

      const auto runtime_a = group_a.second.AverageRuntime();
      const auto runtime_b = group_b.second.AverageRuntime();
      std::cout << "  Relative Runtime: "
                << 100.0 * (runtime_a - runtime_b) / (runtime_a + runtime_b) << " %" << std::endl;
    }
  }

  if (workload.tracing().has_value()) {
    TracingConfig config = workload.tracing().value();

    if (config.filepath.has_value()) {
      std::string tracing_filepath = config.filepath.value();

      std::ofstream human_readable_file;
      human_readable_file.open(tracing_filepath);

      if (human_readable_file) {
        std::cout << "Traces being saved in " << tracing_filepath << "..." << std::endl;

        if (!tracing.WriteHumanReadable(human_readable_file))
          FX_LOGS(ERROR) << "Writing human readable file failed.";
      } else {
        FX_LOGS(ERROR) << "Failed to open " << tracing_filepath << ".";
      }
    }

    if (config.trace_string_ref.has_value()) {
      std::vector<Tracing::DurationStats> duration_stats;
      std::map<uint64_t, Tracing::QueuingStats> queuing_stats;

      if (!tracing.PopulateDurationStats(config.trace_string_ref.value(), &duration_stats,
                                         &queuing_stats)) {
        FX_LOGS(ERROR) << "Provided string ref not found.";
      } else if (duration_stats.size() != 0 && queuing_stats.size() != 0) {
        uint64_t total_wall_duration_ns{0};
        uint64_t total_queuing_time_ns{0};

        for (auto& event : duration_stats) {
          total_wall_duration_ns += event.wall_duration_ns;
        }

        for (auto& event : queuing_stats) {
          total_queuing_time_ns += event.second.queuing_time_ns;
        }

        std::cout << "Tracing stats:" << std::endl;
        std::cout << "  Average Wall Duration: "
                  << double_nanoseconds{total_wall_duration_ns}.count() /
                         static_cast<double>(duration_stats.size())
                  << " ns." << std::endl;
        std::cout << "  Average Queuing Time: "
                  << double_nanoseconds{total_queuing_time_ns}.count() /
                         static_cast<double>(queuing_stats.size())
                  << " ns." << std::endl;
      } else {
        FX_LOGS(WARNING) << "No events found that match provided string ref.";
      }
    }
  }

  std::cout << "Done!" << std::endl;
  return 0;
}