WARNING: This project is not maintained anymore and does not work on PHP 7+. If you are looking for a PHP profiler, you can have a look at https://blackfire.io/ (the free version has more features and a better UI than the ones provided by this project).

uprofiler

Introduction

uprofiler is a hierarchical profiler for PHP. It reports function-level call counts and inclusive and exclusive metrics such as wall (elapsed) time, CPU time and memory usage. A function's profile can be broken down by callers or callees. The raw data collection component is implemented in C as a PHP Zend extension called uprofiler. uprofiler has a simple HTML based user interface (written in PHP). The browser based UI for viewing profiler results makes it easy to view results or to share results with peers. A callgraph image view is also supported.

uprofiler reports can often be helpful in understanding the structure of the code being executed. The hierarchical nature of the reports can be used to determine, for example, what chain of calls led to a particular function getting called.

uprofiler supports ability to compare two runs (a.k.a. "diff" reports) or aggregate data from multiple runs. Diff and aggregate reports, much like single run reports, offer "flat" as well as "hierarchical" views of the profile.

uprofiler is a light-weight instrumentation based profiler. During the data collection phase, it keeps track of call counts and inclusive metrics for arcs in the dynamic callgraph of a program. It computes exclusive metrics in the reporting/post processing phase. uprofiler handles recursive functions by detecting cycles in the callgraph at data collection time itself and avoiding the cycles by giving unique depth qualified names for the recursive invocations.

uprofiler's light-weight nature and aggregation capabilities make it well suited for collecting "function-level" performance statistics from production environments.

Originally developed at Facebook, uprofiler was open sourced in Mar, 2009.

uprofiler Overview

uprofiler provides:

• Flat profile

  Function-level summary information such as number of calls, inclusive/exclusive wall time, memory usage, and CPU time.

  .. image:: http://get.uprofiler.io/sample-flat-view.jpg

• Hierarchical profile (Parent/Child View)

  For each function, it provides a breakdown of calls and times per parent (caller) & child (callee), such as:

  • what functions call a particular function and how many times?
  • what functions does a particular function call?
  • the total time spent under a function when called from a particular parent.

  .. image:: http://get.uprofiler.io/sample-parent-child-view.jpg

• Diff Reports

  You may want to compare data from two uprofiler runs for various reasons-- to figure out what's causing a regression between one version of the code base to another, to evaluate the performance improvement of a code change you are making, and so on.

  A diff report takes two runs as input and provides both flat function-level diff information, and hierarchical information (breakdown of diff by parent/children functions) for each function.

  The "flat" view in the diff report points out the top regressions & improvements.

  .. image:: http://get.uprofiler.io/sample-diff-report-flat-view.jpg

  Clicking on functions in the "flat" view of the diff report, leads to the "hierarchical" (or parent/child) diff view of a function. We can get a breakdown of the diff by parent/children functions.

  .. image:: http://get.uprofiler.io/sample-diff-report-parent-child-view.jpg

• Callgraph View

  The profile data can also be viewed as a callgraph. The callgraph view highlights the critical path of the program.

  .. image:: http://get.uprofiler.io/sample-callgraph-image.jpg

• Memory Profile

  uprofiler's memory profile mode helps track functions that allocate lots of memory.

  It is worth clarifying that that uprofiler doesn't strictly track each allocation/free operation. Rather it uses a more simplistic scheme. It tracks the increase/decrease in the amount of memory allocated to PHP between each function's entry and exit. It also tracks increase/decrease in the amount of peak memory allocated to PHP for each function.

• uprofiler tracks include, include_once, require and require_once operations as if they were functions. The name of the file being included is used to generate the name for these "fake" functions (see below).

Terminology

• Inclusive Time (or Subtree Time): Includes time spent in the function as well as in descendant functions called from a given function.

• Exclusive Time/Self Time: Measures time spent in the function itself. Does not include time in descendant functions.

• Wall Time: a.k.a. Elapsed time or wall clock time.

• CPU Time: CPU time in user space + CPU time in kernel space.

Naming convention for special functions

• main(): a fictitious function that is at the root of the call graph.

