Using the SHOWPROFILE command in MySQL to analyze performance usage _ MySQL

This article describes how to use the showprofile command in MySQL to analyze performance. showprofiles is a common command for database performance optimization, for more information, see how to donate the show profile to the MySQL community by Jeremy Cole. This feature is disabled by default, but can be enabled at the session level. Enabling It allows MySQL to collect resources used during statement execution. Set profiling to 1 for statistical reports

mysql> SET profiling = 1;

Then run a query

mysql> SELECT COUNT(DISTINCT actor.first_name) AS cnt_name, COUNT(*) AS cnt-> FROM sakila.film_actor-> INNER JOIN sakila.actor USING(actor_id)-> GROUP BY sakila.film_actor.film_id-> ORDER BY cnt_name DESC;...997 rows in set (0.03 sec)

The profiling information of the executed statement is stored in this session. Use show profiles for viewing.

mysql> SHOW PROFILES\G

*************************** 1. row ***************************Query_ID: 1Duration: 0.02596900Query: SELECT COUNT(DISTINCT actor.first_name) AS cnt_name,...

You can use the show profile statement to obtain the stored profiling data. If no parameter is added, the status and duration are displayed.

mysql> SHOW PROFILE;

+------------------------+-----------+| Status | Duration |+------------------------+-----------+| (initialization) | 0.000005 || Opening tables | 0.000033 || System lock | 0.000037 || Table lock | 0.000024 || init | 0.000079 || optimizing | 0.000024 || statistics | 0.000079 || preparing | 0.00003 || Creating tmp table | 0.000124 || executing | 0.000008 || Copying to tmp table | 0.010048 || Creating sort index | 0.004769 || Copying to group table | 0.0084880 || Sorting result | 0.001136 || Sending data | 0.000925 || end | 0.00001 || removing tmp table | 0.00004 || end | 0.000005 || removing tmp table | 0.00001 || end | 0.000011 || query end | 0.00001 || freeing items | 0.000025 || removing tmp table | 0.00001 || freeing items | 0.000016 || closing tables | 0.000017 || logging slow query | 0.000006 |+------------------------+-----------+

Each row is a process of state change and their duration. The Status column should be consistent with the show full processlist State.
The value is from the thd-> proc_info variable. Therefore, the value you view is directly from within MySQL. Even though these values are easy to understand, you can view the MySQL manual.

You can specify Query_ID for show profiles to view the specified statement and add a new column to the output. For example, view the user and CPU usage. Run the following command.

mysql> SHOW PROFILE CPU FOR QUERY 1;

Show profile allows you to thoroughly view the execution status of statements on the server. It also helps you understand the time consumed by executing statements. Some restrictions are that it does not implement the function, and it cannot view and analyze other connected statements, as well as the consumption caused by analysis.

Show profiles displays multiple statements recently sent to the server. the number of statements is defined according to the session variable profiling_history_size. the default value is 15 and the maximum value is 100. Setting 0 is equivalent to disabling the analysis function.

Show profile for query n, where n corresponds to Query_ID in the show profiles output.

For example:

mysql> show profiles;

+----------+-------------+---------------------------------------+| Query_ID | Duration | Query     |+----------+-------------+---------------------------------------+| 1 | 0.00037700 | alter table table1 drop column c3 int || 2 | 70.37123800 | alter table table1 drop column c3 || 3 | 0.00124500 | show tables    || 4 | 0.00569800 | select * from table1 where id=2 || 5 | 0.00068500 | select count(1) from tables1  || 6 | 0.00197900 | select count(1) from table1  || 7 | 0.00105900 | alter table tables1 drop c1  || 8 | 0.00800200 | alter table table1 drop c1  |+----------+-------------+---------------------------------------+8 rows in set (0.00 sec)

Mysql> show profile for query 2; # view the analysis of alter table table1 drop column c3

+------------------------------+-----------+| Status   | Duration |+------------------------------+-----------+| starting   | 0.000183 || checking permissions  | 0.000057 || checking permissions  | 0.000059 || init    | 0.000060 || Opening tables  | 0.000071 || System lock   | 0.000062 || setup   | 0.000080 || creating table  | 0.005052 || After create   | 0.000220 || copy to tmp table  | 0.000244 || rename result table  | 70.364027 || end    | 0.000575 || Waiting for query cache lock | 0.000062 || end    | 0.000075 || query end   | 0.000057 || closing tables  | 0.000061 || freeing items  | 0.000080 || logging slow query  | 0.000056 || logging slow query  | 0.000098 || cleaning up   | 0.000059 |+------------------------------+-----------+20 rows in set (0.00 sec)

If for query is not specified, the information of the last statement is output.

The use of the LIMIT part is the same as that of the LIMIT clause in the SELECT statement.

Type is optional and the value range is as follows:

• ALL show ALL performance information
• Block io displays the number of block io operations
• Context switches: displays the number of context switches, whether active or passive.
• CPU displays the user's CPU time and system CPU time
• IPC displays the number of messages sent and received
• MEMORY [not implemented yet]
• Page faults display PAGE error count
• SOURCE: displays the function name and position in the SOURCE code.
• Number of SWAPS displayed

Example:

mysql> show profile cpu for query 2;

