metrics/vmlog_writer.cc

// Copyright 2017 The Chromium OS 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 "metrics/vmlog_writer.h"

#include <fcntl.h>
#include <inttypes.h>
#include <sys/stat.h>
#include <sys/types.h>
#include <unistd.h>

#include <string>
#include <vector>

#include <base/bind.h>
#include <base/bind_helpers.h>
#include <base/files/file_util.h>
#include <base/logging.h>
#include <base/strings/string_number_conversions.h>
#include <base/strings/string_split.h>
#include <base/strings/stringprintf.h>
#include <base/sys_info.h>
#include <brillo/daemons/daemon.h>

namespace chromeos_metrics {
namespace {

constexpr char kVmlogHeader[] = "time pgmajfault pswpin pswpout\n";

// We limit the size of vmlog log files to keep frequent logging from wasting
// disk space.
constexpr int kMaxVmlogFileSize = 1024 * 1024;
// constexpr base::TimeDelta kVmlogInterval = base::TimeDelta::FromSeconds(2);

}  // namespace

bool VmStatsParseStats(const std::string& stats, struct VmstatRecord* record) {
  // a mapping of string name to field in VmstatRecord and whether we found it
  struct Mapping {
    const std::string name;
    uint64_t* value_p;
    bool found;
  } map[] = {
      {.name = "pgmajfault", .value_p = &record->page_faults_, .found = false},
      {.name = "pswpin", .value_p = &record->swap_in_, .found = false},
      {.name = "pswpout", .value_p = &record->swap_out_, .found = false},
  };

  // Each line in the file has the form
  // <ID> <VALUE>
  // for instance:
  // nr_free_pages 213427
  std::vector<std::string> lines = base::SplitString(stats,
                                                     "\n",
                                                     base::KEEP_WHITESPACE,
                                                     base::SPLIT_WANT_NONEMPTY);
  for (const auto& line : lines) {
    std::vector<std::string> tokens = base::SplitString(line,
                                                        " ",
                                                        base::KEEP_WHITESPACE,
                                                        base::SPLIT_WANT_ALL);
    if (tokens.size() != 2u) {
      LOG(WARNING) << "Unexpected vmstat format in line: " << line;
      continue;
    }
    for (auto& mapping : map) {
      if (!tokens[0].compare(mapping.name)) {
        if (!base::StringToUint64(tokens[1], mapping.value_p))
          return false;
        mapping.found = true;
      }
    }
  }
  // Make sure we got all the stats
  for (const auto& mapping : map) {
    if (mapping.found == false) {
      LOG(WARNING) << "vmstat missing " << mapping.name;
      return false;
    }
  }
  return true;
}

VmlogFile::VmlogFile(const base::FilePath& live_path,
                     const base::FilePath& rotated_path,
                     const uint64_t max_size,
                     const std::string& header) :
      live_path_(live_path),
      rotated_path_(rotated_path),
      max_size_(max_size),
      header_(header) {
  fd_ = open(live_path_.value().c_str(), O_CREAT | O_RDWR | O_EXCL, 0644);
  if (fd_ != -1) {
    Write(header_);
  } else {
    PLOG(ERROR) << "Failed to open file: " << live_path_.value();
  }
}

VmlogFile::~VmlogFile() = default;

bool VmlogFile::Write(const std::string& data) {
  if (fd_ == -1)
    return false;

  if (cur_size_ + data.size() > max_size_) {
    if (!base::CopyFile(live_path_, rotated_path_)) {
      PLOG(ERROR) << "Could not copy vmlog to: " << rotated_path_.value();
    }

    if (HANDLE_EINTR(ftruncate(fd_, 0)) != 0) {
      PLOG(ERROR) << "Could not ftruncate() file";
      return false;
    }
    if (HANDLE_EINTR(lseek(fd_, 0, SEEK_SET)) != 0) {
      PLOG(ERROR) << "Could not lseek() file";
      return false;
    }
    cur_size_ = 0;
    if (!Write(header_)) {
      return false;
    }
  }

  if (!base::WriteFileDescriptor(fd_, data.c_str(), data.size())) {
    return false;
  }
  cur_size_ += data.size();
  return true;
}

VmlogWriter::VmlogWriter(const base::FilePath& vmlog_dir,
                         const base::TimeDelta& log_interval) {
  if (!base::DirectoryExists(vmlog_dir)) {
    if (!base::CreateDirectory(vmlog_dir)) {
      PLOG(ERROR) << "Couldn't create " << vmlog_dir.value();
      return;
    }
  }

  base::Time now = base::Time::Now();
  base::FilePath vmlog_current_path = vmlog_dir.Append(
      "vmlog." + brillo::GetTimeAsLogString(now));
  base::FilePath vmlog_rotated_path = vmlog_dir.Append(
      "vmlog.1." + brillo::GetTimeAsLogString(now));

  brillo::UpdateLogSymlinks(vmlog_dir.Append("vmlog.LATEST"),
                            vmlog_dir.Append("vmlog.PREVIOUS"),
                            vmlog_current_path);

  // This will create a vmlog.1.LATEST symlink that doesn't point at a file
  // until the log is rotated, but it seems more important to keep vmlog and
  // vmlog.1 symlinks synchronized.
  brillo::UpdateLogSymlinks(vmlog_dir.Append("vmlog.1.LATEST"),
                            vmlog_dir.Append("vmlog.1.PREVIOUS"),
                            vmlog_rotated_path);

  vmlog_.reset(new VmlogFile(
      vmlog_current_path, vmlog_rotated_path, kMaxVmlogFileSize, kVmlogHeader));

  vmstat_fd_ = open("/proc/vmstat", O_RDONLY);
  if (vmstat_fd_ < 0) {
    PLOG(ERROR) << "Couldn't open /proc/vmstat";
    return;
  }

  if (!log_interval.is_zero()) {
    timer_.Start(FROM_HERE, log_interval, this, &VmlogWriter::WriteCallback);
  }
}

VmlogWriter::~VmlogWriter() = default;

void VmlogWriter::WriteCallback() {
  if (lseek(vmstat_fd_, 0, SEEK_SET) < 0) {
    PLOG(ERROR) << "Unable to lseek() /proc/vmstat";
    timer_.Stop();
    return;
  }

  // Assume that vmstat output will be no larger than 8K-1. Poking around some
  // chromebooks, the size seems to generally be around 2K.
  char buf[8192];
  int len = HANDLE_EINTR(read(vmstat_fd_, buf, arraysize(buf)-1));
  if (len < 0) {
    PLOG(ERROR) << "Unable to read() /proc/vmstat";
    timer_.Stop();
    return;
  }

  // Null terminate the data we've read
  buf[len] = 0;

  VmstatRecord r;
  if (!VmStatsParseStats(buf, &r)) {
    LOG(ERROR) << "Unable to parse vmstat data";
    timer_.Stop();
    return;
  }

  int64_t uptime_micros = base::SysInfo::Uptime().InMicroseconds();
  std::string out_line = base::StringPrintf(
      "[%5" PRIu64 ".%" PRIu64  "] %" PRIu64 " %" PRIu64 " %" PRIu64 "\n",
      uptime_micros / 1000000,
      uptime_micros % 1000000,
      r.page_faults_,
      r.swap_in_,
      r.swap_out_);

  if (!vmlog_->Write(out_line)) {
    LOG(ERROR) << "Writing to vmlog failed.";
    timer_.Stop();
    return;
  }
}

}  // namespace chromeos_metrics