gistfile1.md

Profiler

This is a simple PHP profiler based on syslog and ticks.

Killer feature is that it doesn't need to be included inside statements but only prepend your scripts.

Usage

The script is a standalone file, so you only have to include it.

<?php
require_once 'profiler.php';
declare(ticks=1);

// your code here
?>

Example

<?php

require_once 'profiler.php';
declare(ticks=1);

// production code

$foo = new foo;

f1();
f3();

function f1() {
    usleep(5000);
    f2();
}

function f2() {
    usleep(50000);
    f3();
}

function f3() {
    usleep(50000);
    f4();
}

function f4() {
    global $foo;
    usleep(50000);

    foo::bar();

    $t = function () {
        usleep(5000);
    };
    $t();

    $foo->bar2();
}


class foo {
    static function bar() {
        usleep(1000);
    }
    function bar2() {
        usleep(1000);
    }
}

?>

Output

Output tokens are:

[process id][datetime] total calls in stack (hypens) statement : memory used : time used

* ubuntu apache2: [678][1970-01-01 00:00:00.05076] === profiler ===
* ubuntu apache2: [678][1970-01-01 00:00:00.05620] f1 : 235616 : 0.007133960723877
* ubuntu apache2: [678][1970-01-01 00:00:00.10653] - f2 : 236880 : 0.050199031829834
* ubuntu apache2: [678][1970-01-01 00:00:00.15692] -- f3 : 238136 : 0.050237894058228
* ubuntu apache2: [678][1970-01-01 00:00:00.15715] --- f4 : 239416 : 6.5088272094727E-5
* ubuntu apache2: [678][1970-01-01 00:00:00.20754] --- f4 : 239416 : 0.050306081771851
* ubuntu apache2: [678][1970-01-01 00:00:00.20888] ---- foo::bar : 241120 : 0.0011959075927734
* ubuntu apache2: [678][1970-01-01 00:00:00.20904] --- f4 : 239600 : 0.050353050231934
* ubuntu apache2: [678][1970-01-01 00:00:00.20921] --- f4 : 239952 : 0.050410270690918
* ubuntu apache2: [678][1970-01-01 00:00:00.21457] ---- {closure} : 241224 : 0.0052261352539062
* ubuntu apache2: [678][1970-01-01 00:00:00.21475] --- f4 : 240136 : 0.050458192825317
* ubuntu apache2: [678][1970-01-01 00:00:00.21606] ---- foo->bar2 : 241984 : 0.0011999607086182
* ubuntu apache2: [678][1970-01-01 00:00:00.21624] --- f4 : 240320 : 0.050514221191406
* ubuntu apache2: [678][1970-01-01 00:00:00.21640] -- f3 : 238856 : 0.050291776657104
* ubuntu apache2: [678][1970-01-01 00:00:00.21656] - f2 : 237776 : 0.050248861312866
* ubuntu apache2: [678][1970-01-01 00:00:00.21671] f1 : 236688 : 0.00718092918396
* ubuntu apache2: [678][1970-01-01 00:00:00.26707] f3 : 236688 : 0.10052275657654
* ubuntu apache2: [678][1970-01-01 00:00:00.26724] - f4 : 237776 : 0.050561189651489
* ubuntu apache2: [678][1970-01-01 00:00:00.31756] - f4 : 237776 : 0.10074710845947
* ubuntu apache2: [678][1970-01-01 00:00:00.31893] -- foo::bar : 239296 : 0.0023877620697021
* ubuntu apache2: [678][1970-01-01 00:00:00.31910] - f4 : 237776 : 0.10079216957092
* ubuntu apache2: [678][1970-01-01 00:00:00.31927] - f4 : 238128 : 0.1008460521698
* ubuntu apache2: [678][1970-01-01 00:00:00.32459] -- {closure} : 239248 : 0.010415315628052
* ubuntu apache2: [678][1970-01-01 00:00:00.32477] - f4 : 238160 : 0.10089206695557
* ubuntu apache2: [678][1970-01-01 00:00:00.32610] -- foo->bar2 : 239824 : 0.0024130344390869
* ubuntu apache2: [678][1970-01-01 00:00:00.32629] - f4 : 238160 : 0.10094213485718
* ubuntu apache2: [678][1970-01-01 00:00:00.32643] f3 : 236688 : 0.10056781768799
$ clear && tail -n 27 /var/log/syslog

profiler.php

<?php

register_tick_function(function () {
    /**
     * Used for the timer.
     * @var float
     */
    static $last = null;
    /**
     * Used to store profiles.
     * @var array
     */
    static $profile = array();

    if (is_null($last)) {
        // start time isn't at invoke but when
        // the server received request
        $last = $_SERVER['REQUEST_TIME_FLOAT'];
        // used to divide instances
        // process id is used to prevent instances mix due to requests flood
        syslog(LOG_DEBUG, '[' . getmypid() . '][' . date('Y-m-d H:i:s', $last)
            . substr((string) microtime(), 1, 6) . '] === profiler ==='
        );
    }
    /**
     * This variable contains main informations about last calls.
     * @var array
     */
    $backtrace = debug_backtrace();
    // if there are only 2 elements we aren't in a user defined code
    if (count($backtrace) <= 1) {
        return;
    }

    /**
     * This variable contains current function definition attributes like name,
     * class, type, file, line and args.
     * @var string
     */
    $function = $backtrace[1];
    $function = isset($function['class'])
            ? $function['class'] . $function['type'] . $function['function']
            : $function['function'];

    if (isset($backtrace[2])) {
        /**
         * This variable contains informations about parent (user defined)
         * code that invoked current statement.
         * @var string
         */
        $parent = $backtrace[2];
        $parent = isset($parent['class'])
            ? $parent['class'] . $parent['type'] . $parent['function']
            : $parent['function'];
    }

    /**
     * This variable contains microtimes.
     * Used to render time differences.
     * @var array
     */
    $profile[$function] = isset($profile[$function])
        ? microtime(true) - $last + $profile[$function]
        : microtime(true) - $last;
    // output times in the right place
    // syntax: [{process id}][{datetime}] {position in stack (hypens)} {function} : {memory} : {seconds}
    syslog(LOG_DEBUG, '[' . getmypid() . '][' . date('Y-m-d H:i:s')
        . substr((string) microtime(), 1, 6) . '] '
        . (count($backtrace) - 2 ? str_repeat('-', count($backtrace) - 2) . ' ' : null) . $function 
        . ' : ' . memory_get_usage()
        . ' : ' . $profile[$function]
    );
    /**
     * Used to profile next request.
     * @var float
     */
    $last = microtime(true);
});