+------------------------------+-----------+----------+------------+| Status   | Duration | CPU_user | CPU_system |+------------------------------+-----------+----------+------------+| starting   | 0.000183 | 0.000000 | 0.000000 || checking permissions  | 0.000057 | 0.000000 | 0.000000 || checking permissions  | 0.000059 | 0.000000 | 0.000000 || init    | 0.000060 | 0.000000 | 0.000000 || Opening tables  | 0.000071 | 0.000000 | 0.000000 || System lock   | 0.000062 | 0.000000 | 0.000000 || setup   | 0.000080 | 0.000000 | 0.001000 || creating table  | 0.005052 | 0.003000 | 0.001000 || After create   | 0.000220 | 0.000000 | 0.000000 || copy to tmp table  | 0.000244 | 0.000000 | 0.000000 || rename result table  | 70.364027 | 7.470864 | 41.612674 || end    | 0.000575 | 0.000000 | 0.001000 || Waiting for query cache lock | 0.000062 | 0.000000 | 0.000000 || end    | 0.000075 | 0.000000 | 0.000000 || query end   | 0.000057 | 0.000000 | 0.000000 || closing tables  | 0.000061 | 0.000000 | 0.000000 || freeing items  | 0.000080 | 0.000000 | 0.000000 || logging slow query  | 0.000056 | 0.000000 | 0.000000 || logging slow query  | 0.000098 | 0.000000 | 0.000000 || cleaning up   | 0.000059 | 0.000000 | 0.000000 |+------------------------------+-----------+----------+------------+20 rows in set (0.00 sec)

Ps:
The show profile all for query 2; information can also be obtained through SELECT * FROM information_schema.profiling WHERE query_id = 2 order by seq.

Scope
This command only works in this session, that is, it cannot analyze statements outside this session.

After the analysis function is enabled, all the statements in this session are analyzed (even including statements with incorrect execution), except the show profile and show profiles statements.

Application example: use show profile to analyze the performance advantages of cache hits.

mysql> set profiling=1;

Query OK, 0 rows affected (0.00 sec)

mysql> select count(1) as cnt from tran_excution;

+-------+| cnt |+-------+| 14225 |+-------+1 row in set (0.00 sec)

Because the query cache has been enabled, the same query (non-partition table) can be directly hit in the query cache.

mysql> select count(1) as cnt from tran_excution;

Let's take a closer look at the analysis of two identical statements.

mysql> show profile source for query 1;

+--------------------------------+----------+-----------------------+---------------+-------------+| Status    | Duration | Source_function | Source_file | Source_line |+--------------------------------+----------+-----------------------+---------------+-------------+| starting   | 0.000048 | NULL   | NULL  | NULL || Waiting for query cache lock | 0.000013 | try_lock  | sql_cache.cc |  454 || checking query cache for query | 0.000040 | send_result_to_client | sql_cache.cc | 1561 || checking permissions  | 0.000023 | check_access  | sql_parse.cc | 4751 || Opening tables   | 0.000040 | open_tables  | sql_base.cc | 4831 || System lock   | 0.000020 | mysql_lock_tables | lock.cc |  299 || Waiting for query cache lock | 0.000037 | try_lock  | sql_cache.cc |  454 || init    | 0.000020 | mysql_select  | sql_select.cc | 2579 || optimizing   | 0.000015 | optimize  | sql_select.cc |  865 || statistics   | 0.000017 | optimize  | sql_select.cc | 1056 || preparing   | 0.000016 | optimize  | sql_select.cc | 1078 || executing   | 0.000015 | exec   | sql_select.cc | 1836 || Sending data   | 0.003875 | exec   | sql_select.cc | 2380 || end    | 0.000018 | mysql_select  | sql_select.cc | 2615 || query end   | 0.000015 | mysql_execute_command | sql_parse.cc | 4440 || closing tables   | 0.000016 | mysql_execute_command | sql_parse.cc | 4492 || freeing items   | 0.000016 | mysql_parse  | sql_parse.cc | 5640 || Waiting for query cache lock | 0.000012 | try_lock  | sql_cache.cc |  454 || freeing items   | 0.000032 | NULL   | NULL  | NULL || Waiting for query cache lock | 0.000017 | try_lock  | sql_cache.cc |  454 || freeing items   | 0.000016 | NULL   | NULL  | NULL || storing result in query cache | 0.000017 | end_of_result  | sql_cache.cc | 1020 || logging slow query  | 0.000018 | log_slow_statement | sql_parse.cc | 1461 || logging slow query  | 0.000050 | log_slow_statement | sql_parse.cc | 1470 || cleaning up   | 0.000018 | dispatch_command | sql_parse.cc | 1417 |+--------------------------------+----------+-----------------------+---------------+-------------+25 rows in set (0.00 sec)

mysql> show profile source for query 2;

+--------------------------------+----------+-----------------------+--------------+-------------+| Status    | Duration | Source_function | Source_file | Source_line |+--------------------------------+----------+-----------------------+--------------+-------------+| starting   | 0.000051 | NULL   | NULL  | NULL || Waiting for query cache lock | 0.000014 | try_lock  | sql_cache.cc |  454 || checking query cache for query | 0.000016 | send_result_to_client | sql_cache.cc | 1561 || checking privileges on cached | 0.000013 | send_result_to_client | sql_cache.cc | 1652 || checking permissions  | 0.000015 | check_access  | sql_parse.cc | 4751 || sending cached result to clien | 0.000036 | send_result_to_client | sql_cache.cc | 1749 || logging slow query  | 0.000017 | log_slow_statement | sql_parse.cc | 1461 || cleaning up   | 0.000018 | dispatch_command | sql_parse.cc | 1417 |+--------------------------------+----------+-----------------------+--------------+-------------+8 rows in set (0.00 sec)

The cache hit is clearly displayed, which greatly saves the background overhead. Of course, the use of cache also needs to be tested and used based on various scenarios (table data size, update frequency, etc.). without enabling cache, the query efficiency will certainly be improved. This is only an application example of show profile.