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'm a Product Manager in Server Technologies, working on scripting languages and developer-access.
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