hphp/util/boot-stats.cpp

   1 /*
   2    +----------------------------------------------------------------------+
   3    | HipHop for PHP                                                       |
   4    +----------------------------------------------------------------------+
   5    | Copyright (c) 2010-present 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 "hphp/util/logger.h"
  19 #include "hphp/util/process.h"
  20 #include "hphp/util/struct-log.h"
  21 #include "hphp/util/timer.h"
  22 #include "hphp/util/trace.h"
  23
  24 namespace HPHP {
  25
  26 ///////////////////////////////////////////////////////////////////////////////
  27
  28 ResourceUsage ResourceUsage::sinceEpoch() {
  29   return ResourceUsage(
  30     std::chrono::duration_cast<TimeUnit>(
  31       std::chrono::steady_clock::now().time_since_epoch()),
  32     std::chrono::duration_cast<TimeUnit>(
  33       std::chrono::microseconds(
  34         HPHP::Timer::GetRusageMicros(Timer::TotalCPU, Timer::Self))),
  35     Process::GetMemUsageMb());
  36 }
  37
  38 std::string ResourceUsage::toString() const {
  39   return folly::sformat(
  40     "{}ms wall, {}ms cpu, {} MB RSS",
  41     std::chrono::duration_cast<std::chrono::milliseconds>(wall()).count(),
  42     std::chrono::duration_cast<std::chrono::milliseconds>(cpu()).count(),
  43     rssMb());
  44 }
  45
  46 void ResourceUsage::operator=(const ResourceUsage& rhs) {
  47   m_wall = rhs.m_wall;
  48   m_cpu = rhs.m_cpu;
  49   m_rssMb = rhs.m_rssMb;
  50 }
  51
  52 ResourceUsage ResourceUsage::operator-(const ResourceUsage& rhs) const {
  53   return ResourceUsage(m_wall - rhs.m_wall,
  54                        m_cpu - rhs.m_cpu,
  55                        m_rssMb - rhs.m_rssMb);
  56 }
  57
  58 ResourceUsage ResourceUsage::operator+(const ResourceUsage& rhs) const {
  59   return ResourceUsage(m_wall + rhs.m_wall,
  60                        m_cpu + rhs.m_cpu,
  61                        m_rssMb + rhs.m_rssMb);
  62 }
  63
  64 ///////////////////////////////////////////////////////////////////////////////
  65
  66 struct BootStats::Impl {
  67   Impl() : m_last(ResourceUsage::sinceEpoch()) {}
  68
  69   void add(const std::string& info, ResourceUsage value);
  70   void dumpMarks();
  71   ResourceUsage computeDeltaFromLast();
  72
  73   friend struct BootStats;
  74
  75 private:
  76   // Must hold when updating m_last
  77   std::mutex m_last_guard_;
  78   ResourceUsage m_last;
  79   std::mutex m_marks_guard_;
  80   std::map<std::string, ResourceUsage> m_marks;
  81   std::map<std::string, std::string> m_strs;
  82   std::map<std::string, int64_t> m_ints;
  83 };
  84
  85 void BootStats::Impl::add(const std::string& info, ResourceUsage value) {
  86   std::lock_guard<std::mutex> lock(m_marks_guard_);
  87   m_marks[info] = m_marks[info] + value;
  88 }
  89
  90 void BootStats::Impl::dumpMarks() {
  91   for (const auto& it : m_marks) {
  92     Logger::FInfo("BootStats: {} = {}", it.first, it.second.toString());
  93   }
  94 }
  95
  96 ResourceUsage BootStats::Impl::computeDeltaFromLast() {
  97   std::lock_guard<std::mutex> lock(m_last_guard_);
  98   auto now = ResourceUsage::sinceEpoch();
  99   auto ret = now - m_last;
 100   m_last = now;
 101   return ret;
 102 }
 103
 104 ///////////////////////////////////////////////////////////////////////////////
 105
 106 BootStats::Block::Block(const std::string& name, bool enabled) {
 107   if (!enabled) return;
 108   m_name = name;
 109   m_enabled = true;
 110   m_start = ResourceUsage::sinceEpoch();
 111   Logger::FInfo("BootStats: {}...", name);
 112 }
 113
 114 BootStats::Block::~Block() {
 115   if (!m_enabled) return;
 116   auto total = ResourceUsage::sinceEpoch() - m_start;
 117   Logger::FInfo("BootStats: {} block done, took {}", m_name, total.toString());
 118   BootStats::add(m_name, total);
 119 }
 120
 121 ///////////////////////////////////////////////////////////////////////////////
 122
 123 bool BootStats::s_started;
 124 ResourceUsage BootStats::s_start;
 125 std::unique_ptr<BootStats::Impl> BootStats::s_instance;
 126
 127 void BootStats::start() {
 128   BootStats::s_started = true;
 129   BootStats::s_start = ResourceUsage::sinceEpoch();
 130   BootStats::s_instance = std::make_unique<BootStats::Impl>();
 131 }
 132
 133 void BootStats::done() {
 134   if (!s_started) return;
 135   s_started = false;
 136
 137   auto total = ResourceUsage::sinceEpoch() - s_start;
 138   Logger::FInfo("BootStats: all done, took {} total", total.toString());
 139
 140   BootStats::s_instance->add("TOTAL", total);
 141   BootStats::s_instance->dumpMarks();
 142
 143   if (StructuredLog::enabled()) {
 144     std::lock_guard<std::mutex> lock(s_instance->m_marks_guard_);
 145     StructuredLogEntry cols;
 146     for (auto const& sample : s_instance->m_marks) {
 147       cols.setInt(sample.first, sample.second.wall().count());
 148       cols.setInt(sample.first + " CPU", sample.second.cpu().count());
 149     }
 150     for (auto const& strCol : s_instance->m_strs) {
 151       cols.setStr(strCol.first, strCol.second);
 152     }
 153     for (auto const intCol : s_instance->m_strs) {
 154       cols.setStr(intCol.first, intCol.second);
 155     }
 156     StructuredLog::log("hhvm_boot_timer", cols);
 157     cols.clear();
 158     for (auto sample : s_instance->m_marks) {
 159       cols.setInt(sample.first, sample.second.rssMb() * (1 << 20)); // To bytes.
 160     }
 161     StructuredLog::log("hhvm_boot_memory", cols);
 162   }
 163 }
 164
 165 void BootStats::mark(const std::string& info) {
 166   if (!s_started) return;
 167   auto elapsed = BootStats::s_instance->computeDeltaFromLast();
 168   Logger::FInfo("BootStats: {} done, took {}", info, elapsed.toString());
 169   BootStats::s_instance->add(info, elapsed);
 170 }
 171
 172 void BootStats::add(const std::string& info, const ResourceUsage value) {
 173   if (!s_started) return;
 174   BootStats::s_instance->add(info, value);
 175 }
 176
 177 void BootStats::set(const std::string& name, const std::string& value) {
 178   if (!s_started) return;
 179   BootStats::s_instance->m_strs[name] = value;
 180 }
 181
 182 void BootStats::set(const std::string& name, int64_t value) {
 183   if (!s_started) return;
 184   BootStats::s_instance->m_ints[name] = value;
 185 }
 186
 187 ///////////////////////////////////////////////////////////////////////////////
 188 }