osquery-1/osquery/profiler/posix/profiler.cpp

/**
 *  Copyright (c) 2014-present, Facebook, Inc.
 *  All rights reserved.
 *
 *  This source code is licensed as defined on the LICENSE file found in the
 *  root directory of this source tree.
 */

#ifdef __linux__
// Needed for linux specific RUSAGE_THREAD, before including anything else
#ifndef _GNU_SOURCE
#define _GNU_SOURCE
#endif
#endif

#include <cerrno>
#include <cstdint>
#include <cstring>

#include <sys/resource.h>
#include <sys/time.h>

#include <boost/format.hpp>
#include <boost/io/detail/quoted_manip.hpp>

#include <osquery/killswitch.h>
#include <osquery/logger.h>
#include <osquery/numeric_monitoring.h>
#include <osquery/profiler/profiler.h>

namespace osquery {
namespace {

void record(const std::vector<std::string>& names,
            const std::string& metricName,
            monitoring::ValueType measurement) {
  for (const std::string& name : names) {
    monitoring::record(name + "." + metricName,
                       measurement,
                       monitoring::PreAggregationType::None);
  }
}

int getRusageWho() {
  return
#ifdef __linux__
      RUSAGE_THREAD; // Linux supports more granular profiling
#else
      RUSAGE_SELF;
#endif
}

enum class RusageError { FatalError = 1 };

static Expected<struct rusage, RusageError> callRusage() {
  struct rusage stats;
  const int who = getRusageWho();
  auto rusage_status = getrusage(who, &stats);
  if (rusage_status != -1) {
    return stats;
  } else {
    return createError(RusageError::FatalError, "")
           << "Linux query profiling failed. error code: " << rusage_status
           << " message: " << boost::io::quoted(strerror(errno));
  }
}

void recordRusageStatDifference(const std::vector<std::string>& names,
                                const std::string& stat_name,
                                int64_t start_stat,
                                int64_t end_stat) {
  if (end_stat == 0) {
    TLOG << "rusage field " << boost::io::quoted(stat_name)
         << " is not supported";
  } else if (start_stat <= end_stat) {
    record(names, stat_name, end_stat - start_stat);
  } else {
    LOG(WARNING) << "Possible overflow detected in rusage field: "
                 << boost::io::quoted(stat_name);
  }
}

void recordRusageStatDifference(const std::vector<std::string>& names,
                                const std::string& stat_name,
                                const struct timeval& start_stat,
                                const struct timeval& end_stat) {
  recordRusageStatDifference(
      names,
      stat_name + ".millis",
      std::chrono::duration_cast<std::chrono::milliseconds>(
          std::chrono::seconds(start_stat.tv_sec) +
          std::chrono::microseconds(start_stat.tv_usec))
          .count(),
      std::chrono::duration_cast<std::chrono::milliseconds>(
          std::chrono::seconds(end_stat.tv_sec) +
          std::chrono::microseconds(end_stat.tv_usec))
          .count());
}

void recordRusageStatDifference(const std::vector<std::string>& names,
                                const struct rusage& start_stats,
                                const struct rusage& end_stats) {
  recordRusageStatDifference(names, "rss.max.kb", 0, end_stats.ru_maxrss);

  recordRusageStatDifference(
      names, "rss.increase.kb", start_stats.ru_maxrss, end_stats.ru_maxrss);

  recordRusageStatDifference(
      names, "input.load", start_stats.ru_inblock, end_stats.ru_inblock);

  recordRusageStatDifference(
      names, "output.load", start_stats.ru_oublock, end_stats.ru_oublock);

  recordRusageStatDifference(
      names, "time.user", start_stats.ru_utime, end_stats.ru_utime);

  recordRusageStatDifference(
      names, "time.system", start_stats.ru_stime, end_stats.ru_stime);
}

} // namespace

class CodeProfiler::CodeProfilerData {
 public:
  CodeProfilerData()
      : rusage_data_(callRusage()),
        wall_time_(std::chrono::steady_clock::now()) {}

  const std::chrono::time_point<std::chrono::steady_clock>& getWallTime() {
    return wall_time_;
  }
  Expected<struct rusage, RusageError> takeRusageData() {
    return std::move(rusage_data_);
  }

 private:
  Expected<struct rusage, RusageError> rusage_data_;
  std::chrono::time_point<std::chrono::steady_clock> wall_time_;
};

CodeProfiler::CodeProfiler(const std::initializer_list<std::string>& names)
    : names_(names), code_profiler_data_(new CodeProfilerData()) {}

CodeProfiler::~CodeProfiler() {
  if (Killswitch::get().isPosixProfilingEnabled()) {
    CodeProfilerData code_profiler_data_end;

    auto rusage_start = code_profiler_data_->takeRusageData();
    if (!rusage_start) {
      LOG(ERROR) << "rusage_start error: "
                 << rusage_start.getError().getFullMessageRecursive();
    } else {
      auto rusage_end = code_profiler_data_end.takeRusageData();
      if (!rusage_end) {
        LOG(ERROR) << "rusage_end error: "
                   << rusage_end.getError().getFullMessageRecursive();
      } else {
        recordRusageStatDifference(names_, *rusage_start, *rusage_end);
      }
    }

    const auto query_duration =
        std::chrono::duration_cast<std::chrono::milliseconds>(
            code_profiler_data_end.getWallTime() -
            code_profiler_data_->getWallTime());
    record(names_, "time.wall.millis", query_duration.count());
  }
}

} // namespace osquery