Debugging PHP with DTrace, part 2

Your next step in observing PHP with DTrace could easily be the following script. It times how much time (in nanoseconds) each Apache process has spent running a particular PHP function.

This script generates a table of Apache PIDs and PHP scripts started within, and later you’ll get a table of all the functions with PIDs which ran them and the time spent.

You can download this script here: php-scripts-timer.d

#!/usr/sbin/dtrace -s
#pragma D option quiet
BEGIN
{
printf("php scripts timer startedn");
}
:dtrace.so::function-entry
/ copyinstr(arg0) == "" && name[pid,copyinstr(arg1)] != 1 /
{
printf("%d -> %-30sn", pid, copyinstr(arg1));
name[pid,copyinstr(arg1)] = 1;
}
:dtrace.so::function-entry
/ copyinstr(arg0) != "" /
{
self->ts = timestamp;
}
:dtrace.so::function-return
/ copyinstr(arg0) != "" /
{
self->elapsed = timestamp - self->ts;
@time[pid, copyinstr(arg0)] = sum(self->elapsed);
}
END
{
printf("<------ php scripts timer finished");
printf("n%10s %40s %14sn", "PID", "PHP function", "Time elapsed");
printa("%10d %40s %14@un", @time);
}

A typical result of running this script while opening some PHP pages served by your Apache will look like this:

php scripts timer started
223074 -> /export/www/nightly/pma/left.php
223071 -> /export/www/nightly/pma/main.php
223074 -> /export/www/nightly/pma/css/phpmyadmin.css.php
223071 -> /export/www/nightly/pma/css/phpmyadmin.css.php
<------ php scripts timer finished
PID                             PHP function   Time elapsed
223074                             ob_get_level          22280
223074                              get_cfg_var          32678