Wednesday, December 17, 2008

MySQL Profiling: SQL Tuning

MySQL provides a number of different tools for tuning SQL statements. Some of the key SQL tuning tools include:
  • EXPLAIN - Displays execution plans generated by the MySQL Cost Based Optimizer.
  • Status Variables - Contains statistics on SQL run time activity.
  • Profiling - Contains run time statistics on each phase in the execution of individual SQL statements.
Main Phases in Processing a SQL Statement

Profiling allows access to very detailed run time statistics on each phase of processing a SQL command. The main phases include:
  • Parsing the SQL statement.
  • Generating an execution plan.
  • Performing an execution and fetch.
  • Cleaning up resources.
Profiling Benefits

Profiling provides the following benefits:
  • Ability to understand time spent in each phase of processing a SQL command.
  • Displays if the OS performed a disk read because the requested block is not in memory.
  • The number of waits that occurred while the thread processed the SQL command.
  • Disk activity generated by the SQL statement.
  • Resources allocated for processing the SQL command.
  • Approximations of time required to process each step of the SQL statement.
  • Comparision of execution times relative to other SQL statements.
  • If you're into the source code, each C function and line number where it is executed for each step of processing the SQL statement.

Profiling Resources in MySQL

The profiling resources available beginning in MySQL 5.1.28 include:
  • SHOW PROFILE command.
  • SHOW PROFILES command.
  • Information_schema.profiling table.

Turning Profiling ON

Profiling is turned OFF (0) by default. Profiling is turned ON (1) at the session level. The PROFILING_HISTORY_SIZE parameter is used to determine how many statements are kept in the history. The default is 15 statements. The query id will change for each SQL statement executed in a session.

mysql> SET PROFILING=1;


SHOW PROFILES

The SHOW PROFILES command will display the query id, the duration and the SQL command executed.

mysql> SHOW PROFILES;
+----------+------------+------------------------------------------------------
| Query_ID | Duration | Query
+----------+------------+--------------------------------------------------------
| 1 | 0.00073900 | SELECT Co.Name, Ci.Name, Ci.Population FROM CountryList Co, CityList Ci WHERE Co.Code = Ci.CountryCode AND Ci.Population > 8000000 |
| 2 | 0.00086100 | SELECT query_id, seq,state, duration, source_function FROM information_schema.profiling WHERE query_id = 1 |
...


SHOW PROFILE
SHOW PROFILE [type [, type] ... ]
[FOR QUERY n]
[LIMIT row_count [OFFSET offset]]

type:
ALL
| BLOCK IO
| CONTEXT SWITCHES
| CPU
| IPC
| MEMORY
| PAGE FAULTS
| SOURCE
| SWAPS

mysql> SHOW PROFILE FOR QUERY 3;
+--------------------+----------+
| Status | Duration |
+--------------------+----------+
| starting | 0.000091 |
| freeing items | 0.000040 |
| logging slow query | 0.000007 |
| cleaning up | 0.000007 |
+--------------------+----------+
4 rows in set (0.00 sec)

INFORMATION_SCHEMA.PROFILING

There are much more interersting queries you can get out of this database object, but this simple query fits in the blog eaily and provides a hint of detailed information available.

mysql> SELECT query_id, duration, state
FROM information_schema.profiling WHERE query_id = 8;
+----------+----------+--------------------+
| query_id | duration | state |
+----------+----------+--------------------+
| 8 | 0.000100 | starting |
| 8 | 0.000068 | Opening tables |
| 8 | 0.000008 | System lock |
| 8 | 0.000013 | Table lock |
| 8 | 0.000028 | init |
| 8 | 0.000015 | optimizing |
| 8 | 0.000016 | statistics |
| 8 | 0.000017 | preparing |
| 8 | 0.001850 | executing |
| 8 | 0.000162 | Sending data |
| 8 | 0.000008 | end |
| 8 | 0.000006 | query end |
| 8 | 0.000069 | freeing items |
| 8 | 0.000034 | removing tmp table |
| 8 | 0.000007 | closing tables |
| 8 | 0.000005 | logging slow query |
| 8 | 0.000007 | cleaning up |
+----------+----------+--------------------+
17 rows in set (0.01 sec)

Thoughts on Profiling

The profiling feature needs to mature more in MySQL, yet this early implementation does provide information that can be useful for evaluating SQL statements. Combining profile information, thread information and session state information together provides different perspectives into the evaluation of SQL processing.

2 comments:

Anonymous said...

Thanks for writing this. It was an interesting read.

Anonymous said...

Thanks for showing us how to use it.