hphp/util/boot-stats.cpp

   1 /*
   2    +----------------------------------------------------------------------+
   3    | HipHop for PHP                                                       |
   4    +----------------------------------------------------------------------+
   5    | Copyright (c) 2010-2014 Facebook, Inc. (http://www.facebook.com)     |
   6    +----------------------------------------------------------------------+
   7    | This source file is subject to version 3.01 of the PHP license,      |
   8    | that is bundled with this package in the file LICENSE, and is        |
   9    | available through the world-wide-web at the following url:           |
  10    | http://www.php.net/license/3_01.txt                                  |
  11    | If you did not receive a copy of the PHP license and are unable to   |
  12    | obtain it through the world-wide-web, please send a note to          |
  13    | license@php.net so we can mail you a copy immediately.               |
  14    +----------------------------------------------------------------------+
  15 */
  16 #include "hphp/util/boot-stats.h"
  17
  18 #include <cassert>
  19
  20 #include <folly/portability/Unistd.h>
  21
  22 #include "hphp/util/logger.h"
  23 #include "hphp/util/process.h"
  24 #include "hphp/util/struct-log.h"
  25 #include "hphp/util/timer.h"
  26 #include "hphp/util/trace.h"
  27
  28 namespace HPHP {
  29
  30 ///////////////////////////////////////////////////////////////////////////////
  31
  32 ResourceUsage ResourceUsage::sinceEpoch() {
  33   return ResourceUsage(
  34     std::chrono::duration_cast<TimeUnit>(
  35       std::chrono::steady_clock::now().time_since_epoch()),
  36     std::chrono::duration_cast<TimeUnit>(
  37       std::chrono::microseconds(
  38         HPHP::Timer::GetRusageMicros(Timer::TotalCPU, Timer::Self))),
  39     Process::GetProcessRSS());
  40 }
  41
  42 std::string ResourceUsage::toString() const {
  43   return folly::sformat(
  44     "{}ms wall, {}ms cpu, {} MB RSS",
  45     std::chrono::duration_cast<std::chrono::milliseconds>(wall()).count(),
  46     std::chrono::duration_cast<std::chrono::milliseconds>(cpu()).count(),
  47     rssMb());
  48 }
  49
  50 void ResourceUsage::operator=(const ResourceUsage& rhs) {
  51   m_wall = rhs.m_wall;
  52   m_cpu = rhs.m_cpu;
  53   m_rssMb = rhs.m_rssMb;
  54 }
  55
  56 ResourceUsage ResourceUsage::operator-(const ResourceUsage& rhs) const {
  57   return ResourceUsage(m_wall - rhs.m_wall,
  58                        m_cpu - rhs.m_cpu,
  59                        m_rssMb - rhs.m_rssMb);
  60 }
  61
  62 ResourceUsage ResourceUsage::operator+(const ResourceUsage& rhs) const {
  63   return ResourceUsage(m_wall + rhs.m_wall,
  64                        m_cpu + rhs.m_cpu,
  65                        m_rssMb + rhs.m_rssMb);
  66 }
  67
  68 ///////////////////////////////////////////////////////////////////////////////
  69
  70 struct BootStats::Impl {
  71   Impl() : m_last(ResourceUsage::sinceEpoch()) {
  72   }
  73
  74   void add(const std::string& info, ResourceUsage value);
  75   void dumpMarks();
  76   ResourceUsage computeDeltaFromLast();
  77
  78   friend struct BootStats;
  79
  80 private:
  81   // Must hold when updating m_last
  82   std::mutex m_last_guard_;
  83   ResourceUsage m_last;
  84   std::mutex m_marks_guard_;
  85   std::map<std::string, ResourceUsage> m_marks;
  86 };
  87
  88 void BootStats::Impl::add(const std::string& info, ResourceUsage value) {
  89   std::lock_guard<std::mutex> lock(m_marks_guard_);
  90   m_marks[info] = m_marks[info] + value;
  91 }
  92
  93 void BootStats::Impl::dumpMarks() {
  94   for (const auto& it : m_marks) {
  95     Logger::Info(
  96       folly::sformat("BootStats: {} = {}", it.first, it.second.toString()));
  97   }
  98 }
  99
 100 ResourceUsage BootStats::Impl::computeDeltaFromLast() {
 101   std::lock_guard<std::mutex> lock(m_last_guard_);
 102   auto now = ResourceUsage::sinceEpoch();
 103   auto ret = now - m_last;
 104   m_last = now;
 105   return ret;
 106 }
 107
 108 ///////////////////////////////////////////////////////////////////////////////
 109
 110 BootStats::Block::Block(const std::string& name)
 111     : m_name(name), m_start(ResourceUsage::sinceEpoch()) {
 112   Logger::Info(folly::sformat("BootStats: {}...", name));
 113 }
 114
 115 BootStats::Block::~Block() {
 116   auto total = ResourceUsage::sinceEpoch() - m_start;
 117   Logger::Info(
 118     folly::sformat(
 119       "BootStats: {} block done, took {}", m_name, total.toString()));
 120   BootStats::add(m_name, total);
 121 }
 122
 123 ///////////////////////////////////////////////////////////////////////////////
 124
 125 bool BootStats::s_started;
 126 ResourceUsage BootStats::s_start;
 127 std::unique_ptr<BootStats::Impl> BootStats::s_instance;
 128
 129 void BootStats::start() {
 130   BootStats::s_started = true;
 131   BootStats::s_start = ResourceUsage::sinceEpoch();
 132   BootStats::s_instance = std::make_unique<BootStats::Impl>();
 133 }
 134
 135 void BootStats::done() {
 136   if (!s_started) return;
 137   s_started = false;
 138
 139   auto total = ResourceUsage::sinceEpoch() - s_start;
 140   Logger::Info(
 141     folly::sformat("BootStats: all done, took {} total", total.toString()));
 142
 143   BootStats::s_instance->add("TOTAL", total);
 144   BootStats::s_instance->dumpMarks();
 145
 146   if (StructuredLog::enabled()) {
 147     std::lock_guard<std::mutex> lock(s_instance->m_marks_guard_);
 148     StructuredLogEntry cols;
 149     for (auto sample : s_instance->m_marks) {
 150       cols.setInt(sample.first, sample.second.wall().count());
 151       cols.setInt(sample.first + " CPU", sample.second.cpu().count());
 152     }
 153     StructuredLog::log("hhvm_boot_timer", cols);
 154     cols.clear();
 155     for (auto sample : s_instance->m_marks) {
 156       cols.setInt(sample.first, sample.second.rssMb() << 20); // To bytes.
 157     }
 158     StructuredLog::log("hhvm_boot_memory", cols);
 159   }
 160 }
 161
 162 void BootStats::mark(const std::string& info) {
 163   if (!s_started) return;
 164   auto elapsed = BootStats::s_instance->computeDeltaFromLast();
 165   Logger::Info(
 166     folly::sformat("BootStats: {} done, took {}", info, elapsed.toString()));
 167   BootStats::s_instance->add(info, elapsed);
 168 }
 169
 170 void BootStats::add(const std::string& info, const ResourceUsage value) {
 171   if (!s_started) return;
 172   BootStats::s_instance->add(info, value);
 173 }
 174
 175 ///////////////////////////////////////////////////////////////////////////////
 176 }