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_worker) \
 113       TM(facts)         \
 114       TM(fixup)         \
 115       TM(fr)            \
 116       TM(funcorder)     \
 117       TM(gc)            \
 118       TM(hackc_translate) \
 119       TM(heapgraph)     \
 120       TM(heapreport)    \
 121       TM(hfsort)        \
 122       TM(hhas)          \
 123       TM(hhbbc)         \
 124       TM(hhbbc_cfg)     \
 125       TM(hhbbc_dce)     \
 126       TM(hhbbc_dump)    \
 127       TM(hhbbc_parse)   \
 128       TM(hhbbc_emit)    \
 129       TM(hhbbc_iface)   \
 130       TM(hhbbc_index)   \
 131       TM(hhbbc_mem)     \
 132       TM(hhbbc_stats)   \
 133       TM(hhbbc_time)    \
 134       TM(hhbc)          \
 135       TM(hhir)          \
 136       TM(hhirTracelets) \
 137       TM(hhir_alias)    \
 138       TM(hhir_cfg)      \
 139       TM(hhir_checkhoist) \
 140       TM(hhir_dce)      \
 141       TM(hhir_fixhint)  \
 142       TM(hhir_fsm)      \
 143       TM(hhir_gvn)      \
 144       TM(hhir_licm)     \
 145       TM(hhir_load)     \
 146       TM(hhir_loop)     \
 147       TM(hhir_lowerbespokes) \
 148       TM(hhir_outline)  \
 149       TM(hhir_phi)      \
 150       TM(hhir_sinkdefs) \
 151       TM(hhir_refcount) \
 152       TM(hhir_refineTmps) \
 153       TM(hhir_checkTypes) \
 154       TM(hhir_store)    \
 155       TM(hhir_unreachable) \
 156       TM(hhir_vanilla)  \
 157       TM(hhprof)        \
 158       TM(inlining)      \
 159       TM(instancebits)  \
 160       TM(intercept)     \
 161       TM(interpOne)     \
 162       TM(irlower)       \
 163       TM(isame)         \
 164       TM(jittime)       \
 165       TM(layout)        \
 166       TM(libxml)        \
 167       TM(logging)       \
 168       TM(mcg)           \
 169       TM(mcgstats)      \
 170       TM(minstr)        \
 171       TM(mm)            \
 172       TM(objprof)       \
 173       TM(perf_mem_event) \
 174       TM(pgo)           \
 175       TM(preg)          \
 176       TM(print_profiles)  \
 177       TM(printir)       \
 178       TM(printir_json)  \
 179       TM(prof_branch)   \
 180       TM(prof_array)    \
 181       TM(prof_prop)     \
 182       TM(rat)           \
 183       TM(refcount)      \
 184       TM(regalloc)      \
 185       TM(region)        \
 186       TM(repo_autoload) \
 187       TM(reusetc)       \
 188       TM(ringbuffer)    \
 189       TM(runtime)       \
 190       TM(servicereq)    \
 191       TM(sib)           \
 192       TM(simplify)      \
 193       TM(stat)          \
 194       TM(statgroups)    \
 195       TM(stats)         \
 196       TM(strobelight)   \
 197       TM(taint)         \
 198       TM(targetcache)   \
 199       TM(tcspace)       \
 200       TM(trans)         \
 201       TM(treadmill)     \
 202       TM(txdeps)        \
 203       TM(txlease)       \
 204       TM(typeProfile)   \
 205       TM(unit_parse)    \
 206       TM(unwind)        \
 207       TM(ustubs)        \
 208       TM(vasm)          \
 209       TM(vasm_block_count) \
 210       TM(vasm_copy)     \
 211       TM(vasm_graph_color) \
 212       TM(vasm_phi)      \
 213       TM(watchman)      \
 214       TM(xenon)         \
 215       TM(xls)           \
 216       TM(xls_stats)     \
 217       TM(clisrv)        \
 218       TM(factparse)     \
 219       TM(bccache)       \
 220       TM(idx)           \
 221       /* Stress categories, to exercise rare paths */ \
 222       TM(stress_txInterpPct)  \
 223       TM(stress_txInterpSeed) \
 224       /* Jit bisection interval */ \
 225       TM(txOpBisectLow)   \
 226       TM(txOpBisectHigh)  \
 227       /* Temporary categories, to save compilation time */ \
 228       TM(tmp0)  TM(tmp1)  TM(tmp2)  TM(tmp3)               \
 229       TM(tmp4)  TM(tmp5)  TM(tmp6)  TM(tmp7)               \
 230       TM(tmp8)  TM(tmp9)  TM(tmp10) TM(tmp11)              \
 231       TM(tmp12) TM(tmp13) TM(tmp14) TM(tmp15)
 232
 233 enum Module {
 234 #define TM(x) \
 235   x,
 236   TRACE_MODULES
 237 #undef TM
 238   NumModules
 239 };
 240
 241 //////////////////////////////////////////////////////////////////////
 242
 243 /*
 244  * S-expression style structured pretty-printing. Implement
 245  * std::string pretty() const { }, with the convention that
 246  * nested structures are notated as lisp-style trees:
 247  *
 248  *    (<typename> field0 field1)
 249  *
 250  * E.g.:
 251  *    (Location Stack 1)
 252  *
 253  * The repetitve prettyNode() templates are intended to aid
 254  * implementing pretty().
 255  */
 256
 257 template<typename P1>
 258 std::string prettyNode(const char* name, const std::vector<P1>& vec) {
 259   using std::string;
 260   std::string retval = string("(") + string(name) + string(" ");
 261   for(size_t i = 0; i < vec.size(); i++) {
 262     retval += vec[i].pretty();
 263     if (i != vec.size() - 1) {
 264       retval += string(" ");
 265     }
 266   }
 267   return retval + string(")");
 268 }
 269
 270 template<typename P1>
 271 std::string prettyNode(const char* name, const P1& p1) {
 272   using std::string;
 273   return string("(") + string(name) + string(" ") +
 274     p1.pretty() +
 275     string(")");
 276 }
 277
 278 template<> std::string prettyNode(const char* name, const std::string& s);
 279
 280 template<typename P1, typename P2>
 281 std::string prettyNode(const char* name, const P1& p1, const P2& p2) {
 282   using std::string;
 283   return string("(") + string(name) + string(" ") +
 284     p1.pretty() + string(" ") + p2.pretty() +
 285     string(")");
 286 }
 287
 288 void traceRelease(ATTRIBUTE_PRINTF_STRING const char*, ...)
 289   ATTRIBUTE_PRINTF(1,2);
 290 void traceRelease(const std::string& s);
 291
 292 template<typename... Args>
 293 void ftraceRelease(Args&&... args) {
 294   traceRelease("%s", folly::format(std::forward<Args>(args)...).str().c_str());
 295 }
 296
 297 // Trace to the global ring buffer and the normal TRACE destination.
 298 #define TRACE_RB(n, ...)                                        \
 299   ONTRACE(n, HPHP::Trace::traceRingBufferRelease(__VA_ARGS__)); \
 300   TRACE(n, __VA_ARGS__);
 301 void traceRingBufferRelease(ATTRIBUTE_PRINTF_STRING const char* fmt, ...)
 302   ATTRIBUTE_PRINTF(1,2);
 303
 304 extern int levels[NumModules];
 305 extern __thread int tl_levels[NumModules];
 306 const char* moduleName(Module mod);
 307 inline bool moduleEnabledRelease(Module tm, int level = 1) {
 308   return levels[tm] + tl_levels[tm] >= level;
 309 }
 310
 311 // Trace::Bump that is on for release tracing.
 312 struct BumpRelease {
 313   BumpRelease(Module mod, int adjust, bool condition = true)
 314     : m_live(condition)
 315     , m_mod(mod)
 316     , m_adjust(adjust)
 317   {
 318     if (m_live) tl_levels[m_mod] -= m_adjust;
 319   }
 320
 321   BumpRelease(BumpRelease&& o) noexcept
 322     : m_live(o.m_live)
 323     , m_mod(o.m_mod)
 324     , m_adjust(o.m_adjust)
 325   {
 326     o.m_live = false;
 327   }
 328
 329   ~BumpRelease() {
 330     if (m_live) tl_levels[m_mod] += m_adjust;
 331   }
 332
 333   BumpRelease negate() const {
 334     return BumpRelease{ m_mod, -m_adjust, m_live };
 335   }
 336
 337   BumpRelease(const BumpRelease&) = delete;
 338   BumpRelease& operator=(const BumpRelease&) = delete;
 339
 340 private:
 341   bool m_live;
 342   Module m_mod;
 343   int m_adjust;
 344 };
 345
 346 CompactVector<BumpRelease> bumpSpec(folly::StringPiece traceSpec);
 347
 348 //////////////////////////////////////////////////////////////////////
 349
 350 #if (!defined(NDEBUG) || defined(USE_TRACE)) /* { */
 351 #  ifndef USE_TRACE
 352 #    define USE_TRACE 1
 353 #  endif
 354
 355 //////////////////////////////////////////////////////////////////////
 356 /*
 357  * Implementation of for when tracing is enabled.
 358  */
 359
 360 inline bool moduleEnabled(Module tm, int level = 1) {
 361   return moduleEnabledRelease(tm, level);
 362 }
 363
 364 inline int moduleLevel(Module tm) { return levels[tm]; }
 365
 366 #define HPHP_TRACE
 367
 368 const bool enabled = true;
 369
 370 #define ONTRACE_MOD(module, n, x) do {    \
 371   if (HPHP::Trace::moduleEnabled(module, n)) {  \
 372     x;                                          \
 373   } } while(0)
 374
 375 #define ONTRACE(n, x) ONTRACE_MOD(TRACEMOD, n, x)
 376
 377 #define TRACE(n, ...) ONTRACE(n, HPHP::Trace::trace(__VA_ARGS__))
 378 #define FTRACE(n, ...)                                        \
 379   ONTRACE(n, HPHP::Trace::trace("%s",                         \
 380              folly::format(__VA_ARGS__).str().c_str()))
 381 #define TRACE_MOD(mod, level, ...) \
 382   ONTRACE_MOD(mod, level, HPHP::Trace::trace(__VA_ARGS__))
 383 #define FTRACE_MOD(mod, level, ...)                     \
 384   ONTRACE_MOD(mod, level, HPHP::Trace::trace("%s",      \
 385              folly::format(__VA_ARGS__).str().c_str()))
 386 #define TRACE_SET_MOD(name)  \
 387   UNUSED static const HPHP::Trace::Module TRACEMOD = HPHP::Trace::name;
 388
 389 /*
 390  * The Indent struct and ITRACE are used for tracing with nested
 391  * indentation. Create an Indent object on the stack to increase the nesting
 392  * level, then use ITRACE just as you would use FTRACE.
 393  */
 394 extern __thread int indentDepth;
 395 struct Indent {
 396   explicit Indent(int n = 2) : n(n) { indentDepth += n; }
 397   ~Indent()                         { indentDepth -= n; }
 398
 399   int n;
 400 };
 401
 402 // See doc comment above for usage.
 403 using Bump = BumpRelease;
 404
 405 inline std::string indent() {
 406   return std::string(indentDepth, ' ');
 407 }
 408
 409 template<typename... Args>
 410 inline void itraceImpl(const char* fmtRaw, Args&&... args) {
 411   auto const fmt = indent() + fmtRaw;
 412   Trace::ftraceRelease(fmt, std::forward<Args>(args)...);
 413 }
 414 #define ITRACE(level, ...) ONTRACE((level), Trace::itraceImpl(__VA_ARGS__));
 415 #define ITRACE_MOD(mod, level, ...)                             \
 416   ONTRACE_MOD(mod, level, Trace::itraceImpl(__VA_ARGS__));
 417
 418 void trace(ATTRIBUTE_PRINTF_STRING const char *, ...) ATTRIBUTE_PRINTF(1,2);
 419 void trace(const std::string&);
 420
 421 template<typename Pretty>
 422 inline void trace(Pretty p) { trace(p.pretty() + std::string("\n")); }
 423
 424 void vtrace(ATTRIBUTE_PRINTF_STRING const char *fmt, va_list args)
 425   ATTRIBUTE_PRINTF(1,0);
 426 void dumpRingbuffer();
 427
 428 // Ensure a tracing output file has been opened.
 429 void ensureInit(std::string outFile);
 430 // Set tracing levels for this thread using a module:level,... specification.
 431 // If traceSpec is empty, all levels for this thread are zeroed.
 432 void setTraceThread(folly::StringPiece traceSpec);
 433
 434 //////////////////////////////////////////////////////////////////////
 435
 436 #else /* } (!defined(NDEBUG) || defined(USE_TRACE)) { */
 437
 438 //////////////////////////////////////////////////////////////////////
 439 /*
 440  * Implementation for when tracing is disabled.
 441  */
 442
 443 #define ONTRACE(...)      do { } while (0)
 444 #define TRACE(...)        do { } while (0)
 445 #define FTRACE(...)       do { } while (0)
 446 #define ONTRACE_MOD(...)  do { } while (0)
 447 #define TRACE_MOD(...)    do { } while (0)
 448 #define FTRACE_MOD(...)   do { } while (0)
 449 #define TRACE_SET_MOD(name) \
 450   DEBUG_ONLY static const HPHP::Trace::Module TRACEMOD = HPHP::Trace::name;
 451
 452 #define ITRACE(...)     do { } while (0)
 453 #define ITRACE_MOD(...) do { } while (0)
 454 struct Indent {
 455   Indent() {
 456     always_assert(true && "If this struct is completely empty we get unused "
 457                           "variable warnings in code that uses it.");
 458   }
 459 };
 460 inline std::string indent() {
 461   return std::string();
 462 }
 463
 464 struct Bump {
 465   Bump(Module /*mod*/, int /*adjust*/, bool /*condition*/ = true) {
 466     always_assert(true && "If this struct is completely empty we get unused "
 467                           "variable warnings in code that uses it.");
 468   }
 469 };
 470
 471 const bool enabled = false;
 472
 473 inline void trace(const char*, ...) {}
 474 inline void trace(const std::string&) {}
 475 inline void vtrace(const char*, va_list) {}
 476 inline bool moduleEnabled(Module /*t*/, int /*level*/ = 1) {
 477   return false;
 478 }
 479 inline int moduleLevel(Module /*tm*/) {
 480   return 0;
 481 }
 482 inline void ensureInit(std::string /*outFile*/) {}
 483 inline void setTraceThread(const std::string& /*traceSpec*/) {}
 484
 485 //////////////////////////////////////////////////////////////////////
 486
 487 #endif /* } (!defined(NDEBUG) || defined(USE_TRACE)) */
 488
 489 } // Trace
 490
 491 // Optional color utility for trace dumps; when output is a tty or
 492 // when we've been told to assume it is.
 493 inline const char* color(const char* color) {
 494   static auto const shouldColorize = []() -> bool {
 495     auto const traceEnv  = getenv("HPHP_TRACE_FILE");
 496     auto const assumeTTY = getenv("HPHP_TRACE_TTY");
 497     if (assumeTTY) return true;
 498     if (!traceEnv) return false;
 499     return
 500       !strcmp(traceEnv, "/dev/stdout") ? isatty(1) :
 501       !strcmp(traceEnv, "/dev/stderr") ? isatty(2) :
 502       false;
 503   }();
 504   return shouldColorize ? color : "";
 505 }
 506
 507 inline std::string color(const char* fg, const char* bg) {
 508   auto const s = add_bgcolor(fg, bg);
 509   return color(s.c_str());
 510 }
 511
 512 //////////////////////////////////////////////////////////////////////
 513
 514 FOLLY_CREATE_MEMBER_INVOKER(invoke_toString, toString);
 515
 516 } // HPHP
 517
 518 namespace folly {
 519 template<typename Val>
 520 class FormatValue<Val,
 521                    std::enable_if_t<
 522                      std::is_invocable_v<HPHP::invoke_toString, Val const> &&
 523                      // This is here because MSVC decides that StringPiece matches
 524                      // both this overload as well as the FormatValue overload for
 525                      // string-y types in folly itself.
 526                      !std::is_same<Val, StringPiece>::value
 527                    >> {
 528  public:
 529   explicit FormatValue(const Val& val) : m_val(val) {}
 530
 531   template<typename Callback> void format(FormatArg& arg, Callback& cb) const {
 532     format_value::formatString(m_val.toString(), arg, cb);
 533   }
 534
 535  private:
 536   const Val& m_val;
 537 };
 538 }