Tuesday Dec 03, 2013

DTrace and Perl from @GregoryGuillou

Grégory Guillou (@GregoryGuillou) has a post on using DTrace with Perl: Custom DTrace Probes for Perl on Oracle Linux 6. He uses libusdt developed by Chris Andrews (@chrisandrews). Check it out!

Monday Dec 02, 2013

PHP Examples in New "Oracle Linux 6 DTrace Tutorial"

My colleague, Gavin Bowe, has released a new Oracle Linux 6 DTrace Tutorial. It is available in HTML, PDF and ePub from http://docs.oracle.com/cd/E37670_01/index.html.

Chapter 3 on "Tracing User-Space Applications" has some PHP examples.

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!

Wednesday Sep 04, 2013

DTrace with PHP Update

I've recently been working with the in-built DTrace code in PHP 5.4 and PHP 5.5, specifically stabilizing its configuration on Solaris and Oracle Linux.

DTrace is an always-available, low overhead, tracing framework that has just celebrated its 10th Birthday. DTrace support in PHP was originally via a separate PECL extension. In PHP 5.4 David Soria Parra (then at Sun) merged DTrace functionality to core PHP making it more accessible.

At the end of last year, I blogged about Adding DTrace Probes to PHP Extensions and how Linux's SystemTap could be used to trace the DTrace probe points. Since then, Oracle's Linux's DTrace project has been making great strides. The latest Oracle Linux UEK3 Beta kernel was just released. It comes with DTrace 0.4 and also supports "User-Level Statically Defined Tracing" (USDT) for the first time. This motivated me to make sure PHP DTrace worked well with "real" DTrace, not just with SystemTap's wrappers.

Some of the recent PHP DTrace changes were:

  • DTrace build script changes from PHP 5.5 were merged back to PHP 5.4 so both branches are now in sync.

  • A 'make install' recursive dependency issue that caused Zend/zend_dtrace.d to be deleted was fixed.

  • PHP DTrace configuration now uses the correct PIC or non-PIC objects. This also fixed building PHP when any extensions were built 'shared'.

  • A segmentation fault in the "error" probe was fixed.

  • PHP's OCI8 2.0 extension now builds correctly with "real" DTrace.

The changes were tested on Solaris and Oracle Linux. The core PHP changes should be available in the next monthly releases, PHP 5.4.20 and PHP 5.5.4. The PHP OCI8 2.0 changes are already available from PECL.

I'll cover more detail about using PHP and PHP OCI8 with DTrace on Oracle Linux in a later blog post, but the basic steps are:

  • Install the UEK3 kernel, currently in Beta from public-yum.oracle.com.

  • Install the dtrace-utils package with 'yum install dtrace-utils'

  • Download a PHP 5.4 or 5.5 snapshot from snaps.php.net (Or download PHP 5.4.20, PHP 5.5.4, or later, once they are available)

  • Configure PHP with the --enable-dtrace option

  • Load the DTrace module: modprobe fasttrap

  • Change the helper device to allow writing: chmod 666 /dev/dtrace/helper

  • Run a DTrace profiling script and your PHP application

Update: the detail is in a new blog post Using PHP DTrace on Oracle Linux

Thursday Dec 06, 2012

Adding DTrace Probes to PHP Extensions

The powerful DTrace tracing facility has some PHP-specific probes that can be enabled with --enable-dtrace.

DTrace for Linux is being created by Oracle and is currently in tech preview. Currently it doesn't support userspace tracing so, in the meantime, Systemtap can be used to monitor the probes implemented in PHP. This was recently outlined in David Soria Parra's post Probing PHP with Systemtap on Linux.

My post shows how DTrace probes can be added to PHP extensions and traced on Linux. I was using Oracle Linux 6.3.

Not all Linux kernels are built with Systemtap, since this can impact stability. Check whether your running kernel (or others installed) have Systemtap enabled, and reboot with such a kernel:

# grep CONFIG_UTRACE /boot/config-`uname -r`
# grep CONFIG_UTRACE /boot/config-*

When you install Systemtap itself, the package systemtap-sdt-devel is needed since it provides the sdt.h header file:

# yum install systemtap-sdt-devel

You can now install and build PHP as shown in David's article. Basically the build is with:

$ cd ~/php-src
$ ./configure --disable-all --enable-dtrace
$ make

(For me, running 'make' a second time failed with an error. The workaround is to do 'git checkout Zend/zend_dtrace.d' and then rerun 'make'. See PHP Bug 63704)

David's article shows how to trace the probes already implemented in PHP. You can also use Systemtap to trace things like userspace PHP function calls. For example, create test.php:

<?php

$c = oci_connect('hr', 'welcome', 'localhost/orcl');
$s = oci_parse($c, "select dbms_xmlgen.getxml('select * from dual') xml from dual");
$r = oci_execute($s);
$row = oci_fetch_array($s, OCI_NUM);
$x = $row[0]->load();
$row[0]->free();
echo $x;

?>

The normal output of this file is the XML form of Oracle's DUAL table:

$ ./sapi/cli/php ~/test.php
<?xml version="1.0"?>
<ROWSET>
 <ROW>
  <DUMMY>X</DUMMY>
 </ROW>
</ROWSET>

To trace the PHP function calls, create the tracing file functrace.stp:

probe process("sapi/cli/php").function("zif_*") {
    printf("Started function %s\n", probefunc());
}

probe process("sapi/cli/php").function("zif_*").return {
    printf("Ended function %s\n", probefunc());
}

This makes use of the way PHP userspace functions (not builtins) like oci_connect() map to C functions with a "zif_" prefix.

Login as root, and run System tap on the PHP script:

# cd ~cjones/php-src
# stap -c 'sapi/cli/php ~cjones/test.php' ~cjones/functrace.stp
Started function zif_oci_connect
Ended function zif_oci_connect
Started function zif_oci_parse
Ended function zif_oci_parse
Started function zif_oci_execute
Ended function zif_oci_execute
Started function zif_oci_fetch_array
Ended function zif_oci_fetch_array
Started function zif_oci_lob_load
<?xml version="1.0"?>
<ROWSET>
 <ROW>
  <DUMMY>X</DUMMY>
 </ROW>
</ROWSET>
Ended function zif_oci_lob_load
Started function zif_oci_free_descriptor
Ended function zif_oci_free_descriptor

Each call and return is logged. The Systemtap scripting language allows complex scripts to be built. There are many examples on the web.

