X

The leading edge of scripting languages and Oracle Database brought to you by the Data Access Development team

  • php |
    November 6, 2013

Tracing Silex from PHP to the OS with DTrace

Christopher Jones
Senior Principal Product Manager

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 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.

Be the first to comment

Comments ( 0 )
Please enter your name.Please provide a valid email address.Please enter a comment.CAPTCHA challenge response provided was incorrect. Please try again.Captcha
Oracle

Integrated Cloud Applications & Platform Services