Tuesday Nov 05, 2013

Tracing Silex from PHP to the OS with DTrace

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.

Friday Nov 01, 2013

DTracing a PHPUnit Test: Looking at Functional Programming

Here's a quick example of using DTrace Dynamic Tracing to work out what a PHP code base does.

I was reading the article Functional Programming in PHP by Patkos Csaba and wondering how efficient this type of programming is. I thought this would be a good time to fire up DTrace and see what is going on. Since DTrace is "always available" even in production machines (once PHP is compiled with --enable-dtrace), this was easy to do.

I have Oracle Linux with the UEK3 kernel and PHP 5.5 with DTrace static probes enabled, as described in DTrace PHP Using Oracle Linux 'playground' Pre-Built Packages

I installed the Functional Programming sample code and Sebastian Bergmann's PHPUnit. Although PHPUnit is included in the Functional Programming example, I found it easier to separately download and use its phar file:

cd ~/Desktop
wget -O master.zip \
  https://github.com/tutsplus/functional-programming-in-php/archive/master.zip
wget https://phar.phpunit.de/phpunit.phar
unzip master.zip

I created a DTrace D script functree.d:

#pragma D option quiet

self int indent;

BEGIN
{
  topfunc = $1;
}

php$target:::function-entry
/copyinstr(arg0) == topfunc/
{
  self->follow = 1;
}

php$target:::function-entry
/self->follow/
{
  self->indent += 2;
  printf("%*s %s%s%s\n", self->indent, "->", arg3?copyinstr(arg3):"", 
                            arg4?copyinstr(arg4):"", copyinstr(arg0));
}

php$target:::function-return
/self->follow/
{
  printf("%*s %s%s%s\n", self->indent, "<-", arg3?copyinstr(arg3):"", 
                            arg4?copyinstr(arg4):"", copyinstr(arg0));
  self->indent -= 2;
}

php$target:::function-return
/copyinstr(arg0) == topfunc/
{
  self->follow = 0;
}

This prints a PHP script function call tree starting from a given PHP function name. This name is passed as a parameter to DTrace, and assigned to the variable topfunc when the DTrace script starts. With this D script, choose a PHP function that isn't recursive, or modify the script to set self->follow = 0 only when all calls to that function have unwound.

From looking at the sample FunSets.php code and its PHPUnit test driver FunSetsTest.php, I settled on one test function to trace:

function testUnionContainsAllElements() {
  ...
}

I invoked DTrace to trace function calls invoked by this test with

# dtrace -s ./functree.d -c 'php phpunit.phar \
 functional-programming-in-php-master/FunSets/Tests/FunSetsTest.php' \
 '"testUnionContainsAllElements"'

The core of this command is a call to PHP to run PHPUnit on the FunSetsTest.php script. Outside that, DTrace is called and the PID of PHP is passed to the D script $target variable so the probes fire just for this invocation of PHP.

Note the quoting around the PHP function name passed to DTrace. The parameter must have double quotes included so DTrace knows it is a string.

The output is:

PHPUnit 3.7.28 by Sebastian Bergmann.

