Three easy ways to optimize your MySQL queries

Any database programmer will tell you that in high-traffic database-driven applications, a single badly-designed SQL query can significantly impact the overall performance of your application. Not only does such a query consume more database time than it ideally should, but it can have an exponential effect on the performance of other application components.

Optimizing query performance is as much a black art as a science, as heavily dependent on the developer’s intuition as on hard statistical performance data. Fortunately, databases likes MySQL come with some tools to aid the process, and this article discusses three of them briefly: using indexes, analyzing queries with EXPLAIN, and adjusting MySQL’s internal configuration.

#1: Using indexes

MySQL allows you to index database tables, making it possible to quickly seek to records without performing a full table scan first and thus significantly speeding up query execution. You can have up to 16 indexes per table, and MySQL also supports multi-column indexes and full-text search indexes.

Adding an index to a table is as simple as calling the CREATE INDEX command and specifying the field(s) to index. Listing A shows you an example:

Listing A


mysql> CREATE INDEX idx_username ON users(username);
Query OK, 1 row affected (0.15 sec)
Records: 1 Duplicates: 0 Warnings: 0

Here, indexing the username field of the users table ensures that SELECT queries which reference this field in their WHERE or HAVING clause will run a little faster than in the pre-indexed state. You can check that the index was created (Listing B) with the SHOW INDEX command:

Listing B


mysql> SHOW INDEX FROM users;
————–+————-+———–+————-+———-+——–+——+————+———+
| Table | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment |
————–+————-+———–+————-+———-+——–+——+————+———+
| users | 1 | idx_username | 1 | username | A | NULL | NULL | NULL | YES | BTREE | |
————–+————-+———–+————-+———-+——–+——+————+———+
1 row in set (0.00 sec)

It’s important to note that indexes are a double-edged sword. Indexing every field of a table is usually unnecessary, and is quite likely to slow things down significantly when inserting or updating data because of the additional work MySQL has to do to rebuild the index each time. On the other hand, avoiding indexes altogether isn’t such a great idea either, because while this will speed up INSERTs, it will cause SELECT operations to slow down. There is thus always a trade-off to be made, and it’s wise to consider what the primary function of the table will be (data retrieval or data edit) when designing the indexing system.

#2: Optimizing query performance

When analyzing query performance, it’s also useful to consider the EXPLAIN keyword. This keyword, when placed in front of a SELECT query, describes how MySQL intends to execute the query and the number of rows it will need to process to successfully deliver a result set. To illustrate, consider the following simple example (Listing C):

Listing C


mysql> EXPLAIN SELECT city.name, city.district FROM city, country WHERE city.countrycode = country.code AND country.code = ‘IND’;
+—-+————-+———+——-+—————+———+———+——-+——+————-+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+—-+————-+———+——-+—————+———+———+——-+——+————-+
| 1 | SIMPLE | country | const | PRIMARY | PRIMARY | 3 | const | 1 | Using index |
| 1 | SIMPLE | city | ALL | NULL | NULL | NULL | NULL | 4079 | Using where |
+—-+————-+———+——-+—————+———+———+——-+——+————-+
2 rows in set (0.00 sec)

Here, the query is structured as a join between two tables and the EXPLAIN keyword describes how MySQL will process the join. It should be clear the current design will require MySQL to process only one record in the country table (which is indexed) but all 4079 records in the city table (which isn’t). This then suggests scope for improvement using other optimization tricks – for example, adding an index to the city table as follows (Listing D):

Listing D


mysql> CREATE INDEX idx_ccode ON city(countrycode);
Query OK, 4079 rows affected (0.15 sec)
Records: 4079 Duplicates: 0 Warnings: 0

And now, when you re-run the query with EXPLAIN, you’ll see a noticeable improvement (Listing E):

Listing E


mysql> EXPLAIN SELECT city.name, city.district FROM city, country WHERE city.countrycode = country.code AND country.code = ‘IND’;
+—-+————-+———+——-+—————+———–+———+——-+——+————-+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+—-+————-+———+——-+—————+———–+———+——-+——+————-+
| 1 | SIMPLE | country | const | PRIMARY | PRIMARY | 3 | const | 1 | Using index |
| 1 | SIMPLE | city | ref | idx_ccode | idx_ccode | 3 | const | 333 | Using where |
+—-+————-+———+——-+—————+———–+———+——-+——+————-+
2 rows in set (0.01 sec)

