hphp/util/trace.h

   1 /*
   2
   3    +----------------------------------------------------------------------+
   4    | HipHop for PHP                                                       |
   5    +----------------------------------------------------------------------+
   6    | Copyright (c) 2010-present Facebook, Inc. (http://www.facebook.com)  |
   7    +----------------------------------------------------------------------+
   8    | This source file is subject to version 3.01 of the PHP license,      |
   9    | that is bundled with this package in the file LICENSE, and is        |
  10    | available through the world-wide-web at the following url:           |
  11    | http://www.php.net/license/3_01.txt                                  |
  12    | If you did not receive a copy of the PHP license and are unable to   |
  13    | obtain it through the world-wide-web, please send a note to          |
  14    | license@php.net so we can mail you a copy immediately.               |
  15    +----------------------------------------------------------------------+
  16 */
  17
  18 #ifndef incl_HPHP_TRACE_H_
  19 #define incl_HPHP_TRACE_H_
  20
  21 #include <string>
  22 #include <vector>
  23 #include <stdarg.h>
  24
  25 #include <folly/Format.h>
  26 #include <folly/portability/Unistd.h>
  27
  28 #include "hphp/util/assertions.h"
  29 #include "hphp/util/portability.h"
  30 #include "hphp/util/text-color.h"
  31
  32 /*
  33  * Runtime-selectable trace facility. A trace statement has both a module and a
  34  * level associated with it;  Enable tracing a module by setting the TRACE
  35  * environment variable to a comma-separated list of module:level pairs. E.g.:
  36  *
  37  * env TRACE=mcg:1,bcinterp:3,tmp0:1 ./hhvm/hhvm ...
  38  *
  39  * In a source file, select the compilation unit's module by calling the
  40  * TRACE_SET_MOD macro. E.g.,
  41  *
  42  *   TRACE_SET_MOD(mcg);
  43  *
  44  *   ...
  45  *   TRACE(0, "See this for any trace-enabled build: %d\n", foo);
  46  *   TRACE(1, "Trace-level must be 1 or higher for this one\n");
  47  *
  48  * While the levels are arbitrary integers, code so far is following a
  49  * rough convention of 1-5, where 1 is minimal and 5 is quite verbose.
  50  *
  51  * Normally trace information is printed to /tmp/hphp.log. You can
  52  * override the environment variable HPHP_TRACE_FILE to change
  53  * this. (Note you can set it to something like /dev/stderr or
  54  * /dev/stdout if you want the logs printed to your terminal).
  55  *
  56  * When printing to the terminal, some traces will know how to use
  57  * colorization.  You can set HPHP_TRACE_TTY to tell the tracing
  58  * facility to assume it should colorize even if the output file isn't
  59  * obviously a tty.
  60  */
  61
  62 /*
  63  * Trace levels can be bumped on a per-module, per-scope basis.  This
  64  * lets you run code that has a set of trace levels in a mode as if
  65  * they were all higher.
  66  *
  67  * Example:
  68  *
  69  *   {
  70  *     Trace::Bump bumper{Trace::mcg, 2};
  71  *     FTRACE(1, "asd\n");  // only fires at level >= 3
  72  *   }
  73  *   FTRACE(1, "asd\n");    // back to normal
  74  *
  75  *
  76  * There is also support for conditionally bumping in the bumper:
  77  *
  78  *   {
  79  *     Trace::Bump bumper{Trace::mcg, 2, somePredicate(foo)};
  80  *     // Only bumped if somePredicate(foo) returned true.
  81  *   }
  82  *
  83  * Note however that if you use that form, `somePredicate' will be
  84  * evaluated even if tracing is off.
  85  */
  86
  87 namespace HPHP {
  88 namespace Trace {
  89
  90 #define TRACE_MODULES \
  91       TM(tprefix)     /* Meta: prefix with string */  \
  92       TM(traceAsync)  /* Meta: lazy writes to disk */ \
  93       TM(apc)           \
  94       TM(asmx64)        \
  95       TM(asmppc64)      \
  96       TM(atomicvector)  \
  97       TM(bcinterp)      \
  98       TM(bisector)      \
  99       TM(class_load)    \
 100       TM(datablock)     \
 101       TM(debugger)      \
 102       TM(debuggerflow)  \
 103       TM(debuginfo)     \
 104       TM(decreftype)    \
 105       TM(dispatchBB)    \
 106       TM(ehframe)       \
 107       TM(emitter)       \
 108       TM(fixup)         \
 109       TM(fr)            \
 110       TM(gc)            \
 111       TM(heapgraph)     \
 112       TM(heapreport)    \
 113       TM(hfsort)        \
 114       TM(hhas)          \
 115       TM(hhbbc)         \
 116       TM(hhbbc_cfg)     \
 117       TM(hhbbc_dce)     \
 118       TM(hhbbc_dump)    \
 119       TM(hhbbc_emit)    \
 120       TM(hhbbc_iface)   \
 121       TM(hhbbc_index)   \
 122       TM(hhbbc_stats)   \
 123       TM(hhbbc_time)    \
 124       TM(hhbc)          \
 125       TM(hhir)          \
 126       TM(hhirTracelets) \
 127       TM(hhir_alias)    \
 128       TM(hhir_cfg)      \
 129       TM(hhir_checkhoist) \
 130       TM(hhir_dce)      \
 131       TM(hhir_fixhint)  \
 132       TM(hhir_fsm)      \
 133       TM(hhir_gvn)      \
 134       TM(hhir_licm)     \
 135       TM(hhir_load)     \
 136       TM(hhir_loop)     \
 137       TM(hhir_phi)      \
 138       TM(hhir_refcount) \
 139       TM(hhir_refineTmps) \
 140       TM(hhir_store)    \
 141       TM(hhir_unreachable) \
 142       TM(hhprof)        \
 143       TM(inlining)      \
 144       TM(instancebits)  \
 145       TM(intercept)     \
 146       TM(interpOne)     \
 147       TM(irlower)       \
 148       TM(jittime)       \
 149       TM(layout)        \
 150       TM(libxml)        \
 151       TM(mcg)           \
 152       TM(mcgstats)      \
 153       TM(minstr)        \
 154       TM(mm)            \
 155       TM(objprof)       \
 156       TM(perf_mem_event) \
 157       TM(pgo)           \
 158       TM(printir)       \
 159       TM(prof_branch)   \
 160       TM(prof_array)    \
 161       TM(rat)           \
 162       TM(refcount)      \
 163       TM(regalloc)      \
 164       TM(region)        \
 165       TM(reusetc)       \
 166       TM(ringbuffer)    \
 167       TM(runtime)       \
 168       TM(servicereq)    \
 169       TM(simplify)      \
 170       TM(stat)          \
 171       TM(statgroups)    \
 172       TM(stats)         \
 173       TM(targetcache)   \
 174       TM(tcspace)       \
 175       TM(trans)         \
 176       TM(treadmill)     \
 177       TM(txdeps)        \
 178       TM(txlease)       \
 179       TM(typeProfile)   \
 180       TM(unwind)        \
 181       TM(ustubs)        \
 182       TM(vasm)          \
 183       TM(vasm_copy)     \
 184       TM(vasm_phi)      \
 185       TM(xenon)         \
 186       TM(xls)           \
 187       TM(xls_stats)     \
 188       TM(pdce_inline)   \
 189       TM(clisrv)        \
 190       TM(factparse)     \
 191       /* Stress categories, to exercise rare paths */ \
 192       TM(stress_txInterpPct)  \
 193       TM(stress_txInterpSeed) \
 194       /* Jit bisection interval */ \
 195       TM(txOpBisectLow)   \
 196       TM(txOpBisectHigh)  \
 197       /* Temporary categories, to save compilation time */ \
 198       TM(tmp0)  TM(tmp1)  TM(tmp2)  TM(tmp3)               \
 199       TM(tmp4)  TM(tmp5)  TM(tmp6)  TM(tmp7)               \
 200       TM(tmp8)  TM(tmp9)  TM(tmp10) TM(tmp11)              \
 201       TM(tmp12) TM(tmp13) TM(tmp14) TM(tmp15)
 202
 203 enum Module {
 204 #define TM(x) \
 205   x,
 206   TRACE_MODULES
 207 #undef TM
 208   NumModules
 209 };
 210
 211 //////////////////////////////////////////////////////////////////////
 212
 213 /*
 214  * S-expression style structured pretty-printing. Implement
 215  * std::string pretty() const { }, with the convention that
 216  * nested structures are notated as lisp-style trees:
 217  *
 218  *    (<typename> field0 field1)
 219  *
 220  * E.g.:
 221  *    (Location Stack 1)
 222  *
 223  * The repetitve prettyNode() templates are intended to aid
 224  * implementing pretty().
 225  */
 226
 227 template<typename P1>
 228 std::string prettyNode(const char* name, const std::vector<P1>& vec) {
 229   using std::string;
 230   std::string retval = string("(") + string(name) + string(" ");
 231   for(size_t i = 0; i < vec.size(); i++) {
 232     retval += vec[i].pretty();
 233     if (i != vec.size() - 1) {
 234       retval += string(" ");
 235     }
 236   }
 237   return retval + string(")");
 238 }
 239
 240 template<typename P1>
 241 std::string prettyNode(const char* name, const P1& p1) {
 242   using std::string;
 243   return string("(") + string(name) + string(" ") +
 244     p1.pretty() +
 245     string(")");
 246 }
 247
 248 template<> std::string prettyNode(const char* name, const std::string& s);
 249
 250 template<typename P1, typename P2>
 251 std::string prettyNode(const char* name, const P1& p1, const P2& p2) {
 252   using std::string;
 253   return string("(") + string(name) + string(" ") +
 254     p1.pretty() + string(" ") + p2.pretty() +
 255     string(")");
 256 }
 257
 258 void traceRelease(ATTRIBUTE_PRINTF_STRING const char*, ...)
 259   ATTRIBUTE_PRINTF(1,2);
 260 void traceRelease(const std::string& s);
 261
 262 template<typename... Args>
 263 void ftraceRelease(Args&&... args) {
 264   traceRelease("%s", folly::format(std::forward<Args>(args)...).str().c_str());
 265 }
 266
 267 // Trace to the global ring buffer and the normal TRACE destination.
 268 #define TRACE_RB(n, ...)                                        \
 269   ONTRACE(n, HPHP::Trace::traceRingBufferRelease(__VA_ARGS__)); \
 270   TRACE(n, __VA_ARGS__);
 271 void traceRingBufferRelease(ATTRIBUTE_PRINTF_STRING const char* fmt, ...)
 272   ATTRIBUTE_PRINTF(1,2);
 273
 274 extern int levels[NumModules];
 275 extern __thread int tl_levels[NumModules];
 276 const char* moduleName(Module mod);
 277 inline bool moduleEnabledRelease(Module tm, int level = 1) {
 278   return levels[tm] + tl_levels[tm] >= level;
 279 }
 280
 281 // Trace::Bump that is on for release tracing.
 282 struct BumpRelease {
 283   BumpRelease(Module mod, int adjust, bool condition = true)
 284     : m_live(condition)
 285     , m_mod(mod)
 286     , m_adjust(adjust)
 287   {
 288     if (m_live) tl_levels[m_mod] -= m_adjust;
 289   }
 290
 291   BumpRelease(BumpRelease&& o) noexcept
 292     : m_live(o.m_live)
 293     , m_mod(o.m_mod)
 294     , m_adjust(o.m_adjust)
 295   {
 296     o.m_live = false;
 297   }
 298
 299   ~BumpRelease() {
 300     if (m_live) tl_levels[m_mod] += m_adjust;
 301   }
 302
 303   BumpRelease(const BumpRelease&) = delete;
 304   BumpRelease& operator=(const BumpRelease&) = delete;
 305
 306 private:
 307   bool m_live;
 308   Module m_mod;
 309   int m_adjust;
 310 };
 311
 312 //////////////////////////////////////////////////////////////////////
 313
 314 #if (defined(DEBUG) || defined(USE_TRACE)) /* { */
 315 #  ifndef USE_TRACE
 316 #    define USE_TRACE 1
 317 #  endif
 318
 319 //////////////////////////////////////////////////////////////////////
 320 /*
 321  * Implementation of for when tracing is enabled.
 322  */
 323
 324 inline bool moduleEnabled(Module tm, int level = 1) {
 325   return moduleEnabledRelease(tm, level);
 326 }
 327
 328 inline int moduleLevel(Module tm) { return levels[tm]; }
 329
 330 #define HPHP_TRACE
 331
 332 const bool enabled = true;
 333
 334 #define ONTRACE_MOD(module, n, x) do {    \
 335   if (HPHP::Trace::moduleEnabled(module, n)) {  \
 336     x;                                          \
 337   } } while(0)
 338
 339 #define ONTRACE(n, x) ONTRACE_MOD(TRACEMOD, n, x)
 340
 341 #define TRACE(n, ...) ONTRACE(n, HPHP::Trace::trace(__VA_ARGS__))
 342 #define FTRACE(n, ...)                                        \
 343   ONTRACE(n, HPHP::Trace::trace("%s",                         \
 344              folly::format(__VA_ARGS__).str().c_str()))
 345 #define TRACE_MOD(mod, level, ...) \
 346   ONTRACE_MOD(mod, level, HPHP::Trace::trace(__VA_ARGS__))
 347 #define FTRACE_MOD(mod, level, ...)                     \
 348   ONTRACE_MOD(mod, level, HPHP::Trace::trace("%s",      \
 349              folly::format(__VA_ARGS__).str().c_str()))
 350 #define TRACE_SET_MOD(name)  \
 351   UNUSED static const HPHP::Trace::Module TRACEMOD = HPHP::Trace::name;
 352
 353 /*
 354  * The Indent struct and ITRACE are used for tracing with nested
 355  * indentation. Create an Indent object on the stack to increase the nesting
 356  * level, then use ITRACE just as you would use FTRACE.
 357  */
 358 extern __thread int indentDepth;
 359 struct Indent {
 360   explicit Indent(int n = 2) : n(n) { indentDepth += n; }
 361   ~Indent()                         { indentDepth -= n; }
 362
 363   int n;
 364 };
 365
 366 // See doc comment above for usage.
 367 using Bump = BumpRelease;
 368
 369 inline std::string indent() {
 370   return std::string(indentDepth, ' ');
 371 }
 372
 373 template<typename... Args>
 374 inline void itraceImpl(const char* fmtRaw, Args&&... args) {
 375   auto const fmt = indent() + fmtRaw;
 376   Trace::ftraceRelease(fmt, std::forward<Args>(args)...);
 377 }
 378 #define ITRACE(level, ...) ONTRACE((level), Trace::itraceImpl(__VA_ARGS__));
 379 #define ITRACE_MOD(mod, level, ...)                             \
 380   ONTRACE_MOD(mod, level, Trace::itraceImpl(__VA_ARGS__));
 381
 382 void trace(ATTRIBUTE_PRINTF_STRING const char *, ...) ATTRIBUTE_PRINTF(1,2);
 383 void trace(const std::string&);
 384
 385 template<typename Pretty>
 386 inline void trace(Pretty p) { trace(p.pretty() + std::string("\n")); }
 387
 388 void vtrace(ATTRIBUTE_PRINTF_STRING const char *fmt, va_list args)
 389   ATTRIBUTE_PRINTF(1,0);
 390 void dumpRingbuffer();
 391
 392 // Ensure a tracing output file has been opened.
 393 void ensureInit(std::string outFile);
 394 // Set tracing levels for this thread using a module:level,... specification.
 395 // If traceSpec is empty, all levels for this thread are zeroed.
 396 void setTraceThread(const std::string& traceSpec);
 397
 398 //////////////////////////////////////////////////////////////////////
 399
 400 #else /* } (defined(DEBUG) || defined(USE_TRACE)) { */
 401
 402 //////////////////////////////////////////////////////////////////////
 403 /*
 404  * Implementation for when tracing is disabled.
 405  */
 406
 407 #define ONTRACE(...)      do { } while (0)
 408 #define TRACE(...)        do { } while (0)
 409 #define FTRACE(...)       do { } while (0)
 410 #define ONTRACE_MOD(...)  do { } while (0)
 411 #define TRACE_MOD(...)    do { } while (0)
 412 #define FTRACE_MOD(...)   do { } while (0)
 413 #define TRACE_SET_MOD(name) \
 414   DEBUG_ONLY static const HPHP::Trace::Module TRACEMOD = HPHP::Trace::name;
 415
 416 #define ITRACE(...)     do { } while (0)
 417 #define ITRACE_MOD(...) do { } while (0)
 418 struct Indent {
 419   Indent() {
 420     always_assert(true && "If this struct is completely empty we get unused "
 421                           "variable warnings in code that uses it.");
 422   }
 423 };
 424 inline std::string indent() {
 425   return std::string();
 426 }
 427
 428 struct Bump {
 429   Bump(Module /*mod*/, int /*adjust*/, bool /*condition*/ = true) {
 430     always_assert(true && "If this struct is completely empty we get unused "
 431                           "variable warnings in code that uses it.");
 432   }
 433 };
 434
 435 const bool enabled = false;
 436
 437 inline void trace(const char*, ...) {}
 438 inline void trace(const std::string&) {}
 439 inline void vtrace(const char*, va_list) {}
 440 inline bool moduleEnabled(Module /*t*/, int /*level*/ = 1) {
 441   return false;
 442 }
 443 inline int moduleLevel(Module /*tm*/) {
 444   return 0;
 445 }
 446 inline void ensureInit(std::string /*outFile*/) {}
 447 inline void setTraceThread(const std::string& /*traceSpec*/) {}
 448
 449 //////////////////////////////////////////////////////////////////////
 450
 451 #endif /* } (defined(DEBUG) || defined(USE_TRACE)) */
 452
 453 } // Trace
 454
 455 // Optional color utility for trace dumps; when output is a tty or
 456 // when we've been told to assume it is.
 457 inline const char* color(const char* color) {
 458   static auto const shouldColorize = []() -> bool {
 459     auto const traceEnv  = getenv("HPHP_TRACE_FILE");
 460     auto const assumeTTY = getenv("HPHP_TRACE_TTY");
 461     if (assumeTTY) return true;
 462     if (!traceEnv) return false;
 463     return
 464       !strcmp(traceEnv, "/dev/stdout") ? isatty(1) :
 465       !strcmp(traceEnv, "/dev/stderr") ? isatty(2) :
 466       false;
 467   }();
 468   return shouldColorize ? color : "";
 469 }
 470
 471 inline std::string color(const char* fg, const char* bg) {
 472   auto const s = add_bgcolor(fg, bg);
 473   return color(s.c_str());
 474 }
 475
 476 //////////////////////////////////////////////////////////////////////
 477
 478 FOLLY_CREATE_HAS_MEMBER_FN_TRAITS(has_toString, toString);
 479
 480 } // HPHP
 481
 482 namespace folly {
 483 template<typename Val>
 484 class FormatValue<Val,
 485                    typename std::enable_if<
 486                      HPHP::has_toString<Val, std::string() const>::value &&
 487                      // This is here because MSVC decides that StringPiece matches
 488                      // both this overload as well as the FormatValue overload for
 489                      // string-y types in folly itself.
 490                      !std::is_same<Val, StringPiece>::value,
 491                      void
 492                    >::type> {
 493  public:
 494   explicit FormatValue(const Val& val) : m_val(val) {}
 495
 496   template<typename Callback> void format(FormatArg& arg, Callback& cb) const {
 497     format_value::formatString(m_val.toString(), arg, cb);
 498   }
 499
 500  private:
 501   const Val& m_val;
 502 };
 503 }
 504
 505 #endif /* incl_HPHP_TRACE_H_ */