hphp/doc/profiling.md

   1 Profiling PHP Code
   2 ==================
   3
   4 ## Quick Start ##
   5
   6 1. Make sure the `Stats.EnableHotProfiler` config option is on (it's on by
   7    default).
   8
   9 2. Profile code like this:
  10
  11    ```php
  12    xhprof_enable();
  13
  14    /* code to be profiled */
  15
  16    $stats = xhprof_disable();
  17    ```
  18
  19    How to interpret the contents of `$stats` is explained in detail below.
  20
  21
  22 ## PHP Interface ##
  23
  24 HHVM supports the whole Xhprof interface, as described
  25 [on php.net](http://php.net/manual/en/book.xhprof.php).
  26
  27 Note that regardless of whether `XHPROF_FLAGS_NO_BUILTINS` is on, builtins will
  28 not be profiled if the config option `Eval.JitEnableRenameFunction` is off. That
  29 config option enables an optimization that bypasses normal profiler hooks when
  30 calling builtins.
  31
  32 HHVM defines a few additional constants that can be passed to `xhprof_enable()`
  33 to customize the profiler's behavior:
  34
  35 * `XHPROF_FLAGS_VTSC`: Like `XHPROF_FLAGS_CPU`, this flag adds CPU-time
  36   profiling to the output. The difference is that if our preferred
  37   high-resolution clock is not available -- in HHVM's case,
  38   `clock_gettime(CLOCK_THREAD_CPUTIME_ID)` -- CPU-time profiling will not be
  39   produced. By contrast, `XHPROF_FLAGS_CPU` will fall back to `getrusage` if
  40   `clock_gettime` is unavailable.
  41
  42 * `XHPROF_FLAGS_TRACE`: Use a different profiler implementation, based on
  43   collecting small snapshots at function entry and exit, and only processing
  44   them when profiling ends. This lowers profiling overhead, but can consume
  45   large amounts of memory. Only one thread is allowed to profile in this mode at
  46   once, unless `XHPROF_FLAGS_I_HAVE_INFINITE_MEMORY` is set. The memory consumed
  47   is accounted for in the output, as "(trace buffer alloc)" and "(trace buffer
  48   realloc)".
  49
  50 * `XHPROF_FLAGS_MEASURE_XHPROF_DISABLE`: Only used when `XHPROF_FLAGS_TRACE` is
  51   enabled. Measures and outputs the overhead of processing collected traces in
  52   `xhprof_disable()`.
  53
  54 * `XHPROF_FLAGS_MALLOC`: Gives memory stats directly from the malloc API. These
  55   stats are only available if the malloc implementation in use is jemalloc or
  56   tcmalloc. It is incompatible with `XHPROF_FLAGS_MEMORY` and is overridden by
  57   that flag.
  58
  59 * `XHPROF_FLAGS_I_HAVE_INFINITE_MEMORY`: Allows one TRACE profiler per thread,
  60   instead of restricting to one per process. The vast majority of users will not
  61   need this.
  62
  63
  64 ### Interpreting the output ###
  65
  66 The array returned from `xhprof_disable()` contains one entry per call edge;
  67 that is, per pair of functions where the first calls the second. The keys look
  68 like `"one==>two"`, which signifies that the function `one` called the function
  69 `two`. The function `main()` represents the top-level entry point of the script.
  70 Recursive calls will look like `one@2==>one@3`, where the number represents how
  71 many levels deep the recursion is.
  72
  73 Each entry is an array, with some of the following keys:
  74
  75 * `ct`: Count. The number of times this edge was observed.
  76
  77 * `wt`: Inclusive wall time in the callee, in microseconds. In HHVM, this is
  78   collected by using the `rdtsc` (read timestamp counter) instruction on x86_64
  79   machines. It is meaningless on other hardware. HHVM tries to bind threads
  80   running profilers to specific CPU cores, to make sure this number will be
  81   reliable.
  82
  83 * `cpu`: Inclusive CPU time in the callee, in microseconds. In HHVM, this is
  84   collected using `clock_gettime(CLOCK_THREAD_CPUTIME_ID)` if available (which
  85   it is in modern Linux kernels).
  86
  87 * `mu`: Delta of memory usage from start to end of the callee, in bytes. This
  88   comes from the same memory accounting as the output of
  89   `memory_get_usage(true)`.
  90
  91 * `pmu`: Delta of peak memory usage from start to end of the callee, in bytes.
  92   This comes from the same memory accounting as the output of
  93   `memory_get_peak_usage(true)`. Should never be negative.
  94
  95 * `alloc`: Delta of cumulative amount of memory requested from malloc() by the
  96   callee, in bytes. Only given if `XHPROF_FLAGS_MALLOC` is on. Should never be
  97   negative.
  98
  99 * `free`: Delta of cumulative amount of memory passed to free() by the callee,
 100   in bytes. Only given if `XHPROF_FLAGS_MALLOC` is on. Should never be negative.
 101
 102
 103 Remember that for short time intervals, different sources of timing can give
 104 inconsistent results, such as CPU time being greater than wall time (which is
 105 impossible in theory). Interpreting timing data correctly requires knowing the
 106 drawbacks of each timing source.
 107
 108
 109 ### Interpreting the output of the sampling profiler ###
 110
 111 The output of the sampling profiler is different. Instead of one entry per call
 112 edge, there will be one entry per sample. A sample is taken every 100
 113 milliseconds, during which a stack trace is captured.
 114
 115 The array returned from `xhprof_sample_disable()` will have sample timestamps as
 116 keys and strings representing stack traces as values.