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 stype 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 \
 /home/cjones/Desktop/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!