DTracing a PHPUnit Test: Looking at Functional Programming
- by cj
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!
