Skip to content

Instantly share code, notes, and snippets.

Embed
What would you like to do?

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
<?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);
});
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment