Adding DTrace Probes to PHP Extensions
- by cj
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:
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();
};
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
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
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.
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")
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.
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.
