13.8 Tracing User-Space Applications

13.8.1 Examining the Stack Trace of a User-Space Application

A number of DTrace-enabled applications will be made available following the release of DTrace 0.4, including MySQL and PHP. These applications have been instrumented to contain statically defined DTrace probes. You can find details about the probes for MySQL at http://dev.mysql.com/doc/refman/5.5/en/dba-dtrace-mysqld-ref.html and about the probes for PHP at http://php.net/manual/features.dtrace.php.

The MySQL query-probes query-start(query, connectionid, database, user, host) and query-done(status) are triggered when the MySQL server receives a query is received by the server and when the query has been completed and the server has successfully sent the information to the client.

For example, the following script reports the execution time for each database query:

#!/usr/sbin/dtrace -qs

dtrace:::BEGIN
{
   printf("%-20s %-10s %-40s %-9s\n", "Who", "Database", "Query", "Time(microseconds)");
}

mysql*:::query-start
{
   self->query = copyinstr(arg0);
   self->connid = arg1;
   self->db    = copyinstr(arg2);
   self->who   = strjoin(copyinstr(arg3),strjoin("@",copyinstr(arg4)));
   self->querystart = timestamp;
}

mysql*:::query-done
{
   printf("%-20s %-10s %-40s %-9d\n",self->who,self->db,self->query,
          (timestamp - self->querystart) / 1000);
}

The following is sample output from this script:

# ./query.d
Who                 Database   Query                                   Time(microseconds)
webuser@localhost   namedb     select * from table1 order by n ASC     1135     
webuser@localhost   namedb     delete from table1 where n='Bill'       10383        

The MySQL query-parsing probes query-parse-start(query) and query-parse-done(status) are triggered immediately before and after MySQL parses a SQL statement. For example, you could use the following script to monitor the execution time for parsing queries:

#!/usr/sbin/dtrace -qs

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

mysql*:::query-parse-done
/arg0 == 0/
{
  printf("Parsing %s: %d microseconds\n", self->parsequery,
    ((timestamp - self->parsestart)/1000));
}

mysql*:::query-parse-done
/arg0 != 0/
{
  printf("Error parsing %s: %d microseconds\n", self->parsequery,
    ((timestamp - self->parsestart)/1000));
}

The following is sample output from this script:

# ./query-parse.d
Parsing select * from table1 where n like 'B%' order by n ASC: 29 microseconds
Error parsing select from table1 join (table2) on (table1.i = table2.i)
    order by table1.s,table1.i limit 10: 36 microseconds

The following script uses the PHP probe error(error_message, request_file, line_number), to report PHP errors:

#!/usr/sbin/dtrace -qs

php*:::error
{
    printf("PHP error\n");
    printf("  error message             %s\n", copyinstr(arg0));
    printf("  request file              %s\n", copyinstr(arg1));
    printf("  line number               %d\n\n", (int)arg2);
}

For example, you can use the PHP trigger_error() function to trigger a PHP error if a MySQL function returns an error:

<?php
ini_set('error_reporting', E_ALL); /* Report all errors */
ini_set('display_errors', 'Off');  /* but do not display them */
...
  $mysqli->query($QUERY) or trigger_error($mysqli->error."[$QUERY]",E_USER_ERROR);
...
?>

You could use the script to report errors that might indicate incorrectly queries or attempted SQL injection attacks, for example:

# ./php_error.d
...
PHP error
  error message             You have an error in your SQL syntax; check the manual that
                            corresponds to your MySQL server version for the right syntax
                            to use near '='1'; --'' at line 1[select * from table1 where n 
                            like 'B%' or '1'='1'; --']
  request file              /var/www/html/example.php
  line number               61

...
PHP error
  error message             You have an error in your SQL syntax; check the manual that
                            corresponds to your MySQL server version for the right syntax
                            to use near 'drop table table1; --'' at line 1[select * from
                            table1 where n like 'B%';drop table table1; --']
  request file              /var/www/html/example.php
  line number               61
... 

13.8.1 Examining the Stack Trace of a User-Space Application

You can use the ustack() function to perform a stack trace of any user-space application, for example:

# dtrace -n syscall::write:entry'/pid == $target/ \
{ustack(); \
exit(0)}' -c "ls -l /"
dtrace: description 'syscall::write:entry' matched 1 probe
total 125
dr-xr-xr-x.   2 root root       4096 Apr 22 09:11 bin
dr-xr-xr-x.   5 root root       4096 Sep 24 09:42 boot
...
drwxr-xr-x.  14 root root       4096 Nov  2  2012 usr
drwxr-xr-x.  25 root root       4096 Apr 20 13:18 var
CPU     ID                    FUNCTION:NAME
  1      6                      write:entry
              libc.so.6`_IO_file_write+0x43
              libc.so.6`_IO_do_write+0x95
              libc.so.6`_IO_file_close_it+0x160
              libc.so.6`fclose+0x178
              ls`0x411fc9
              ls`close_stdout+0x14
              libc.so.6`exit+0xe2
              ls`0x409620
              libc.so.6`_IO_file_underflow+0x138
              libc.so.6`flush_cleanup
              libc.so.6`fclose+0x14d
              libc.so.6`fclose+0x14d
              libselinux.so.1`0x3f1840ce6f
              ls`0x412040
              ls`0x40216b
              ls`0x4027e0
              libc.so.6`__libc_start_main+0xfd
              ls`0x408480
              ls`0x4027e0
              ls`0x4027e0
              ls`0x402809

DTrace can translate the stack frames into symbols for shared libraries (such as libc) and unstripped executables. As ls is a stripped executable, the addresses remain unconverted. dtrace can translate stack frames for stripped executables if the --export-dynamic option was specified when the program was linked. This option causes the linker to add all symbols to the dynamic symbol table.