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