J

Tracking SQL queries

15 May 2015

When you run a large application (or many large applications), it is important that you can effectively track down and investigate slow SQL queries when they arise. MySQL doesn’t receive context of where the query is coming from so in your logs you end up with something that will look like this:

# Time: 150517  6:26:05
# [email protected]: mysql_user[mysql_user] @ db1.example.com [10.0.0.60]
# Thread_id: 4038366  Schema: example_table  Last_errno: 0  Killed: 0
# Query_time: 2.388451  Lock_time: 0.000041  Rows_sent: 0  Rows_examined: 1302  Rows_affected: 1302  Rows_read: 1302
# Bytes_sent: 13  Tmp_tables: 0  Tmp_disk_tables: 0  Tmp_table_sizes: 0
# InnoDB_trx_id: 2D57FA24A
use example_table;
SELECT *
FROM users

Sure, if this is a specific query you might know which URL or method is sending it, but what if someone not so familiar with the application needed to investigate it - would they be able to find it?

One option is to add a comment to your query that contains some useful information such as class name, method name or even a request ID. Consider the following query:

<?php

db_select('users', 'u')
  ->fields('u', array('mail', 'status'))
  ->execute();

# => SELECT u.mail AS mail, u.status AS status FROM users u

To add a comment to a query, you can use Drupal’s Query::comment method which will prepend your comment before sending the query. Below we add a comment that contains the module and function names of the caller.

<?php

db_select('users', 'u')
  ->comment('module:my_custom_module,function:some_slow_function')
  ->fields('u', array('mail', 'status'))
  ->execute()

# => /* module:my_custom_module,function:some_slow_function */ SELECT u.mail AS mail, u.status AS status FROM users u

Now should the query pop up in your slow query logs, it will be annotated with some helpful debugging information on it’s caller.

# Time: 150517  6:26:05
# [email protected]: mysql_user[mysql_user] @ db1.example.com [10.0.0.60]
# Thread_id: 4038366  Schema: example_table  Last_errno: 0  Killed: 0
# Query_time: 2.388451  Lock_time: 0.000041  Rows_sent: 0  Rows_examined: 1302  Rows_affected: 1302  Rows_read: 1302
# Bytes_sent: 13  Tmp_tables: 0  Tmp_disk_tables: 0  Tmp_table_sizes: 0
# InnoDB_trx_id: 2D57FA24A
use example_table;
/* module:my_custom_module,function:some_slow_function */
SELECT *
FROM users

If Rails is your framework of choice, the marginalia gem adds this feature to ActiveRecord and can be configured to capture any data you wish.