Web applications

Many interpreted languages that are used in Web development like Python, Perl, PHP and Ruby implement USDT probes. Some HTTP servers like Apache HTTP server (there is also an nginx fork, called nginx-dtrace) and databases such as MySQL, PostgreSQL and Berkeley DB provide them too. Let's see how that can be used to trace a real web application like Drupal CMS framework.

Warning

DTrace Support in the build system is not complete. Patches Welcome!

We will use Drupal with MySQL database running under Zend PHP interpreter in Apache web-server in mod_php mode. You can also use PHP-FPM, but it makes requests mapping harder as requests would be processed by different processes. In our case, without PHP-FPM, web-application and http-server would be of same context:

You will need to use provider name to access PHP, MySQL and Apache HTTP Server probes. Their naming convention is the same as any other USDT probe:

php*:::probe-name
mysql*:::probe-name
ap*:::probe-name

process("httpd").mark("probe__name")
process("mysqld").mark("probe__name")
process("libphp5.so").mark("probe__name")

Here are list of arguments and names of some useful Apache probes:

Action	DTrace	SystemTap
Request is redirected	internal-redirect arg0 — old URI arg1 — new URI	internal__redirect $arg1 — old URI $arg2 — new URI
Request is read from socket	read-request-entry arg0 — request_rec structure arg1 — conn_rec structure	read__request__entry $arg1 — request_rec structure $arg2 — conn_rec structure
	read-request-success arg0 — request_rec structure arg1 — method (GET/POST/...) arg2 — URI arg3 — server name arg4 — HTTP status	read__request__success $arg1 — request_rec structure $arg2 — method (GET/POST/...) $arg3 — URI $arg4 — server name $arg5 — HTTP status
	read-request-failure arg0 — request_rec structure	read__request__failure $arg1 — request_rec structure
Request is processed	process-request-entry arg0 — request_rec structure arg1 — URI	process__request__entry $arg1 — request_rec structure $arg2 — URI
	process-request-return arg0 — request_rec structure arg1 — URI arg2 — HTTP status	process__request__return $arg1 — request_rec structure $arg2 — URI $arg3 — HTTP status

Warning

There are also many Apache Hooks probes, but they are not providing useful arguments.

Following table provides list of useful PHP SAPI probes:

Action	DTrace	SystemTap
Request processing
Request processing started	request-startup arg0 — file name arg1 — request URI arg2 — request method	request__startup $arg1 — file name $arg2 — request URI $arg3 — request method
Request processing finished	request-shutdown Arguments are same as for request-startup	request__shutdown Arguments are same as for request__startup
Compiler
Compilation	compile-file-entry arg0 — source file name arg1 — compiled file name	compile__file__entry $arg1 — source file name $arg2 — compiled file name
File is compiled	compile-file-return Arguments are same as for compile-file-entry	compile__file__return Arguments are same as for compile__file__entry
Functions
Function call	function-entry arg0 — function name arg1 — file name arg2 — line number arg3 — class name arg4 — scope operator ::	function__entry $arg1 — function name $arg2 — file name $arg3 — line number $arg4 — class name $arg5 — scope operator ::
Function return	function-return Arguments are same as for function-entry	function__return Arguments are same as for function__entry
VM execution
Beginning of operation execution	execute-entry arg0 — file name arg1 — line number	execute__entry $arg1 — file name $arg2 — line number
Beginning of operation execution	execute-return Arguments are same as for execute-entry	execute__return Arguments are same as for execute__entry
Errors and exceptions
PHP error	error arg0 — error message arg1 — file name arg2 — line number	error $arg1 — error message $arg2 — file name $arg3 — line number
Thrown exception	exception-thrown arg0 — exception class name	exception__thrown arg0 — exception class name
Caught exception	exception-caught Arguments are same as for exception-thrown	exception__caught Arguments are same as for exception__thrown

MySQL has wide set of probes. They are described in MySQL documentation: 5.4.1 mysqld DTrace Probe Reference. Here are list of basic probes which allow to trace queries and connections:

Action	DTrace	SystemTap
Connection	connection-start arg0 — connection number arg1 — user name arg2 — host name	connection__start $arg1 — connection number $arg2 — user name $arg3 — host name
	connection-done arg0 — connection status arg1 — connection number	connection__done $arg1 — connection status $arg2 — connection number
Query parsing	query-parse-start arg0 — query text	query__parse__start $arg1 — query text
	query-parse-done arg0 — status	query__parse__done $arg1 — status
Query execution	query-exec-start arg0 — query text arg1 — connection number arg2 — database name arg3 — user name arg4 — host name arg5 — source of request (cursor, procedure, etc.)	query__exec__start $arg1 — query text $arg2 — connection number $arg3 — database name $arg4 — user name $arg5 — host name $arg6 — source of request (cursor, procedure, etc.)
	query-exec-done arg0 — status	query__exec__done $arg1 — status

Here are simple tracer for PHP web application which is written on SystemTap:

@define httpd %( "/usr/local/apache2/bin/httpd" %)
@define libphp5 %( "/usr/local/apache2/modules/libphp5.so" %)
@define mysqld %( "/usr/local/mysql/bin/mysqld" %)

global parsequery;
global execquery;

function basename:string(s:string) {
    len = strlen(s)
    i = len
    
    while(i > 0) {
        /* 47 is code for '/' */
        if(stringat(s, i - 1) == 47)
            return substr(s, i, len - i);
            
        --i;
    }
    
    return s;
}

probe process(@httpd).mark("internal__redirect")  {
    printf("[httpd] redirect\t'%s' -> '%s'\n", 
           user_string($arg1), user_string($arg2));
}