As this illustrates, MySQL now only needs to scan 333 records in the city table to produce a result set — a reduction of almost 90 percent! Naturally, this translates into faster query execution time and more efficient usage of database resources.

#3: Adjusting internal variables

MySQL is so open that it’s fairly easy to further fine-tune its default settings to obtain greater performance and stability. Some of the key variables that should be optimized are listed below.

  • Altering Index Buffer Size (key_buffer)
    This variable controls the size of the buffer used when handling table indices (both read and write operations). The MySQL manual recommends that this variable be increased “to as much as you can afford” to ensure you get the best performance on indexed tables, and recommends a value equivalent to about 25 percent of the total system memory. This is one of the more important MySQL configuration variables and if you’re interested in optimizing and improving performance, trying different values for the key_buffer_size variable is a good place to start.
  • Altering Table Buffer Size (read_buffer_size)
    When a query requires a table to be scanned sequentially, MySQL allocates a memory buffer to this query. The read_buffer_size variable controls the size of this buffer. If you find that sequential scans are proceeding slowly, you can improve performance by increasing this value, and hence the size of the memory buffer.
  • Setting The Number Of Maximum Open Tables (table_cache)
    This variable controls the maximum number of tables MySQL can have open at any one time, and thus controls the server’s ability to respond to incoming requests. This variable is closely related to the max_connections variables — increasing this value allows MySQL to keep a larger number of tables open, just as increasing max_connections increases the number of allowed connections. Consider altering this value if you have a high-volume server which receives queries on multiple different databases and tables.
  • Deciding A Time Limit For Long Queries (long_query_time)
    MySQL comes with a so-called “slow query log”, which automatically logs all queries that do not end within a particular time limit. This log is useful to track inefficient or misbehaving queries, and to find targets for optimization algorithms. The long_query_time variable controls this maximum time limit, in seconds.

The previous discussion should give you some insight into three tools you can use to analyze and optimize your SQL queries, and help you squeeze better performance out of your application. Go on and try them out — and happy optimizing!

MySQL Query Profiler

Using the New MySQL Query Profiler

One of the great things about MySQL is the superior innovation model that’s used to deliver database server software. Rather than relying solely on internal engineers who create and maintain a piece of software (as in a traditional software company), MySQL partners with the millions of active users across the world who take advantage of the open source model and daily extend the MySQL server to do new and pioneering things. These innovations can then be submitted to MySQL AB, tested, validated, and rolled into the database server so everyone can benefit from the creativity of the very active MySQL community.

