hphp/runtime/base/request-tracing-inl.h

   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 #ifndef incl_HPHP_REQUEST_TRACING_INL_H_
  18 #define incl_HPHP_REQUEST_TRACING_INL_H_
  19
  20 #include <folly/AtomicHashMap.h>
  21 #include <folly/MapUtil.h>
  22 #include <folly/portability/SysTime.h>
  23
  24 #include "hphp/util/assertions.h"
  25
  26 namespace HPHP { struct StringData; }
  27
  28 namespace HPHP { namespace rqtrace {
  29
  30 namespace detail {
  31
  32 struct AtomicEventStats {
  33   struct Empty{};
  34   AtomicEventStats() = default;
  35   AtomicEventStats(Empty) {}
  36
  37   operator EventStats() {
  38     return {
  39       total_duration.load(std::memory_order_relaxed),
  40       total_count.load(std::memory_order_relaxed)
  41     };
  42   }
  43
  44   std::atomic<uint64_t> total_duration;
  45   std::atomic<uint64_t> total_count;
  46 };
  47
  48 using AtomicEventMap = folly::AtomicHashMap<const StringData*,AtomicEventStats>;
  49 extern AtomicEventMap g_events;
  50
  51 inline int64_t to_micros(timespec t) {
  52   return (int64_t(t.tv_sec) * 1000000) + t.tv_nsec / 1000;
  53 }
  54
  55 inline int64_t CurrentMicroTime() {
  56   timeval tv;
  57   gettimeofday(&tv, 0);
  58   return (int64_t(tv.tv_sec) * 1000000) + tv.tv_usec;
  59 }
  60
  61 ////////////////////////////////////////////////////////////////////////////////
  62 }
  63
  64 inline Event::Event(folly::StringPiece name) : m_name(name) {}
  65
  66 inline folly::StringPiece Event::name() const {
  67   return m_name;
  68 }
  69
  70 inline uint64_t Event::startMicro() const {
  71   assertx(finished());
  72   return m_startMicro;
  73 }
  74
  75 inline uint64_t Event::stopMicro() const {
  76   assertx(finished());
  77   return m_stopMicro;
  78 }
  79
  80 inline uint64_t Event::duration() const {
  81   assertx(finished());
  82   return m_stopMicro - m_startMicro;
  83 }
  84
  85 inline const AnnotationMap& Event::annotations() const {
  86   return m_annot;
  87 }
  88
  89 inline bool Event::finished() const {
  90   return m_stopMicro && m_stopMicro;
  91 }
  92
  93 inline void Event::begin(folly::Optional<timespec> t) {
  94   assertx(!m_startMicro);
  95   m_startMicro = detail::CurrentMicroTime();
  96   m_startMicro = t ? detail::to_micros(*t) : detail::CurrentMicroTime();
  97 }
  98
  99 inline void Event::end(folly::Optional<timespec> t) {
 100   assertx(m_startMicro && !m_stopMicro);
 101   m_stopMicro = t ? detail::to_micros(*t) : detail::CurrentMicroTime();
 102 }
 103
 104 inline void Event::annotate(folly::StringPiece key, folly::StringPiece value) {
 105   m_annot.emplace(key, value);
 106 }
 107
 108 ////////////////////////////////////////////////////////////////////////////////
 109
 110 inline const std::vector<Event>& Scope::events() const {
 111   return m_sortedEvents;
 112 }
 113
 114 inline void Scope::setEventPrefix(folly::StringPiece s) {
 115   assertx(m_prefix.empty());
 116   m_prefix = std::string(s);
 117 }
 118
 119 inline void Scope::setEventSuffix(folly::StringPiece s) {
 120   assertx(m_suffix.empty());
 121   m_suffix = std::string(s);
 122 }
 123
 124 inline Event& Scope::appendEvent(Event&& ev) {
 125   assertx(!finished());
 126   assertx(ev.finished());
 127   assertx(
 128     m_sortedEvents.empty() ||
 129     m_sortedEvents.back().startMicro() + m_sortedEvents.back().duration()
 130       <= ev.startMicro()
 131   );
 132   ev.m_name.insert(ev.m_name.begin(), m_prefix.begin(), m_prefix.end());
 133   ev.m_name.append(m_suffix);
 134   m_sortedEvents.emplace_back(std::move(ev));
 135   return m_sortedEvents.back();
 136 }
 137
 138 ////////////////////////////////////////////////////////////////////////////////
 139
 140 inline Scope& Trace::createScope(folly::StringPiece name) {
 141   assertx(m_sortedScopes.empty() || m_sortedScopes.back().finished());
 142   m_sortedScopes.emplace_back(name);
 143   return m_sortedScopes.back();
 144 }
 145
 146 inline void Trace::appendEvent(Event&& e) {
 147   assertx(!m_sortedScopes.empty());
 148   auto& new_ev = m_sortedScopes.back().appendEvent(std::move(e));
 149   auto& info = m_stats[std::string(new_ev.name())];
 150   info.total_duration += new_ev.duration();
 151   info.total_count++;
 152 }
 153
 154 inline Scope& Trace::scope() {
 155   assertx(!m_sortedScopes.empty());
 156   assertx(!m_sortedScopes.back().finished());
 157   return m_sortedScopes.back();
 158 }
 159
 160 inline const Scope& Trace::scope() const {
 161   return const_cast<Trace*>(this)->scope();
 162 }
 163
 164 inline EventStats Trace::stats_for(folly::StringPiece name) const {
 165   return folly::get_default(m_stats, std::string(name), EventStats{});
 166 }
 167
 168 inline const EventMap& Trace::stats() const {
 169   return m_stats;
 170 }
 171
 172 inline void Trace::finishScope() {
 173   assertx(!m_sortedScopes.empty());
 174   assertx(m_sortedScopes.back().finished());
 175
 176   auto& info = m_stats[std::string(m_sortedScopes.back().name())];
 177   info.total_duration += m_sortedScopes.back().duration();
 178   info.total_count++;
 179 }
 180
 181 inline bool Trace::hasActiveScope() const {
 182   return !m_sortedScopes.empty() && !m_sortedScopes.back().finished();
 183 }
 184
 185 ////////////////////////////////////////////////////////////////////////////////
 186
 187 inline EventGuard::EventGuard(
 188   Trace* t,
 189   folly::StringPiece name,
 190   folly::Optional<timespec> ts
 191 ) : m_trace(t && t->hasActiveScope() ? t : nullptr)
 192   , m_event(name)
 193 {
 194   if (m_trace) m_event.begin(ts);
 195 }
 196
 197 inline EventGuard::~EventGuard() {
 198   finish();
 199 }
 200
 201 inline void EventGuard::annotate(
 202   folly::StringPiece key,
 203   folly::StringPiece value
 204 ) {
 205   if (m_trace) m_event.annotate(key, value);
 206 }
 207
 208 inline void EventGuard::finish(folly::Optional<timespec> t) {
 209   if (m_trace) {
 210     m_event.end(t);
 211     m_trace->appendEvent(std::move(m_event));
 212     m_trace = nullptr;
 213   }
 214 }
 215
 216 ////////////////////////////////////////////////////////////////////////////////
 217
 218 inline ScopeGuard::ScopeGuard(
 219   Trace* t,
 220   folly::StringPiece name,
 221   folly::Optional<timespec> ts
 222 ) : m_trace(t)
 223   , m_scope(t ? &t->createScope(name) : nullptr)
 224 {
 225   if (m_scope) m_scope->begin(ts);
 226 }
 227
 228 inline ScopeGuard::~ScopeGuard() {
 229   finish();
 230 }
 231
 232 inline void ScopeGuard::annotate(folly::StringPiece k, folly::StringPiece v) {
 233   if (m_scope) m_scope->annotate(k, v);
 234 }
 235
 236 inline void ScopeGuard::setEventPrefix(folly::StringPiece fx) {
 237   if (m_scope) m_scope->setEventPrefix(fx);
 238 }
 239
 240 inline void ScopeGuard::setEventSuffix(folly::StringPiece fx) {
 241   if (m_scope) m_scope->setEventSuffix(fx);
 242 }
 243
 244 inline void ScopeGuard::finish(folly::Optional<timespec> t) {
 245   if (m_scope) {
 246     m_scope->end(t);
 247     m_trace->finishScope();
 248     m_trace = nullptr;
 249     m_scope = nullptr;
 250   }
 251 }
 252
 253 ////////////////////////////////////////////////////////////////////////////////
 254
 255 inline Range::Range(
 256   folly::StringPiece name,
 257   uint64_t start,
 258   uint64_t end,
 259   const Scope& scope,
 260   const Event& event
 261 ) : m_name(name)
 262   , m_startMicro(start)
 263   , m_stopMicro(end)
 264   , m_scope(scope)
 265   , m_event(event)
 266 {
 267   assertx(m_startMicro && m_stopMicro);
 268   assertx(m_stopMicro >= m_startMicro);
 269   assertx(!m_name.empty());
 270 }
 271
 272 inline folly::StringPiece Range::name() const {
 273   return m_name;
 274 }
 275
 276 inline uint64_t Range::begin() const {
 277   return m_startMicro;
 278 }
 279
 280 inline uint64_t Range::end() const {
 281   return m_stopMicro;
 282 }
 283
 284 inline uint64_t Range::duration() const {
 285   return m_stopMicro - m_startMicro;
 286 }
 287
 288 template<class F>
 289 void Range::visitAnnotations(F&& fun) const {
 290   for (auto& a : m_scope.annotations()) {
 291     fun(a.first, a.second);
 292   }
 293
 294   if ((Event*)&m_scope == &m_event) return;
 295
 296   for (auto& a : m_event.annotations()) {
 297     fun(a.first, a.second);
 298   }
 299 }
 300
 301 ////////////////////////////////////////////////////////////////////////////////
 302
 303 template<class F>
 304 void visit_ranges(const Trace& t, F&& fun) {
 305   for (auto& s : t.scopes()) {
 306     if (s.events().empty()) {
 307       fun(Range(
 308         folly::sformat("{}_BEGIN to {}_END", s.name(), s.name()),
 309         s.startMicro(),
 310         s.stopMicro(),
 311         s,
 312         s
 313       ));
 314       continue;
 315     }
 316     fun(Range(
 317       folly::sformat("{}_BEGIN to {}", s.name(), s.events().front().name()),
 318       s.startMicro(),
 319       s.events().front().startMicro(),
 320       s,
 321       s
 322     ));
 323     for (int i = 0; i < s.events().size() - 1; ++i) {
 324       auto const& start = s.events()[i];
 325       auto const& end = s.events()[i];
 326       fun(Range(
 327         folly::sformat("{} to {}", start.name(), end.name()),
 328         start.startMicro(),
 329         start.stopMicro(),
 330         s,
 331         start
 332       ));
 333     }
 334     fun(
 335       folly::sformat("{} to {}_END", s.events().back().name(), s.name()),
 336       s.events().back().startMicro(),
 337       s.stopMicro(),
 338       s,
 339       s.events().back()
 340     );
 341   }
 342 }
 343
 344 ////////////////////////////////////////////////////////////////////////////////
 345
 346 template<class F>
 347 void visit_process_stats(F&& fun) {
 348   for (auto& pair : detail::g_events) {
 349     fun(pair.first, pair.second);
 350   }
 351 }
 352
 353 ////////////////////////////////////////////////////////////////////////////////
 354 }}
 355
 356 #endif