hphp/runtime/vm/jit/timer.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
  17 #include "hphp/runtime/vm/jit/timer.h"
  18
  19 #include <map>
  20 #include <algorithm>
  21 #include <array>
  22 #include <iterator>
  23
  24 #include <folly/Format.h>
  25
  26 #include "hphp/runtime/base/execution-context.h"
  27 #include "hphp/util/rds-local.h"
  28 #include "hphp/util/struct-log.h"
  29 #include "hphp/util/timer.h"
  30 #include "hphp/util/trace.h"
  31
  32 TRACE_SET_MOD(jittime);
  33
  34 namespace HPHP { namespace jit {
  35
  36 namespace {
  37
  38 //////////////////////////////////////////////////////////////////////
  39
  40 std::array<Timer::Counter,Timer::kNumTimers> kCountersDefault{};
  41 using TimerType = std::array<Timer::Counter,Timer::kNumTimers>;
  42 RDS_LOCAL_NO_CHECK(TimerType, s_counters)(kCountersDefault);
  43
  44 struct TimerName { const char* str; Timer::Name name; };
  45 const TimerName s_names[] = {
  46 # define TIMER_NAME(name) {#name, Timer::name},
  47   JIT_TIMERS
  48 # undef TIMER_NAME
  49 };
  50
  51 int64_t getCPUTimeNanos() {
  52   return RuntimeOption::EvalJitTimer ? HPHP::Timer::GetThreadCPUTimeNanos() :
  53          -1;
  54 }
  55
  56 int64_t getWallClockMicros() {
  57   return RuntimeOption::EvalJitTimer ? HPHP::Timer::GetCurrentTimeMicros() :
  58          -1;
  59 }
  60
  61 //////////////////////////////////////////////////////////////////////
  62
  63 }
  64
  65 Timer::Timer(Name name, StructuredLogEntry* log_entry)
  66   : m_name(name)
  67   , m_finished(false)
  68   , m_start(getCPUTimeNanos())
  69   , m_start_wall(getWallClockMicros())
  70   , m_log_entry(log_entry)
  71 {
  72 }
  73
  74 Timer::~Timer() {
  75   if (!m_finished) stop();
  76 }
  77
  78 int64_t Timer::stop() {
  79   if (!RuntimeOption::EvalJitTimer) return 0;
  80
  81   assertx(!m_finished);
  82   auto const elapsed = getCPUTimeNanos() - m_start;
  83   auto const elapsed_wall_clock = getWallClockMicros() - m_start_wall;
  84
  85   if (m_log_entry) {
  86     m_log_entry->setInt(std::string(s_names[(size_t)m_name].str) + "_micros",
  87                         elapsed / 1000);
  88   }
  89
  90   auto& counter = s_counters[m_name];
  91   counter.total += elapsed;
  92   ++counter.count;
  93   counter.max = std::max(counter.max, elapsed);
  94   counter.wall_time_elapsed += elapsed_wall_clock;
  95   m_finished = true;
  96   return elapsed;
  97 }
  98
  99 Timer::CounterVec Timer::Counters() {
 100   CounterVec ret;
 101   ret.reserve(std::size(s_names));
 102   for (const auto& pair : s_names) {
 103     ret.emplace_back(pair.str, s_counters[pair.name]);
 104   }
 105   return ret;
 106 }
 107
 108 Timer::Counter Timer::CounterValue(Timer::Name name) {
 109   return s_counters[name];
 110 }
 111
 112 void Timer::RequestInit() {
 113   memset(s_counters.get(), 0, sizeof(Timer::Counter[Timer::kNumTimers]));
 114 }
 115
 116 void Timer::RequestExit() {
 117   Dump();
 118 }
 119
 120 void Timer::Dump() {
 121   if (!Trace::moduleEnabledRelease(Trace::jittime)) return;
 122   Trace::traceRelease("%s", Show().c_str());
 123 }
 124
 125 std::string Timer::Show() {
 126   auto const header = "{:<30} | {:>15} {:>15} {:>15} {:>15}\n";
 127   auto const row    = "{:<30} | {:>15} {:>13,}us {:>13,}ns {:>13,}ns\n";
 128
 129   std::array<TimerName,kNumTimers> names_copy;
 130   std::copy(s_names, s_names + kNumTimers, begin(names_copy));
 131
 132   if (!getenv("HHVM_JIT_TIMER_NO_SORT")) {
 133     auto totalSort = [] (const TimerName& a, const TimerName& b) {
 134       return s_counters[a.name].total > s_counters[b.name].total;
 135     };
 136     std::sort(begin(names_copy), end(names_copy), totalSort);
 137   }
 138
 139   std::string rows;
 140   for (auto const& pair : names_copy) {
 141     auto const& counter = s_counters[pair.name];
 142     if (counter.total == 0 && counter.count == 0) continue;
 143
 144     folly::format(
 145       &rows,
 146       row,
 147       pair.str,
 148       counter.count,
 149       counter.total / 1000,
 150       counter.mean(),
 151       counter.max
 152     );
 153   }
 154
 155   if (rows.empty()) return rows;
 156
 157   std::string ret;
 158   auto const url = g_context->getRequestUrl(75);
 159   folly::format(&ret, "\nJIT timers for {}\n", url);
 160   folly::format(&ret, header, "name", "count", "total", "average", "max");
 161   folly::format(&ret, "{:-^30}-+{:-^64}\n{}\n", "", "", rows);
 162   return ret;
 163 }
 164
 165 } }