mysql profiling

this is my first post about profiling, so we need to understand what is profiling (performance analysis)?

In software engineering, performance analysis (a field of dynamic program analysis) is the investigation of a program's behavior using information gathered as the program runs, as opposed to static code analysis. The usual goal of performance analysis is to determine which parts of a program to optimize for speed or memory usage.

full article you can find at mysql documentation, here i'll just overview it.

profiling gives us option to understand on timeline our queries, to see resource usage for executed statements. SHOW PROFILES and SHOW PROFILE were added in MySQL 5.0.37 (that's important!).

Profiling is controlled by the profiling session variable, which has a default value of 0 (OFF). Profiling is enabled by setting profiling to 1 or ON.

mysql> SELECT @@profiling;
+-------------+
| @@profiling |
+-------------+
|           0 |
+-------------+
1 row in set (0.00 sec)

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

mysql> DROP TABLE IF EXISTS t1;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> CREATE TABLE T1 (id INT);
Query OK, 0 rows affected (0.01 sec)

mysql> SHOW PROFILES;
+----------+----------+--------------------------+
| Query_ID | Duration | Query                    |
+----------+----------+--------------------------+
|        0 | 0.000088 | SET PROFILING = 1        |
|        1 | 0.000136 | DROP TABLE IF EXISTS t1  |
|        2 | 0.011947 | CREATE TABLE t1 (id INT) |
+----------+----------+--------------------------+
3 rows in set (0.00 sec)

mysql> SHOW PROFILE;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| checking permissions | 0.000040 |
| creating table       | 0.000056 |
| After create         | 0.011363 |
| query end            | 0.000375 |
| freeing items        | 0.000089 |
| logging slow query   | 0.000019 |
| cleaning up          | 0.000005 |
+----------------------+----------+
7 rows in set (0.00 sec)

mysql> SHOW PROFILE FOR QUERY 1;
+--------------------+----------+
| Status             | Duration |
+--------------------+----------+
| query end          | 0.000107 |
| freeing items      | 0.000008 |
| logging slow query | 0.000015 |
| cleaning up        | 0.000006 |
+--------------------+----------+
4 rows in set (0.00 sec)

mysql> SHOW PROFILE CPU FOR QUERY 2;
+----------------------+----------+----------+------------+
| Status               | Duration | CPU_user | CPU_system |
+----------------------+----------+----------+------------+
| checking permissions | 0.000040 | 0.000038 |   0.000002 |
| creating table       | 0.000056 | 0.000028 |   0.000028 |
| After create         | 0.011363 | 0.000217 |   0.001571 |
| query end            | 0.000375 | 0.000013 |   0.000028 |
| freeing items        | 0.000089 | 0.000010 |   0.000014 |
| logging slow query   | 0.000019 | 0.000009 |   0.000010 |
| cleaning up          | 0.000005 | 0.000003 |   0.000002 |
+----------------------+----------+----------+------------+
7 rows in set (0.00 sec)

Here is SQL queries that you need to know:

SELECT @@profiling;

SET profiling = 1;
SET profiling = 0;

SHOW PROFILES;
SHOW PROFILE;
SHOW PROFILE FOR QUERY 1;

/* displays all information */
SHOW PROFILE ALL FOR QUERY 1;
/* displays counts for block input and output operations */
SHOW PROFILE BLOCK IO FOR QUERY 1;
/* displays counts for voluntary and involuntary context switches */
SHOW PROFILE CONTEXT SWITCHES FOR QUERY 1;
/* displays user and system CPU usage times */
SHOW PROFILE CPU FOR QUERY 1;
/* displays counts for messages sent and received */
SHOW PROFILE IPC FOR QUERY 1;
/* displays counts for major and minor page faults */
SHOW PROFILE PAGE FAULTS FOR QUERY 1;
/* displays the names of functions from the source code, together with the name and line number of the file in which the function occurs */
SHOW PROFILE SOURCE FOR QUERY 1;
/* displays swap counts */
SHOW PROFILE SWAPS FOR QUERY 1;