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.