Inline Helpers - Debugging Slow MySQL Solutions

This article contains some techniques for finding slow MySQL queries. It includes an Inline Helper tag which make debugging MySQL queries easier by allowing you to tag queries in the long query log and process list.

Introduction

MySQL includes a number of tools which make it possible to see how the data source is processing your database requests and to perform optimization when necessary. It is important to use these tools particularly if you are experiencing slowdowns or instability, but being proactive about optimizing your machine can help ensure that you don't experience issues in the future. Often a site will appear to work perfectly well when traffic is low, but will be throttled by bottlenecks when traffic is high.

This tip includes a general discussion of using the MySQL Slow Query Log, Process List, and EXPLAIN statement to examine MySQL bottlenecks. The included [Inline_Helper] tag makes it easier to associate SQL statements with the Lasso pages which originated them. Finally, a few additional helper tags [Inline_Statement] and [Inline_Records] are presented.

Download

The [Inline_Helper] tag described below can be downloaded using this link. The resulting "inline_helper.lasso" file should be included in any file which you want to use this tag or can be installed into the LassoStartup folder if you want to make it available across your entire server (or an individual site).

Debugging Slow MySQL Solutions.zip  

Understanding MySQL Slowdowns

MySQL has three tools which are essential when you are attempting to debug a MySQL slowdown.

Slow Query Log

http://dev.mysql.com/doc/refman/4.1/en/slow-query-log.html

The slow query log should be turned on using the following statement in your my.cnf file. The log will be created automatically in the same folder as your database files.

  log-slow-queries

By default the slow query log lists every query which took longer than ten seconds to process. Most MySQL queries take only a fraction of a second. An occasional system maintenance script might reasonably take longer than ten seconds, but you almost certainly don't want any queries generated by your Web visitors to take that long.

The entries in the slow query log should appear similar to that shown below. The log includes the client's IP address, the date/time at which the query was started, how long the query took, how many records were sent to the client, how many records were inspected to find those records, and the query itself.

  # Time: 071101 14:16:24
  # User@Host: lasso[lasso] @  [localhost]
  # Query_time: 12  Lock_time: 0  Rows_sent: 10  Rows_examined: 41546
  SELECT article_index FROM `website`.`articles` WHERE
  (`status` = "active") ORDER BY `creation_datetime` DESC LIMIT 10;

 

Using the slow query log is straightforward. Your job is to find where the SQL statement was issued and try to find a way to rewrite the query so that it runs faster. However, finding the SQL statement is often difficult. If you write your own SQL statements you can improve matters by including a short comment in each SQL statement as shown below. MySQL will ignore the contents of the comment, but you will be able to see it in the slow query log.

  SELECT /* search page */ article_index FROM `website`.`articles` WHERE
  (`status` = "active") ORDER BY `creation_datetime` DESC LIMIT 10;

 

The [Inline_Helper] tag below shows how you can insert a comment into your traditional Lasso inlines without any significant changes or slowdowns.

Process List

http://dev.mysql.com/doc/refman/4.1/en/show-processlist.html

MySQL's process list allows you to see what processes are running right now. The list is returned by the following SQL statement.

  SHOW PROCESSLIST;

The list will appear as shown below. Each line includes information about the client, the current status of the thread, and the SQL statement. It is often helpful to expand the terminal window as large as possible before running the SHOW PROCESSLIST statement since more of each SQL statement will be shown.

ID	User	Host	db	Command	Time	State	Info
19618071	lasso	localhost	NULL	Query	5	NULL	SHOW PROCESSLIST
19619492	lasso	localhost	website	Query	5	Sending data	SELECT article_index FROM `web

Again, a short comment right at the start of each SQL statement makes it a lot easier to tell which statement belongs to which Lasso page. Since the SQL statements are truncated they often don't contain the search terms which are most essential to identify which page generated the statement.

ID	User	Host	db	Command	Time	State	Info
19618071	lasso	localhost	NULL	Query	5	NULL	SHOW PROCESSLIST
19619492	lasso	localhost	website	Query	5	Sending data	SELECT /* search page */ article_index FROM `web

The process list is a snapshot of what's happening right now. On a busy server you'll usually see a few queries running, but it is also not unusual to see no queries at all. By viewing the process list several times over the course of a couple minutes you should be able to get a good feel for how the processes are going on your server.

When you view the process list look particularly for statements that are "locked" and statements which are taking a long time to sort. A single UPDATE or DELETE can sometimes lock an entire table and a great many SELECTs will pile up after it. If you have many locked statements then you should consider methods of optimizing your searches and minimizing updates and deletes so that they cause as little disruption as possible.