......-> FunSetsTest::testUnionContainsAllElements
  -> FunSets::singletonSet
  <- FunSets::singletonSet
  -> FunSets::singletonSet
  <- FunSets::singletonSet
  -> FunSets::union
  <- FunSets::union
  -> FunSets::contains
    -> FunSets::{closure}
      -> FunSets::contains
        -> FunSets::{closure}
        <- FunSets::{closure}
      <- FunSets::contains
    <- FunSets::{closure}
  <- FunSets::contains
  -> PHPUnit_Framework_Assert::assertTrue
    -> PHPUnit_Framework_Assert::isTrue
    <- PHPUnit_Framework_Assert::isTrue
    -> PHPUnit_Framework_Assert::assertThat
      -> PHPUnit_Framework_Constraint::count
      <- PHPUnit_Framework_Constraint::count
      -> PHPUnit_Framework_Constraint::evaluate
        -> PHPUnit_Framework_Constraint_IsTrue::matches
        <- PHPUnit_Framework_Constraint_IsTrue::matches
      <- PHPUnit_Framework_Constraint::evaluate
    <- PHPUnit_Framework_Assert::assertThat
  <- PHPUnit_Framework_Assert::assertTrue
  -> FunSets::contains
    -> FunSets::{closure}
      -> FunSets::contains
        -> FunSets::{closure}
        <- FunSets::{closure}
      <- FunSets::contains
      -> FunSets::contains
        -> FunSets::{closure}
        <- FunSets::{closure}
      <- FunSets::contains
    <- FunSets::{closure}
  <- FunSets::contains
  -> PHPUnit_Framework_Assert::assertTrue
    -> PHPUnit_Framework_Assert::isTrue
    <- PHPUnit_Framework_Assert::isTrue
    -> PHPUnit_Framework_Assert::assertThat
      -> PHPUnit_Framework_Constraint::count
      <- PHPUnit_Framework_Constraint::count
      -> PHPUnit_Framework_Constraint::evaluate
        -> PHPUnit_Framework_Constraint_IsTrue::matches
        <- PHPUnit_Framework_Constraint_IsTrue::matches
      <- PHPUnit_Framework_Constraint::evaluate
    <- PHPUnit_Framework_Assert::assertThat
  <- PHPUnit_Framework_Assert::assertTrue
  -> FunSets::contains
    -> FunSets::{closure}
      -> FunSets::contains
        -> FunSets::{closure}
        <- FunSets::{closure}
      <- FunSets::contains
      -> FunSets::contains
        -> FunSets::{closure}
        <- FunSets::{closure}
      <- FunSets::contains
    <- FunSets::{closure}
  <- FunSets::contains
  -> PHPUnit_Framework_Assert::assertFalse
    -> PHPUnit_Framework_Assert::isFalse
      -> {closure}
        -> main
        <- main
      <- {closure}
    <- PHPUnit_Framework_Assert::isFalse
    -> PHPUnit_Framework_Assert::assertThat
      -> PHPUnit_Framework_Constraint::count
      <- PHPUnit_Framework_Constraint::count
      -> PHPUnit_Framework_Constraint::evaluate
        -> PHPUnit_Framework_Constraint_IsFalse::matches
        <- PHPUnit_Framework_Constraint_IsFalse::matches
      <- PHPUnit_Framework_Constraint::evaluate
    <- PHPUnit_Framework_Assert::assertThat
  <- PHPUnit_Framework_Assert::assertFalse
<- FunSetsTest::testUnionContainsAllElements
...

Time: 1.85 seconds, Memory: 3.75Mb
OK (9 tests, 23 assertions)

The periods correspond to the successful tests before and after (and from) the test I was tracing.

You can see the function entry ("->") and return ("<-") points. Cross checking with the testUnionContainsAllElements() source code confirms the two singletonSet() calls, one union() call, two assertTrue() calls and finally an assertFalse() call. These assertions have a contains() call as a parameter, so contains() is called before the PHPUnit assertion functions are run. You can see contains() being called recursively, and how the closures are invoked.

If you want to focus on the application logic and suppress the PHPUnit function trace, you could turn off tracing when assertions are being checked by adding D clauses checking the entry and exit of assertFalse() and assertTrue().

But if you want to see all of PHPUnit's code flow, you can modify the functree.d code that sets and unsets self->follow, and instead change it to toggle the variable in request-startup and request-shutdown probes:

php$target:::request-startup
{
  self->follow = 1
}

php$target:::request-shutdown
{
  self->follow = 0
}

Be prepared for a large amount of output!

About

Tourists looking out over an Opal mine
I work in the Linux Engineering team at Oracle, espousing the Oracle-PHP-Apache-Linux ("OPAL") stack. I also assist with Python, Perl and Ruby.
Email: christopher.jones@oracle.com
Twitter: http://twitter.com/ghrd
Book: Free PHP Oracle book
Download: PHP Linux RPMs with the OCI8 extension
Links: OTN PHP Developer Center

Search

Archives
« November 2013 »
SunMonTueWedThuFriSat
     
2
3
4
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
       
Today