To augment this generic capability and the PHP probes in PHP, other extensions can have probes too. Below are the steps I used to add probes to OCI8:

  1. I created a provider file ext/oci8/oci8_dtrace.d, enabling three probes. The first one will accept a parameter that runtime tracing can later display:

    provider php {
    	probe oci8__connect(char *username);
    	probe oci8__nls_start();
    	probe oci8__nls_done();
    };
    
  2. I updated ext/oci8/config.m4 with the PHP_INIT_DTRACE macro. The patch is at the end of config.m4. The macro takes the provider prototype file, a name of the header file that 'dtrace' will generate, and a list of sources files with probes. When --enable-dtrace is used during PHP configuration, then the outer $PHP_DTRACE check is true and my new probes will be enabled. I've chosen to define an OCI8 specific macro, HAVE_OCI8_DTRACE, which can be used in the OCI8 source code:

    diff --git a/ext/oci8/config.m4 b/ext/oci8/config.m4
    index 34ae76c..f3e583d 100644
    --- a/ext/oci8/config.m4
    +++ b/ext/oci8/config.m4
    @@ -341,4 +341,17 @@ if test "$PHP_OCI8" != "no"; then
         PHP_SUBST_OLD(OCI8_ORACLE_VERSION)
     
       fi
    +
    +  if test "$PHP_DTRACE" = "yes"; then
    +     AC_CHECK_HEADERS([sys/sdt.h], [
    +       PHP_INIT_DTRACE([ext/oci8/oci8_dtrace.d],
    +                       [ext/oci8/oci8_dtrace_gen.h],[ext/oci8/oci8.c])
    +         AC_DEFINE(HAVE_OCI8_DTRACE,1,
    +         [Whether to enable DTrace support for OCI8 ])
    +     ], [
    +       AC_MSG_ERROR(
    +         [Cannot find sys/sdt.h which is required for DTrace support])
    +     ])
    +   fi
    +
     fi
    
  3. In ext/oci8/oci8.c, I added the probes at, for this example, semi-arbitrary places:

    diff --git a/ext/oci8/oci8.c b/ext/oci8/oci8.c
    index e2241cf..ffa0168 100644
    --- a/ext/oci8/oci8.c
    +++ b/ext/oci8/oci8.c
    @@ -1811,6 +1811,12 @@ php_oci_connection *php_oci_do_connect_ex(char *username, int username_len, char
     		}
     	}
     
    +#ifdef HAVE_OCI8_DTRACE
    +    if (DTRACE_OCI8_CONNECT_ENABLED()) {
    +		DTRACE_OCI8_CONNECT(username);
    +	}
    +#endif
    +
     	/* Initialize global handles if they weren't initialized before */
     	if (OCI_G(env) == NULL) {
     		php_oci_init_global_handles(TSRMLS_C);
    @@ -1870,11 +1876,22 @@ php_oci_connection *php_oci_do_connect_ex(char *username, int username_len, char
     		size_t rsize = 0;
     		sword result;
     
    +#ifdef HAVE_OCI8_DTRACE
    +		if (DTRACE_OCI8_NLS_START_ENABLED()) {
    +			DTRACE_OCI8_NLS_START();
    +		}
    +#endif
     		PHP_OCI_CALL_RETURN(result, OCINlsEnvironmentVariableGet, (&charsetid_nls_lang, 0, OCI_NLS_CHARSET_ID, 0, &rsize));
     		if (result != OCI_SUCCESS) {
     			charsetid_nls_lang = 0;
     		}
     		smart_str_append_unsigned_ex(&hashed_details, charsetid_nls_lang, 0);
    +
    +#ifdef HAVE_OCI8_DTRACE
    +		if (DTRACE_OCI8_NLS_DONE_ENABLED()) {
    +			DTRACE_OCI8_NLS_DONE();
    +		}
    +#endif
     	}
     
     	timestamp = time(NULL);
    

    The oci_connect(), oci_pconnect() and oci_new_connect() calls all use php_oci_do_connect_ex() internally. The first probe simply records that the PHP application made a connection call. I already showed a way to do this without needing a probe, but adding a specific probe lets me record the username. The other two probes can be used to time how long the globalization initialization takes.

    The relationships between the oci8_dtrace.d names like oci8__connect, the probe guards like DTRACE_OCI8_CONNECT_ENABLED() and probe names like DTRACE_OCI8_CONNECT() are obvious after seeing the pattern of all three probes.

    I included the new header that will be automatically created by the dtrace tool when PHP is built. I did this in ext/oci8/php_oci8_int.h:

    diff --git a/ext/oci8/php_oci8_int.h b/ext/oci8/php_oci8_int.h
    index b0d6516..c81fc5a 100644
    --- a/ext/oci8/php_oci8_int.h
    +++ b/ext/oci8/php_oci8_int.h
    @@ -44,6 +44,10 @@
     #  endif
     # endif /* osf alpha */
     
    +#ifdef HAVE_OCI8_DTRACE
    +#include "oci8_dtrace_gen.h"
    +#endif
    +
     #if defined(min)
     #undef min
     #endif
    
  4. Now PHP can be rebuilt:

    $ cd ~/php-src
    $ rm configure && ./buildconf --force
    $ ./configure --disable-all --enable-dtrace \
                  --with-oci8=instantclient,/home/cjones/instantclient
    $ make
    

    If 'make' fails, do the 'git checkout Zend/zend_dtrace.d' trick I mentioned.

  5. The new probes can be seen by logging in as root and running:

    # stap -l 'process.provider("php").mark("oci8*")' -c 'sapi/cli/php -i'
    process("sapi/cli/php").provider("php").mark("oci8__connect")
    process("sapi/cli/php").provider("php").mark("oci8__nls_done")
    process("sapi/cli/php").provider("php").mark("oci8__nls_start")
    
  6. To test them out, create a new trace file, oci.stp:

    global numconnects;
    global start;
    global numcharlookups = 0;
    global tottime = 0;
    probe process.provider("php").mark("oci8-connect") {
        printf("Connected as %s\n", user_string($arg1));
        numconnects += 1;
    }
    probe process.provider("php").mark("oci8-nls_start") {
        start = gettimeofday_us();
        numcharlookups++;
    }
    probe process.provider("php").mark("oci8-nls_done") {
        tottime += gettimeofday_us() - start;
    }
    probe end {
        printf("Connects: %d, Charset lookups: %ld\n", numconnects, numcharlookups);
        printf("Total NLS charset initalization time: %ld usecs/connect\n", 
                            (numcharlookups > 0 ? tottime/numcharlookups : 0));
    }
    

    This calculates the average time that the NLS character set lookup takes. It also prints out the username of each connection, as an example of using parameters.

  7. Login as root and run Systemtap over the PHP script:

    # cd ~cjones/php-src
    # stap -c 'sapi/cli/php ~cjones/test.php' ~cjones/oci.stp
    Connected as cj
    <?xml version="1.0"?>
    <ROWSET>
     <ROW>
      <DUMMY>X</DUMMY>
     </ROW>
    </ROWSET>
    Connects: 1, Charset lookups: 1
    Total NLS charset initalization time: 164 usecs/connect
    

    This shows the time penalty of making OCI8 look up the default character set. This time would be zero if a character set had been passed as the fourth argument to oci_connect() in test.php.

Update: To use real (non-SystemTap) DTrace, the extension binary needs to be built slightly differently than shown above in step 2. Instead of modifying config.m4 to reuse PHP_INIT_DTRACE, an OCI8-specific variant of that macro is created. To see how this is done, look at the new OCI8_INIT_DTRACE macro definition and way it is used in PHP OCI8 2.0's ext/oci8/config.m4.

Tuesday Jan 19, 2010

Tracing PHP Oracle Applications, part 1

[Read More]
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
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
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