Debugging PHP with DTrace, part 2

May 2, 2009 · Filed Under General Solaris topics 

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

Tags: ,

Comments

Leave a Reply