If you see a lot of statements which are currently sorting their results then you may need to optimize how you are performing your searches in order to minimize the number of records which MySQL needs to sort. In particular, if there are any filesorts occurring then you should optimize your queries so they aren't necessary.

Finally, if you see queries which are simply taking a long time and aren't locked or performing filesorts, then you should look at the indexing of your tables to make sure that they are being used. A query which uses an index can be dramatically faster than one which does not, from several seconds to a fraction of a second in many cases.

EXPLAIN Statement

http://dev.mysql.com/doc/refman/4.1/en/explain.html

The EXPLAIN statement will tell you what work MySQL needs to do in order to perform a SELECT query. It will tell you whether indexes are being consulted, whether a filesort is required, and what tables are being used for the query. Simply put the keyword EXPLAIN in front of any SELECT statement.

  EXPLAIN SELECT article_index FROM `website`.`articles` WHERE
  (`status` = "active") ORDER BY `creation_datetime` DESC LIMIT 10;

The result will be as shown below. Each table is listed along with information about what indexes were consulted and additional comments such as whether a filesort was required.

D	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
1	SIMPLE	articles	ref	id,status,author,subject	status	16	const	3526	Using where; Using filesort

Once you have identified a slow query or a query that is locking your database then you can use EXPLAIN to determine what optimizations are possible. IF no indexes are being used then you should review the indexes on the table. If a filesort is being performed then you should optimize the statement to limit the number of records which need to be sorted.

Inline Helper

When Lasso processes an inline it generates a SQL statement internally and then transmits that SQL statement to the data source. The SQL statement which Lasso generates can be returned using the [Action_Statement] tag. For example, the following inline...

  [Inline: -Search,
      -Database='ldml8_reference',
      -Table='tags',
      -KeyField='id',
      -Eq, 'tag_name'='[Field]']
    [Action_Statement]
  [/Inline]

 

... would generate this SQL statement:

  SELECT * FROM tags WHERE tag_name="[Field]";

As we saw above, we'd like a way to insert a comment into the SELECT statement. The [Inline_Helper] tag makes this possible. All of the parameters of the [Inline] are passed first through the [Inline_Helper] tag and then the results of that tag are passed back to the inline.

The [Inline_Helper] tag accepts an optional -Comment parameter which will add a comment to the generated SQL statement.

The inline below is the same as the inline above, but now uses the [Inline_Helper] tag to add a -Comment to the inline.

  [Inline: (Inline_Helper: -Comment='My Search Page',
      -Search,
      -Database='ldml8_reference',
      -Table='tags',
      -KeyField='id',
      -Eq, 'tag_name'='[Field]')]
    [Action_Statement]
  [/Inline]

 

The SQL statement generated by the inline above now contains the comment specified. Otherwise, the inline will work exactly the same as the inline it was based on.

  SELECT /* My Search Page */ * FROM tags WHERE tag_name="[Field]";

By modifying each of the inlines on a site we can add a comment which will let us know which inline generated each statement that we see in the MySQL slow query log and process list. One good idea is to simply label each inline with the current Response_FilePath and Include_CurrentPath.

  -Comment=(Response_FilePath + ' ' + Include_CurrentPath),

The [Inline_Helper] should work with any SQL-based data source that supports inline comments. It has been tested with MySQL and the built-in SQLite data source. It will not work with FileMaker data sources.

How It Works

The [Inline_Helper] tag has a very simple implementation. It expects to be passed the same parameters at the opening [Inline] tag. It creates two parameter arrays. The first array contains all of the parameters passed into the tag. This array is passed into an internal [Inline] tag and includes -StatementOnly. The internal inline generates a SQL statement, but does not perform any action.

The second array contains the parameters that will be the result of the tag. The basic parameters -Database, -Table, -Schema, -KeyField, etc. are copied into this array. In addition, the SQL statement generated by the internal inline is placed into this array.

The input of the tag is an inline database action like this...

  -Search,
  -Database='ldml8_reference',
  -Table='Tags',
  -KeyField='id',
  'tag_name'='[Field]',

The output of the tag is a SQL-based database action like this. Since this uses the SQL statement generated by the code above it will generate exactly the same results within Lasso.

  -Database='ldml8_reference',
  -Table='tags',
  -KeyField='id',
  -SQL='SELECT * FROM tags where field_name='[Field]';',

See the source of the tag for information about how it juggles the various parameters.