hphp/util/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 #include "hphp/util/timer.h"
  17
  18 #include <cassert>
  19
  20 #include <folly/ClockGettimeWrappers.h>
  21 #include <folly/portability/SysResource.h>
  22 #include <folly/portability/SysTime.h>
  23
  24 #include "hphp/util/logger.h"
  25 #include "hphp/util/trace.h"
  26
  27 #ifdef FACEBOOK
  28 #include "common/time/ClockGettimeNS.h" // nolint
  29 #endif
  30
  31 namespace HPHP {
  32 ///////////////////////////////////////////////////////////////////////////////
  33
  34 __thread int64_t s_extra_request_nanoseconds;
  35
  36 namespace {
  37 ///////////////////////////////////////////////////////////////////////////////
  38
  39 #define PRINT_MSG(...)                          \
  40   switch (m_report) {                           \
  41     case Log:                                   \
  42       Logger::Info(__VA_ARGS__);                \
  43       break;                                    \
  44     case Stderr:                                \
  45       fprintf(stderr, __VA_ARGS__);             \
  46       break;                                    \
  47     case Trace:                                 \
  48       Trace::traceRelease(__VA_ARGS__);         \
  49       break;                                    \
  50     default: not_reached();                     \
  51   }
  52
  53 ///////////////////////////////////////////////////////////////////////////////
  54 }
  55
  56 Timer::Timer(Type type, const char *name /* = NULL */, ReportType r)
  57   : m_type(type), m_report(r) {
  58   if (name) {
  59     m_name = name;
  60     PRINT_MSG("%s...", name);
  61   }
  62   m_start = measure();
  63 }
  64
  65 Timer::~Timer() {
  66   if (!m_name.empty()) {
  67     report();
  68   }
  69 }
  70
  71 int64_t Timer::getMicroSeconds() const {
  72   return measure() - m_start;
  73 }
  74
  75 void Timer::report() const {
  76   int64_t ms = getMicroSeconds();
  77   int seconds = ms / 1000000;
  78   PRINT_MSG("%s took %d'%02d\" (%" PRId64 " us) %s", m_name.c_str(),
  79             seconds / 60, seconds % 60, ms, getName());
  80 }
  81
  82 void Timer::GetMonotonicTime(timespec &ts) {
  83   gettime(CLOCK_MONOTONIC, &ts);
  84 }
  85
  86 void Timer::GetRealtimeTime(timespec &ts) {
  87   gettime(CLOCK_REALTIME, &ts);
  88 }
  89
  90 static int64_t to_usec(const timeval& tv) {
  91   return (int64_t(tv.tv_sec) * 1000000) + tv.tv_usec;
  92 }
  93
  94 int64_t Timer::GetCurrentTimeMicros() {
  95   timeval tv;
  96   gettimeofday(&tv, 0);
  97   return to_usec(tv);
  98 }
  99
 100 int64_t Timer::GetRusageMicros(Type t, Who who) {
 101   assert(t != WallTime);
 102
 103   rusage ru;
 104   memset(&ru, 0, sizeof(ru));
 105   auto DEBUG_ONLY ret = getrusage(who, &ru);
 106   assert(ret == 0);
 107
 108   switch (t) {
 109     case SystemCPU: return to_usec(ru.ru_stime);
 110     case UserCPU:   return to_usec(ru.ru_utime);
 111     case TotalCPU:  return to_usec(ru.ru_stime) + to_usec(ru.ru_utime);
 112     default: always_assert(false);
 113   }
 114 }
 115
 116 int64_t Timer::GetThreadCPUTimeNanos() {
 117   return gettime_ns(CLOCK_THREAD_CPUTIME_ID);
 118 }
 119
 120 int64_t Timer::measure() const {
 121   if (m_type == WallTime) {
 122     return GetCurrentTimeMicros();
 123   }
 124
 125   return GetRusageMicros(m_type, Timer::Self);
 126 }
 127
 128 const char *Timer::getName() const {
 129   switch (m_type) {
 130   case WallTime:  return "wall time";
 131   case SystemCPU: return "system cpu";
 132   case UserCPU:   return "user cpu";
 133   case TotalCPU:  return "total cpu";
 134   }
 135   always_assert(false);
 136 }
 137
 138 ///////////////////////////////////////////////////////////////////////////////
 139
 140 SlowTimer::SlowTimer(int64_t msThreshold, const char *location, const char *info)
 141   : m_timer(Timer::WallTime), m_msThreshold(msThreshold) {
 142   if (location) m_location = location;
 143   if (info) m_info = info;
 144 }
 145
 146 SlowTimer::~SlowTimer() {
 147   int64_t msec = getTime();
 148   if (msec >= m_msThreshold && m_msThreshold != 0) {
 149     Logger::Error("SlowTimer [%" PRId64 "ms] at %s: %s",
 150                   msec, m_location.c_str(), m_info.c_str());
 151   }
 152 }
 153
 154 int64_t SlowTimer::getTime() const {
 155   return m_timer.getMicroSeconds() / 1000;
 156 }
 157
 158 ///////////////////////////////////////////////////////////////////////////////
 159
 160 int gettime(clockid_t clock, timespec* ts) {
 161   if (clock != CLOCK_THREAD_CPUTIME_ID) {
 162     return folly::chrono::clock_gettime(clock, ts);
 163   }
 164
 165   constexpr uint64_t sec_to_ns = 1000000000;
 166
 167 #ifdef FACEBOOK
 168   uint64_t time;
 169   if (!fb_perf_get_thread_cputime_ns(&time)) {
 170     time += s_extra_request_nanoseconds;
 171     ts->tv_sec = time / sec_to_ns;
 172     ts->tv_nsec = time % sec_to_ns;
 173     return 0;
 174   }
 175 #endif
 176
 177   auto const ret = folly::chrono::clock_gettime(clock, ts);
 178   always_assert(ts->tv_nsec < sec_to_ns);
 179
 180   ts->tv_sec += s_extra_request_nanoseconds / sec_to_ns;
 181   auto res = ts->tv_nsec + s_extra_request_nanoseconds % sec_to_ns;
 182   if (res > sec_to_ns) {
 183     res -= sec_to_ns;
 184     ts->tv_sec += 1;
 185   }
 186   ts->tv_nsec = res;
 187
 188   return ret;
 189 }
 190
 191 int64_t gettime_ns(clockid_t clock) {
 192   if (clock != CLOCK_THREAD_CPUTIME_ID) {
 193     return folly::chrono::clock_gettime_ns(clock);
 194   }
 195
 196 #ifdef FACEBOOK
 197   uint64_t time;
 198   if (!fb_perf_get_thread_cputime_ns(&time)) {
 199     return time + s_extra_request_nanoseconds;
 200   }
 201 #endif
 202
 203   return folly::chrono::clock_gettime_ns(clock) + s_extra_request_nanoseconds;
 204 }
 205
 206 int64_t gettime_diff_us(const timespec& start, const timespec& end) {
 207   int64_t dsec = end.tv_sec - start.tv_sec;
 208   int64_t dnsec = end.tv_nsec - start.tv_nsec;
 209   return dsec * 1000000 + dnsec / 1000;
 210 }
 211
 212 ///////////////////////////////////////////////////////////////////////////////
 213 }