Sometimes you forget about what you did years ago, for example the ability of mysqlnd write back traces of slow queries into the PHP error log . Regardless if you use mysqlnd with ext/mysql, ext/mysqli or PDO_MYSQL, mysqlnd is able to tell you which of your code has executed a slow query. To enable the feature, you need to compile PHP with CFLAGS="-D A0". A0? Yeah, we must have had some doubts about the usefulness.

Slow queries

The MySQL server is capable of monitoring queries and recording slow queries in a slow query log. MySQL can log the following types of queries:

• SQL statements that took more than long_query_time seconds to execute
• SQL statement that required at least min_examined_row_limit rows to be examined (MySQL 5.1.21+)
• SQL statement that do not use indexes
• Slow administrative statements

Please consult the MySQL manual on how to use the slow query log. The basic approach is to set the server startup options --log-slow-queries, --log-queries-not-using-indexes.

Not only the server known which query was slow, clients can tell as well. And this can be used to create a backtrace in PHP to identify the PHP code which has executed a slow query.

It seems little to not documented at all how to identify slow queries when using the C API. If you happen to use the C API as well, have a look at the code example I gave in the german language blog posting SERVER_QUERY_NO_INDEX_USED, SERVER_QUERY_NO_GOOD_INDEX_USED (and SERVER_QUERY_WAS_SLOW).

mysqli_report()

User of ext/mysqli have been able to create backtraces of slow queries for quite some time by help of mysqli_report(). mysqli_report(MYSQLI_REPORT_INDEX) should cause and exception to the thrown whenever a slow query is detected and mysqli_report(MYSQLI_REPORT_INDEX ^ MYSQLI_REPORT_STRICT) should give a warning. There are two drawbacks with this approach. First, it may be inconvenient or virtually impossible to react to the exceptions given the many database abstraction layers used by non-trivial PHP applications. Second, this is ext/mysqli - it won’t work with ext/mysql or PDO_MYSQL.

CFLAGS="-D A0"

If you compile ext/mysql, ext/mysqli and PDO_MYSQL using something like CFLAGS="-D A0" ./configure --with-mysql=mysqlnd --with-mysqli=mysqlnd --with-pdo-mysql=mysqlnd, you will enable the neat little code passage shown below. Whenever mysqlnd fetches a result from the server and the server hints a slow query, mysqlnd will write a backtrace to the PHP error log. The logging happens regardless who calls mysqlnd: ext/mysql, ext/mysqli, PDO_MYSQL. All queries generating a result set will be recorded.

#if A0
        char *backtrace = mysqlnd_get_backtrace(TSRMLS_C);
        php_log_err(backtrace TSRMLS_CC);
        efree(backtrace);
#endif

From mysqlnd_result.c

NOTE: The feature is experimental. Consider it untested. mysqlnd_get_backtrace() didn’t crash yesterday when forcing it to log all queries from all 440+ PHP tests for ext/mysql and ext/mysqli. It should work just fine but we have not done an extensive testing…

mysqlnd.log_mask

The PHP configuration setting mysqlnd.log_mask defines which queries will be logged. The default is mysqlnd.log_mask = "0", which disables logging. Set it to 16 + 32 = 48 to log slow queries which either use no good index (SERVER_QUERY_NO_GOOD_INDEX_USED = 16) or no index at all (SERVER_QUERY_NO_INDEX_USED = 32). Or, if you are a curious person, try mysqlnd.log_mask=2043 (= 1 + 2 + 8 + … + 1024).

The SEVER_* constants are MySQL internal (C-level) constants (defines) not exported to the PHP userland. There are no corresponding PHP constants. However, you can look up the values in the below table which has been created by inspecting the mysqlnd source.

From mysqlnd_enum_n_def.h. mysqlnd has taken the values from the corresponding header file of the server. The server code has some few annotations. If you compare the server code and the mysqlnd code don’t be puzzled about SERVER_QUERY_WAS_SLOW - it is from MySQL 6.0, it is in flux, it is undocumented.

The mysqlnd slow query log

Once you put all pieces together, mysqlnd will log (slow) queries. The log not very sophisticated. Just the opposite. For example, mysqlnd cuts off query strings after 15 characters reporting only a fraction of the SQL statement. If you don’t like that, hack mysqlnd_debug.c. Be warned that there may be more such limitations. As said above, this is experimental.

#1 {main}
[23-Oct-2009 13:58:48] #0 /home/nixnutz/src/php-src/branches/PHP_5_3/ext/mysqli/tests/013.php(32): mysqli_query(Object(mysqli), 'select * from t...')
#1 {main}
[23-Oct-2009 13:58:48] #0 /home/nixnutz/src/php-src/branches/PHP_5_3/ext/mysqli/tests/014.skip.php(6): mysqli_query(Object(mysqli), 'SHOW VARIABLES ...')

Back then we stopped at this point. Let us know what you think about it. Comments are welcome.

A0 ?!

A[ndrey] 0. As you know, Andrey is the brain. I’m the helper and ghost writer. The brain just told me that there is another A0 in mysqlnd_alloc.c. However, mysqlnd_alloc.c won’t be compiled. Everything is fine - I am the lucky helper…