An example of this model in action is the recent release of a new SQL diagnostic facility that assists in the debugging and analysis of running SQL – the SQL Profiler. The new profiler became available in the 5.0.37 version of the MySQL Community Server and was created and submitted by Jeremy Cole of Proven Scaling (http://www.provenscaling.com/).

Let’s take a look at this new diagnostic utility Jeremy developed and see how it can help you create high-performing SQL code as well as assist in troubleshooting existing queries that aren’t providing the response times you’d like.

The Best Way to Diagnose Performance Problems

When it comes to overall performance, it’s important to remember that the #1 contributor is always a good database design. The second highest contributor to performance is well-tuned SQL code. Some try and switch the two in priority, but this is a mistake because a bad design has the potential to simply drown even the best-tuned SQL code (e.g. you can’t get index access in your SQL queries if the physical index design is poorly done). But make no mistake – bad SQL code that’s introduced into an otherwise well-running database can make a real train wreck of things.

So how do you go about analyzing database performance? There are three forms of performance analysis that are used to troubleshoot and tune database systems:

  1. Bottleneck analysis – focuses on answering the questions: What is my database server waiting on; what is a user connection waiting on; what is a piece of SQL code waiting on?
  2. Workload analysis – examines the server and who is logged on to determine the resource usage and activity of each.
  3. Ratio-based analysis – utilizes a number of rule-of-thumb ratios to gauge performance of a database, user connection, or piece of code.

Of the three, bottleneck analysis is the most efficient approach in terms of fast problem resolution. By determining where the server, a user connection, or set of SQL code is spending its time, you can then work to eliminate the discovered blockages, increase throughput, and reduce overall response times. Unfortunately, this hasn’t always been easy in MySQL because the server hasn’t traditionally exposed the type of wait-based and resource statistics to quickly uncover bottlenecks.

But a better day has come along in MySQL 5.0.37 with the inclusion of the SQL Profiling utility. This interactive diagnostic aid allows a developer or DBA to gain insight into where a set of SQL code spends its time and the resources it is using. The best way to see the power of this new utility is to walk through some examples of how it’s used and see the clear benefits it supplies, so let’s do just that.

Getting started with the SQL Profiler

The SQL Profiler is built into the database server and can be dynamically enabled/disabled via the MySQL client utility. To begin profiling one or more SQL queries, simply issue the following command:

mysql> set profiling=1;
Query OK, 0 rows affected (0.00 sec)

Two things happen once you issue this command. First, any query you issue from this point on will be traced by the server with various performance diagnostics being created and attached to each distinct query. Second, a memory table named profiling is created in the INFORMATION_SCHEMA database for your particular session (not viewable by any other MySQL session) that stores all the SQL diagnostic results. This table remains persistent until you disconnect from MySQL at which point it is destroyed.

Now, simply execute a SQL query:

mysql> select count(*) from client where broker_id=2;
+----------+
| count(*) |
+----------+
|      200 |
+----------+
1 row in set (0.00 sec)

Once the query completes, you can issue the following command to view the SQL profiles that have currently been stored for you:

mysql> show profiles;
+----------+------------+-----------------------------------------------+
| Query_ID | Duration   | Query
  |
+----------+------------+-----------------------------------------------+
|        0 | 0.00007300 | set profiling=1                               |
|        1 | 0.00044700 | select count(*) from client where broker_id=2 |
+----------+------------+-----------------------------------------------+
2 rows in set (0.00 sec)

You get a quick summary of all your captured SQL plus the total duration that the query took to complete. To get the same diagnostic info, you can also query the memory table that holds your statistical information:

mysql> select sum(duration) from information_schema.profiling where query_id=1;
+---------------+
| sum(duration) |
+---------------+
|      0.000447 |
+---------------+
1 row in set (0.00 sec)

I’ll show you why it’s good to be able to query the memory-based profiling table later in this article, but for now, let’s concentrate on other SHOW commands that you can use to get more detailed diagnostic info about one or more queries that you’ve profiled. The most basic command is one that lists the steps a profiled query went through to satisfy your SQL request, along with each step’s time:

mysql> show profile for query 1;
+--------------------+------------+
| Status             | Duration   |
+--------------------+------------+
| (initialization)   | 0.00006300 |
| Opening tables     | 0.00001400 |
| System lock        | 0.00000600 |
| Table lock         | 0.00001000 |
| init               | 0.00002200 |
| optimizing         | 0.00001100 |
| statistics         | 0.00009300 |
| preparing          | 0.00001700 |
| executing          | 0.00000700 |
| Sending data       | 0.00016800 |
| end                | 0.00000700 |
| query end          | 0.00000500 |
| freeing items      | 0.00001200 |
| closing tables     | 0.00000800 |
| logging slow query | 0.00000400 |
+--------------------+------------+
15 rows in set (0.00 sec)

You can also just issue SHOW PROFILE and exclude the identification of a specific profile number to see the very last profile you created.

Regardless of how you obtain the output, you can see this data is extremely valuable in that it allows you to see where your query spends its time during execution. This is done for all types of queries, and not just SELECT statements as this example shows:

mysql> alter table t engine=myisam;
Query OK, 112050 rows affected (0.64 sec)
Records: 112050  Duplicates: 0  Warnings: 0
 
mysql> show profiles;
+----------+------------+-----------------------------------------------+
| Query_ID | Duration   | Query                                         |
+----------+------------+-----------------------------------------------+
|        0 | 0.00007300 | set profiling=1                               |
|        1 | 0.00044700 | select count(*) from client where broker_id=2 |
|        2 | 0.


00003400 | set profiling=0                               |
|        3 | 0.00007400 | set profiling=1                               |
|        4 | 0.63789700 | alter table t engine=myisam                   |
|        5 | 0.00004000 | set profiling=0                               |
+----------+------------+-----------------------------------------------+
6 rows in set (0.00 sec)
 
mysql> show profile for query 4;
+----------------------+------------+
| Status               | Duration   |
+----------------------+------------+
| (initialization)     | 0.00002900 |
| checking permissions | 0.00000800 |
| init                 | 0.00004000 |
| Opening table        | 0.00009400 |
| System lock          | 0.00000500 |
| Table lock           | 0.00000700 |
| setup                | 0.00004200 |
| creating table       | 0.00195800 |
| After create         | 0.00010900 |
| copy to tmp table    | 0.52264500 |
| rename result table  | 0.11289400 |
| end                  | 0.00004600 |
| query end            | 0.00000700 |
| freeing items        | 0.00001300 |
+----------------------+------------+
14 rows in set (0.00 sec)

So as you can see in the above profile, the ALTER TABLE statement spends the bulk of its time in the temporary table copy step. Armed with this type of information, you have more insight into the hoops your query is jumping through from start to finish, and therefore, you can then work to tune your queries to help eliminate any identified bottlenecks.

There’s more information than just duration that you can get from your profiles – for example, CPU usage (which, unfortunately, is not available on all platforms; the below comes from Linux):

mysql> show profile cpu for query 4;
+----------------------+------------+------------+------------+
| Status               | Duration   | CPU_user   | CPU_system |
+----------------------+------------+------------+------------+
| (initialization)     | 0.00002900 | 0.00000000 | 0.00000000 |
| checking permissions | 0.00000800 | 0.00000000 | 0.00000000 |
| init                 | 0.00004000 | 0.00000000 | 0.00000000 |
| Opening table        | 0.00009400 | 0.00100000 | 0.00000000 |
| System lock          | 0.00000500 | 0.00000000 | 0.00000000 |
| Table lock           | 0.00000700 | 0.00000000 | 0.00000000 |
| setup                | 0.00004200 | 0.00000000 | 0.00000000 |
| creating table       | 0.00195800 | 0.00000000 | 0.00100000 |
| After create         | 0.00010900 | 0.00000000 | 0.00000000 |
| copy to tmp table    | 0.52264500 | 0.55591600 | 0.04199300 |
| rename result table  | 0.11289400 | 0.00199900 | 0.00000000 |
| end                  | 0.00004600 | 0.00000000 | 0.00000000 |
| query end            | 0.00000700 | 0.00000000 | 0.00000000 |
| freeing items        | 0.00001300 | 0.00000000 | 0.00000000 |
+----------------------+------------+------------+------------+
14 rows in set (0.00 sec)

Other parameters that can be passed to the SHOW PROFILE command include:

  • ALL – displays all information
  • BLOCK IO – displays counts for block input and output operations
  • CONTEXT SWITCHES – displays counts for voluntary and involuntary context switches
  • IPC – displays counts for messages sent and received
  • MEMORY – is not currently implemented
  • PAGE FAULTS – displays counts for major and minor page faults
  • SOURCE – displays the names of functions from the source code, together with the name and line number of the file in which the function occurs
  • SWAPS – displays swap counts

Using the Profiler for Tuning Queries

Let’s take a look at a quick example of how the new profiler can be a help to tune an inefficient query. I don’t know about you, but I’ve always been just so-so at being able to really use EXPLAIN‘s to troubleshoot queries. But the new profiler makes things pretty nice and easy.

I have a MySQL database that’s used to track investment activity for a small brokerage house. There’s a view in the database that’s used to get a quick report of client accounts over a million dollars:

mysql> select * from v_client_portfolio_high;
+-----------+-------------------+------------------+-----------------+
| client_id | client_first_name | client_last_name | portfolio_value |
+-----------+-------------------+------------------+-----------------+
|         5 | ABNER             | ROSSELLETT       |      1252115.50 |
|       500 | CANDICE           | BARTLETT         |      1384877.50 |
+-----------+-------------------+------------------+-----------------+
2 rows in set (3.73 sec)

Now a query running under four seconds isn’t necessarily a bad thing, but I wonder if things could be made a little bit better. So let’s profile the view and see what we can discover:

mysql> set profiling=1;
Query OK, 0 rows affected (0.00 sec)
 
mysql> select * from v_client_portfolio_high;
+-----------+-------------------+------------------+-----------------+
| client_id | client_first_name | client_last_name | portfolio_value |
+-----------+-------------------+------------------+-----------------+
|         5 | ABNER             | ROSSELLETT       |      1252115.50 |
|       500 | CANDICE           | BARTLETT         |      1384877.50 |
+-----------+-------------------+------------------+-----------------+
2 rows in set (4.01 sec)
 
mysql> set profiling=0;
Query OK, 0 rows affected (0.00 sec)
 
mysql> show profiles;
+----------+------------+-----------------------------------------------+
| Query_ID | Duration   | Query                                         |
+----------+------------+-----------------------------------------------+
|        0 | 0.00007300 | set profiling=1                               |
|        1 | 0.00044700 | select count(*) from client where broker_id=2 |
|        2 | 0.00003400 | set profiling=0                               |
|        3 | 0.00007400
| set profiling=1                               |
|        4 | 0.63789700 | alter table t engine=myisam                   |
|        5 | 0.00004000 | set profiling=0                               |
|        6 | 0.00007600 | set profiling=1                               |
|        7 | 4.01965600 | select * from v_client_portfolio_high         |
|        8 | 0.00003500 | set profiling=0                               |
+----------+------------+-----------------------------------------------+

Now at first, I’m tempted to issue a SHOW PROFILE for query 7, which is my view query, but instead let’s see just how many lines of diagnostic data the profiler has collected for me:

mysql> select count(*) from information_schema.profiling where query_id=7;
+----------+
| count(*) |
+----------+
|    74734 |
+----------+

Hello! The profiler generated over 74,000 lines of output for me, which might be hard to wade through using the normal SHOW PROFILE command (even though a LIMIT option is provided). Instead, let’s use a SQL query against the profiling table to see what our query did:

mysql> select min(seq) seq,state,count(*) numb_ops,
    -> round(sum(duration),5) sum_dur, round(avg(duration),5) avg_dur,
    -> round(sum(cpu_user),5) sum_cpu, round(avg(cpu_user),5) avg_cpu
    -> from information_schema.profiling
    -> where query_id = 7
    -> group by state
    -> order by seq;
+-------+----------------------+----------+---------+---------+---------+---------+
| seq   | state                | numb_ops | sum_dur | avg_dur | sum_cpu | avg_cpu |
+-------+----------------------+----------+---------+---------+---------+---------+
|     0 | (initialization)     |        1 | 0.00004 | 0.00004 | 0.00000 | 0.00000 |
|     1 | Opening tables       |        1 | 0.00023 | 0.00023 | 0.00000 | 0.00000 |
|     2 | System lock          |        1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
|     3 | Table lock           |        1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
|     4 | checking permissions |        1 | 0.00010 | 0.00010 | 0.00000 | 0.00000 |
|     5 | optimizing           |        4 | 0.00004 | 0.00001 | 0.00000 | 0.00000 |
|     6 | statistics           |        4 | 0.00007 | 0.00002 | 0.00100 | 0.00025 |
|     7 | preparing            |        4 | 0.00005 | 0.00001 | 0.00000 | 0.00000 |
|     8 | Creating tmp table   |        1 | 0.00003 | 0.00003 | 0.00000 | 0.00000 |
|     9 | executing            |    37352 | 0.16631 | 0.00000 | 0.05899 | 0.00000 |
|    10 | Copying to tmp table |        1 | 0.00006 | 0.00006 | 0.00000 | 0.00000 |
|    15 | Sending data         |    37353 | 3.85151 | 0.00010 | 3.72943 | 0.00010 |
| 74717 | Sorting result       |        1 | 0.00112 | 0.00112 | 0.00100 | 0.00100 |
| 74719 | removing tmp table   |        2 | 0.00003 | 0.00001 | 0.00000 | 0.00000 |
| 74721 | init                 |        1 | 0.00002 | 0.00002 | 0.00000 | 0.00000 |
| 74727 | end                  |        1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
| 74728 | query end            |        1 | 0.00000 | 0.00000 | 0.00000 | 0.00000 |
| 74729 | freeing items        |        1 | 0.00002 | 0.00002 | 0.00000 | 0.00000 |
| 74730 | closing tables       |        2 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
| 74733 | logging slow query   |        1 | 0.00000 | 0.00000 | 0.00000 | 0.00000 |
+-------+----------------------+----------+---------+---------+---------+---------+

Looking at the diagnostics above, I can see that my view query spends the bulk of its time in the Sending data step, with that step and the executing step experiencing over 37,000 operations. Why would this be the case? Let’s take a look at the underlying view definition and see what the actual query looks like:

create view v_client_portfolio_high 
(
    client_id,
    client_first_name,
    client_last_name,
    portfolio_value
)
as
select  b.client_id,
        b.client_first_name,
        b.client_last_name,
       (select sum(number_of_units * price) 
from client_transaction c 
where c.action = 'buy' and 
c.client_id = b.client_id) -
(select sum(number_of_units * price) 
from client_transaction d 
where d.action = 'sell' and 
d.client_id = b.client_id) portfolio_value
from    client_transaction a,
        client b
where   a.client_id = b.client_id 
group by b.client_id,
        b.client_first_name,
        b.client_last_name
having portfolio_value > 1000000

The view does some normal column grabs from the underlying base tables, but then uses some inline views to calculate a client’s overall portfolio value. The inline views/subselects are obviously what’s causing the large number of data sends and executions. Let’s eliminate just one of the subselects by pulling it up into the main query and if that makes a difference. We’ll drop and recreate the view (with a little clean up on NULL values that may affect the computed outcome), profile the new view’s performance, and then examine the diagnostic output:

mysql> drop view v_client_portfolio_high;
Query OK, 0 rows affected (0.00 sec)
 
mysql> create view v_client_portfolio_high
    -> (
    ->     client_id,
    ->     client_first_name,
    ->     client_last_name,
    ->     portfolio_value
    -> )
    -> as
    -> select  b.client_id,
    ->  b.client_first_name,
    ->  b.client_last_name,
    ->  sum(number_of_units * price)  -
    ->  case
    ->          (select sum(number_of_units * price)
    ->          from client_transaction d
    ->          where d.action = 'sell' and
    ->          d.client_id = b.client_id)
    ->  when NULL then 0
    ->  else
    ->
         (select sum(number_of_units * price)
    ->          from client_transaction d
    ->          where d.action = 'sell' and
    ->          d.client_id = b.client_id)
    ->  end portfolio_value
    -> from    client_transaction a,
    ->  client b
    -> where   a.client_id = b.client_id and
    ->  action = 'buy'
    -> group    by b.client_id,
    ->  b.client_first_name,
    ->  b.client_last_name
    -> having   portfolio_value > 1000000;
Query OK, 0 rows affected (0.00 sec)
 
mysql> set profiling=1;
Query OK, 0 rows affected (0.00 sec)
 
mysql> select * from v_client_portfolio_high;
+-----------+-------------------+------------------+-----------------+
| client_id | client_first_name | client_last_name | portfolio_value |
+-----------+-------------------+------------------+-----------------+
|         5 | ABNER             | ROSSELLETT       |      1252115.50 |
|       500 | CANDICE           | BARTLETT         |      1384877.50 |
+-----------+-------------------+------------------+-----------------+
2 rows in set (0.47 sec)
 
mysql> set profiling=0;
Query OK, 0 rows affected (0.00 sec)
 
mysql> show profiles;
+----------+------------+-----------------------------------------------+
| Query_ID | Duration   | Query                                         |
+----------+------------+-----------------------------------------------+
|        0 | 0.00007300 | set profiling=1                               |
|        1 | 0.00044700 | select count(*) from client where broker_id=2 |
|        2 | 0.00003400 | set profiling=0                               |
|        3 | 0.00007400 | set profiling=1                               |
|        4 | 0.63789700 | alter table t engine=myisam                   |
|        5 | 0.00004000 | set profiling=0                               |
|        6 | 0.00007600 | set profiling=1                               |
|        7 | 4.01965600 | select * from v_client_portfolio_high         |
|        8 | 0.00003500 | set profiling=0                               |
|        9 | 0.00007500 | set profiling=1                               |
|       10 | 0.45292700 | select * from v_client_portfolio_high         |
|       11 | 0.00003800 | set profiling=0                               |
+----------+------------+-----------------------------------------------+
12 rows in set (0.00 sec)
 
mysql> select min(seq) seq,state,count(*) numb_ops,
    -> round(sum(duration),5) sum_dur, round(avg(duration),5) avg_dur,
    -> round(sum(cpu_user),5) sum_cpu, round(avg(cpu_user),5) avg_cpu
    -> from infor


mation_schema.profiling
    -> where query_id = 10
    -> group by state
    -> order by seq;
+-------+----------------------+----------+---------+---------+---------+---------+
| seq   | state                | numb_ops | sum_dur | avg_dur | sum_cpu | avg_cpu |
+-------+----------------------+----------+---------+---------+---------+---------+
|     0 | (initialization)     |        1 | 0.00004 | 0.00004 | 0.00000 | 0.00000 |
|     1 | Opening tables       |        1 | 0.00024 | 0.00024 | 0.00000 | 0.00000 |
|     2 | System lock          |        1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
|     3 | Table lock           |        1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
|     4 | checking permissions |        1 | 0.00012 | 0.00012 | 0.00100 | 0.00100 |
|     5 | optimizing           |        4 | 0.00005 | 0.00001 | 0.00000 | 0.00000 |
|     6 | statistics           |        4 | 0.00007 | 0.00002 | 0.00000 | 0.00000 |
|     7 | preparing            |        4 | 0.00005 | 0.00001 | 0.00000 | 0.00000 |
|     8 | Creating tmp table   |        1 | 0.00003 | 0.00003 | 0.00000 | 0.00000 |
|     9 | executing            |    11194 | 0.04983 | 0.00000 | 0.01800 | 0.00000 |
|    10 | Copying to tmp table |        1 | 0.00008 | 0.00008 | 0.00000 | 0.00000 |
|    15 | Sending data         |    11195 | 0.39853 | 0.00004 | 0.36794 | 0.00003 |
| 22401 | Sorting result       |        1 | 0.00375 | 0.00375 | 0.00400 | 0.00400 |
| 22403 | removing tmp table   |        2 | 0.00005 | 0.00002 | 0.00000 | 0.00000 |
| 22405 | init                 |        1 | 0.00002 | 0.00002 | 0.00000 | 0.00000 |
| 22411 | end                  |        1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
| 22412 | query end            |        1 | 0.00000 | 0.00000 | 0.00000 | 0.00000 |
| 22413 | freeing items        |        1 | 0.00002 | 0.00002 | 0.00000 | 0.00000 |
| 22414 | closing tables       |        2 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
| 22417 | logging slow query   |        1 | 0.00000 | 0.00000 | 0.00000 | 0.00000 |
+-------+----------------------+----------+---------+---------+---------+---------+
20 rows in set (0.44 sec)

Much better! Although more tuning on the view can likely be done, this simple change has knocked the Sending data and the executing step counts down by over two-thirds, with the end result being an 88% reduction in overall response time. The profiler was very useful in this case as this particular query shows that even though an individual step in the SQL execution process may be handled very quickly (the average duration column in the above query), having that same step executed over and over again can put a major dent in total query performance.

Some Last Thoughts on the Profiler

Here are some other things to keep in mind when using the new SQL profiler:

Profiling is initially turned off for each session.

By default, you can store 15 different query profiles for your session. You can increase this up to 100 by setting the profiling_history_size session variable. Certain diagnostics rely on operating system support for the getrusage() system call, so you may see NULL values for some statistics if you’re on a platform that doesn’t support this function.

There were a few bugs in the initial release of the profiler. The first centered around a problem that developed if you issued a SHOW PROFILES command before enabling profiling. Another concerned duration statistics that were not accurately paired up for each SQL execution step. All these have been fixed now and will be in the next Community server source drop and binary.

For more information on the SQL profiler, you can review the documentation found in the MySQL 5.0 manual at: http://dev.mysql.com/doc/refman/5.0/en/show-profiles.html.

The new SQL profiler is a nice addition to the DBA’s and developer’s toolbelt and is a great example of the vibrant MySQL Community (in this cas

e, Jeremy Cole) in action. I can’t wait to see what they come up with next!