Tracing Silex from PHP to the OS with DTrace
- by cj
In this blog post I show the full stack tracing of Brendan Gregg's
php_syscolors.d script in the DTrace
Toolkit. The Toolkit contains a dozen very useful PHP DTrace
scripts and many more scripts for other languages and the OS.
For this example, I'll trace the PHP micro framework Silex, which was the topic of
the second of two talks by Dustin Whittle at a recent SF PHP Meetup. His slides are at Silex: From Micro to Full Stack.
Installing DTrace and PHP
The php_syscolors.d script uses some static PHP probes
and some kernel probes. For Oracle Linux I discussed installing
DTrace and PHP in DTrace PHP Using Oracle Linux 'playground' Pre-Built Packages.
On other platforms with DTrace support, follow your standard
procedures to enable DTrace and load the correct providers. The
sdt and systrace providers are required in
addition to fasttrap.
On Oracle Linux, I loaded the DTrace modules like:
# modprobe fasttrap
# modprobe sdt
# modprobe systrace
# chmod 666 /dev/dtrace/helper
Installing the DTrace Toolkit
I download DTraceToolkit-0.99.tar.gz and extracted it:
$ tar -zxf DTraceToolkit-0.99.tar.gz
The PHP scripts are in the Php directory and examples in the Examples directory.
Installing Silex
I downloaded the "fat" Silex .tgz file from the download page and extracted it:
$ tar -zxf silex_fat.tgz
I changed the demonstration silex/web/index.php so I
could use the PHP development web server:
<?php
// web/index.php
$filename = __DIR__.preg_replace('#(\?.*)$#', '', $_SERVER['REQUEST_URI']);
if (php_sapi_name() === 'cli-server' && is_file($filename)) {
return false;
}
require_once __DIR__.'/../vendor/autoload.php';
$app = new Silex\Application();
//$app['debug'] = true;
$app->get('/hello', function() {
return 'Hello!';
});
$app->run();
?>
Running DTrace
The php_syscolors.d script uses the -Z
option to dtrace, so it can be started before PHP,
i.e. when there are zero of the requested probes available to be
traced. I ran DTrace like:
# cd DTraceToolkit-0.99/Php
# ./php_syscolors.d
Next, I started the PHP developer web server in a second
terminal:
$ cd silex
$ php -S localhost:8080 -t web web/index.php
At this point, the web server is idle, waiting for requests.
DTrace is idle, waiting for the probes in php_syscolors.d
to be fired, at which time the action associated with each probe will
run.
I then loaded the demonstration page in a browser:
http://localhost:8080/hello
When the request was fulfilled and the simple output of "Hello" was
displayed, I ^C'd php and dtrace in
their terminals to stop them.
DTrace output over a thousand lines long had been generated. Here
is one snippet from when run() was invoked:
C PID/TID DELTA(us) FILE:LINE TYPE -- NAME
...
1 4765/4765 21 Application.php:487 func -> run
1 4765/4765 29 ClassLoader.php:182 func -> loadClass
1 4765/4765 17 ClassLoader.php:198 func -> findFile
1 4765/4765 31 ":- syscall -> access
1 4765/4765 26 ":- syscall <- access
1 4765/4765 16 ClassLoader.php:198 func <- findFile
1 4765/4765 25 ":- syscall -> newlstat
1 4765/4765 15 ":- syscall <- newlstat
1 4765/4765 13 ":- syscall -> newlstat
1 4765/4765 13 ":- syscall <- newlstat
1 4765/4765 22 ":- syscall -> newlstat
1 4765/4765 14 ":- syscall <- newlstat
1 4765/4765 15 ":- syscall -> newlstat
1 4765/4765 60 ":- syscall <- newlstat
1 4765/4765 13 ":- syscall -> newlstat
1 4765/4765 13 ":- syscall <- newlstat
1 4765/4765 20 ":- syscall -> open
1 4765/4765 16 ":- syscall <- open
1 4765/4765 26 ":- syscall -> newfstat
1 4765/4765 12 ":- syscall <- newfstat
1 4765/4765 17 ":- syscall -> newfstat
1 4765/4765 12 ":- syscall <- newfstat
1 4765/4765 12 ":- syscall -> newfstat
1 4765/4765 12 ":- syscall <- newfstat
1 4765/4765 20 ":- syscall -> mmap
1 4765/4765 14 ":- syscall <- mmap
1 4765/4765 3201 ":- syscall -> mmap
1 4765/4765 27 ":- syscall <- mmap
1 4765/4765 1233 ":- syscall -> munmap
1 4765/4765 53 ":- syscall <- munmap
1 4765/4765 15 ":- syscall -> close
1 4765/4765 13 ":- syscall <- close
1 4765/4765 34 Request.php:32 func -> main
1 4765/4765 22 Request.php:32 func <- main
1 4765/4765 31 ClassLoader.php:182 func <- loadClass
1 4765/4765 33 Request.php:249 func -> createFromGlobals
1 4765/4765 29 Request.php:198 func -> __construct
1 4765/4765 24 Request.php:218 func -> initialize
1 4765/4765 26 ClassLoader.php:182 func -> loadClass
1 4765/4765 89 ClassLoader.php:198 func -> findFile
1 4765/4765 43 ":- syscall -> access
...
The output shows PHP functions being called and returning (and
where they are located) and which system calls the PHP functions in
turn invoked. The time each line took from the previous one is
displayed in the third column.
The first column is the CPU number. In this example, the process
was always on CPU 1 so the output is naturally ordered without
requiring post-processing, or the D script requiring to be modified to
display a time stamp.
On a terminal, the output of php_syscolors.d is
color-coded according to whether each function is a PHP or system one,
hence the file name.
Summary
With one tool, I was able to trace the interaction of a user
application with the operating system. I was able to do this to an
application running "live" in a web context.
The DTrace Toolkit provides a very handy repository of DTrace
information. Even though the PHP scripts were created in the
time frame of the original PHP DTrace PECL extension, which only had
PHP function entry and return probes, the scripts provide core
examples for custom investigation and resolution scripts. You can
easily adapt the ideas and and create scripts using the other PHP
static probes, which are listed in the PHP
Manual.
Because DTrace is "always on", you can take advantage of it to
resolve development questions or fix production situations.
