Generating an execution trace for a PHP script with Dtrace

Here is a small Dtrace script I used to generate the execution trace of a PHP script running in a terminal : (executiontrace.d)

#! /usr/bin/dtrace -s
#pragma D option quiet
#pragma D option switchrate=10

BEGIN
{
    printf("TRACE START [%Y]\n", walltimestamp);
    self->depth      = 0;
    self->time_last  = 0;
}

/**
 * program begins, so {main}
 */
php*:::function-entry
/copyinstr(arg0) == ""/
{
    printf(
        "%d\t -> {main}() %s:%d\n",
        /* well, just zero :-) */
        0,
        /* source file, you can use basename(copyinstr(arg1)) if needed */
        copyinstr(arg1),
        /* line number*/
        arg2
    );

    self->time_last = timestamp;
}

/**
 * start any other function that is not {main}
 */
php*:::function-entry
/copyinstr(arg0) != ""/
{
    self->depth += 2;

    printf(
        /* string format */
        "%d\t %*s %s%s%s() %s:%d\n",
        /* time delta (microseconds)*/
        (timestamp - self->time_last) / 1000,
        /* indentation   */
        self->depth, "->",
        /* class name, if available */
        copyinstr(arg3),
        /* scope operator, if available */
        copyinstr(arg4),
        /* function name, always available */
        copyinstr(arg0),
        /* source file, you can use basename(copyinstr(arg1)) if needed */
        copyinstr(arg1),
        /* line number*/
        arg2
    );

    self->time_last = timestamp;
}

/**
 * end of any other function that is not {main}
 */
php*:::function-return
/copyinstr(arg0) != ""/
{
    self->depth -= 2;
}

END
{
    self->depth = 0;
    printf("TRACE END [%Y]", walltimestamp);
}

It looks like an Xdebug trace (without the memory usage / delta) but since Dtrace and Xdebug do not operate at the same level the results are quite different. If you want to test this script you can use for example the following (nestedfunctions.php) :

<?php
function parent()
{
 new DirectoryIterator( __DIR__ );
 child();
}
function child()
{
 sleep( 1 );
}
function launch()
{
 parent( );
}
function foo(){}
launch(  );
foo();
sleep( 2 );
foo();
launch();
foo();
?>

And by running the following command :

sudo dtrace -s executiontrace.d -c "php nestedfunctions.php"

You should get a result like this (do not forget to hit <Ctrl-c> in order to exit from Dtrace).

TRACE START [2010 Aug 12 10:44:27]
0     -> {main}() [...]/testnestedfunctions.php:0
669     -> launch() [...]/testnestedfunctions.php:21
24       -> parent() [...]/testnestedfunctions.php:16
37         -> DirectoryIterator::__construct() [...]/testnestedfunctions.php:5
286         -> child() [...]/testnestedfunctions.php:6
21           -> sleep() [...]/testnestedfunctions.php:11
1000158     -> foo() [...]/testnestedfunctions.php:22
32     -> sleep() [...]/testnestedfunctions.php:23
2000097     -> foo() [...]/testnestedfunctions.php:24
32     -> launch() [...]/testnestedfunctions.php:25
21       -> parent() [...]/testnestedfunctions.php:16
32         -> DirectoryIterator::__construct() [...]/testnestedfunctions.php:5
141         -> child() [...]/testnestedfunctions.php:6
20           -> sleep() [...]/testnestedfunctions.php:11
1000111     -> foo() [...]/testnestedfunctions.php:26
^C
TRACE END [2010 Aug 12 10:44:34]

I tried to add as much comments as possible in order to make the script clearer. Please note that if you run this script on production you will get a lot of output because the script does not filter on any pid so Dtrace will aggregate results across multilple Apache processes. It is up to you to use the correct predicate to filter on the PID you want in order to limit the result set.

Comments !

blogroll

social