13.8 Tracing User-Space Applications

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
...