• load::<filename> and run_init::<filename>:

  uprofiler tracks PHP include/require operations as function calls.

  For example, an include "lib/common.php"; operation will result in two uprofiler function entries:

  • load::lib/common.php: This represents the work done by the interpreter to compile/load the file. [Note: If you are using a PHP opcode cache like APC, then the compile only happens on a cache miss in APC.]

  • run_init::lib/common.php: This represents initialization code executed at the file scope as a result of the include operation.

• foo@<n>: Implies that this is a recursive invocation of foo(), where <> represents the recursion depth. The recursion may be direct (such as due to foo() --> foo()), or indirect (such as due to foo() --> goo() --> foo()).

Limitations

True hierarchical profilers keep track of a full call stack at every data gathering point, and are later able to answer questions like: what was the cost of the 3rd invokation of foo()? or what was the cost of bar() when the call stack looked like a()->b()->bar()?

uprofiler keeps track of only 1-level of calling context and is therefore only able to answer questions about a function looking either 1-level up or 1-level down. It turns out that in practice this is sufficient for most use cases.

To make this more concrete, take for instance the following example. Say you have:

.. code-block:: text

1 call from a() --> c() 1 call from b() --> c() 50 calls from c() --> d()

While uprofiler can tell you that d() was called from c() 50 times, it cannot tell you how many of those calls were triggered due to a() vs. b(). [We could speculate that perhaps 25 were due to a() and 25 due to b(), but that's not necessarily true.]

In practice however, this isn't a very big limitation.

Installing the uprofiler Extension

The extension lives in the "extension/" sub-directory.

.. note::

A windows port hasn't been implemented yet. We have tested uprofiler on Linux/FreeBSD and on Mac OS so far.

.. note::

uprofiler uses the RDTSC instruction (time stamp counter) to implement a really low overhead timer for elapsed time. So at the moment uprofiler only works on x86 architecture. Also, since RDTSC values may not be synchronized across CPUs, uprofiler binds the program to a single CPU during the profiling period.

uprofiler's RDTSC based timer functionality doesn't work correctly if SpeedStep technology is turned on. This technology is available on some Intel processors. [Note: Mac desktops and laptops typically have SpeedStep turned on by default. To use uprofiler, you'll need to disable SpeedStep.]

The steps below should work for Linux/Unix environments:

.. code-block:: bash

$ cd extension/ $ phpize $ ./configure --with-php-config=path-to-php-config $ make $ make install

php.ini file: You can update your php.ini file to automatically load your extension. Add the following to your php.ini file:

.. code-block:: ini

[uprofiler]
extension=uprofiler.so
;
; directory used by default implementation of the iuprofilerRuns
; interface (namely, the uprofilerRuns_Default class) for storing
; uprofiler runs.
;
uprofiler.output_dir=<directory_for_storing_uprofiler_runs>

Profiling using uprofiler

Test generating raw profiler data using a sample test program like:

.. code-block:: php

<?php

// foo.php

function bar($x) {
  if ($x > 0) {
    bar($x - 1);
  }
}

function foo() {
  for ($idx = 0; $idx < 2; $idx++) {
    bar($idx);
    $x = strlen("abc");
  }
}

// start profiling
uprofiler_enable();

// run program
foo();

// stop profiler
$uprofiler_data = uprofiler_disable();

// display raw uprofiler data for the profiler run
print_r($uprofiler_data);

Run the above test program:

.. code-block:: php

$ php -dextension=uprofiler.so foo.php

You should get an output like:

.. code-block:: text

Array
(
    [foo==>bar] => Array
        (
            [ct] => 2         # 2 calls to bar() from foo()
            [wt] => 27        # inclusive time in bar() when called from foo()
        )

    [foo==>strlen] => Array
        (
            [ct] => 2
            [wt] => 2
        )

    [bar==>bar@1] => Array    # a recursive call to bar()
        (
            [ct] => 1
            [wt] => 2
        )

    [main()==>foo] => Array
        (
            [ct] => 1
            [wt] => 74
        )

    [main()==>uprofiler_disable] => Array
        (
            [ct] =>