probe process(@httpd).mark("read__request__entry") {
    printf("[httpd] read-request\n");
}

probe process(@httpd).mark("read__request__success") {
    servername = ($arg4) ? user_string($arg4) : "???";
    
    printf("[httpd] read-request\t%s %s %s  [status: %d]\n",
           user_string($arg2), servername, user_string($arg3), $arg5);
}

probe process(@httpd).mark("process__request__entry") {
    printf("[httpd] process-request\t'%s'\n", user_string($arg2));
}

probe process(@httpd).mark("process__request__return") {
    printf("[httpd] process-request\t'%s' access-status: %d\n",
           user_string($arg2), $arg3);
}

probe process(@libphp5).mark("request__startup"),
      process(@libphp5).mark("request__shutdown") {
    printf("[ PHP ] %s\n\t%s '%s' file: %s \n", pn(), user_string($arg3),
           user_string($arg2), user_string($arg1));
}

probe process(@libphp5).mark("function__entry"),
      process(@libphp5).mark("function__return") {
    printf("[ PHP ] %s\n\t%s%s%s file: %s:%d \n", pn(), 
          user_string($arg4), user_string($arg5), user_string($arg1),
          basename(user_string($arg2)), $arg3);
}

probe process(@mysqld).mark("query__parse__start") {
   parsequery[tid()] = user_string_n($arg1, 1024);
}

probe process(@mysqld).mark("query__parse__done") {
   printf("[MySQL] query-parse\t'%s' status: %d\n", parsequery[tid()], $arg1);
}

probe process(@mysqld).mark("query__exec__start") {
   execquery[tid()] = user_string_n($arg1, 1024);
}

probe process(@mysqld).mark("query__exec__done") {
   printf("[MySQL] query-exec\t'%s' status: %d\n", execquery[tid()], $arg1);
}

[httpd] read-request
[httpd] read-request    GET ??? /drupal/modules/contextual/images/gear-select.png  [status: 200]                                                                            
[httpd] process-request '/drupal/modules/contextual/images/gear-select.png'                                                                                                 
[httpd] process-request '/drupal/modules/contextual/images/gear-select.png' access-status: 304                                                                              
[httpd] read-request                                                                                                                                                        
[httpd] read-request    GET ??? /drupal/  [status: 200]                                                                                                                     
[httpd] process-request '/drupal/'                                                                                                                                          
[ PHP ] request-startup GET '/drupal/index.php' file: /usr/local/apache2/htdocs/drupal/index.php                                                                            
[ PHP ] function-entry  main file: index.php:19                                                                                                                             
[ PHP ] function-return main file: index.php:19 
…
[ PHP ] function-entry  DatabaseStatementBase::execute file: database.inc:680 
[MySQL] query-parse     'SELECT u.*, s.* FROM users u INNER JOIN sessions s ON u.uid = s.uid WHERE s.sid = 'yIR5hLWScBNAfwOby2R3FiDfDokiU456ZE-rBDsPfu0'' status: 0
[MySQL] query-exec      'SELECT u.*, s.* FROM users u INNER JOIN sessions s ON u.uid = s.uid WHERE s.sid = 'yIR5hLWScBNAfwOby2R3FiDfDokiU456ZE-rBDsPfu0'' status: 0
...
[ PHP ] request-shutdown        GET '/drupal/index.php' file: /usr/local/apache2/htdocs/drupal/index.php 
[httpd] process-request '/drupal/index.php' access-status: 200

As you can see from this trace, there is a request of a static image gear-select.png which is resulted in status 304 and a dynamic page index.php which eventually accesses database to check user session.

Warning

Due to high amounts of script outputs, you will need to increase buffers in DTrace. The rest of script will look similar to web.stp:

#pragma D option strsize=2048
#pragma D option bufsize=128M
#pragma D option switchrate=20hz

ap*:::internal-redirect  {
    printf("[httpd] redirect\t'%s' -> '%s'\n", copyinstr(arg0), copyinstr(arg1));
}

ap*:::read-request-entry {
    printf("[httpd] read-request\n");
}

ap*:::read-request-success {
    this->servername = (arg3) ? copyinstr(arg3) : "???";
    
    printf("[httpd] read-request\t%s %s %s  [status: %d]\n", 
        copyinstr(arg1), this->servername, copyinstr(arg2), arg4);
}

ap*:::process-request-entry {
    printf("[httpd] process-request\t'%s'\n", copyinstr(arg1));
}

ap*:::process-request-return {
    printf("[httpd] process-request\t'%s' access-status: %d\n", 
        copyinstr(arg1), arg2);
}

php*:::request-startup,
php*:::request-shutdown {
    printf("[ PHP ] %s\t%s '%s' file: %s \n", probename, 
        copyinstr(arg2), copyinstr(arg1), copyinstr(arg0));
}

php*:::function-entry,
php*:::function-return {
    printf("[ PHP ] %s\t%s%s%s file: %s:%d \n", probename, 
        copyinstr(arg3), copyinstr(arg4), copyinstr(arg0),
        basename(copyinstr(arg1)), arg2);
}

mysql*:::query-parse-start {
   self->parsequery = copyinstr(arg0, 1024);
}

mysql*:::query-parse-done {
   printf("[MySQL] query-parse\t'%s' status: %d\n", self->parsequery, arg0);
}

mysql*:::query-exec-start {
   self->execquery = copyinstr(arg0, 1024);
}

mysql*:::query-exec-done {
   printf("[MySQL] query-exec\t'%s' status: %d\n", self->execquery, arg0);
}