MySQL USES the SHOW PROFILE command to analyze the usage collation of performance

  • 2020-11-20 06:17:44
  • OfStack

show profile was donated by Jeremy Cole to the MySQL community version. It is turned off by default, but can be turned on at the session level. Turning it on allows MySQL to collect the resources used when executing statements. For statistical purposes, set profiling to 1


mysql> SET profiling = 1;


Then run 1 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 for this execution statement is stored in the session. View using SHOW PROFILES.


mysql> SHOW PROFILES\G

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


You can use the SHOW PROFILE statement to get the profiling data that has been stored. If no parameters are added, the states and how long they last 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 line is a process of state change and how long they last. Status column 1 and SHOW FULL PROCESSLIST State should be 1.
This value comes from thd- > proc_info variables. So the value you're looking at is directly from within MySQL. Although the Numbers are straightforward, you can also check out the MySQL manual.

You can assign SHOW PROFILES an Query_ID to view the specified statement, and you can add new columns to the output. For example, view user and CPU use. You can use the following command.


mysql> SHOW PROFILE CPU FOR QUERY 1;


SHOW PROFILE can drill down to see how the server executes statements. And can also help you understand the time it takes to execute a statement. Some limitations are the functionality it does not implement, the inability to view and parse statements for other connections, and the cost of parsing.

SHOW PROFILES displays the number of statements recently sent to the server, defined by the session variable profiling_history_size. The default is 15, with a maximum of 100. Setting it to 0 is equivalent to turning off analysis.

SHOW PROFILE FOR QUERY n, where n corresponds to Query_ID in the output of SHOW PROFILES.


Such as:


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; # To view alter table table1 drop column c3 The analysis of the 

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)
0

If FOR QUERY is not specified, output the information for the last statement.

The usage of section LIMIT is the same as LIMIT clause 1 in SELECT and is not repeated.

type is optional and the value range can be as follows:

ALL displays all performance information BLOCK IO Display block IO number of operations CONTEXT SWITCHES displays the number of context switches, whether active or passive CPU shows user CPU time and system CPU time IPC shows the number of messages sent and received MEMORY [not yet implemented] PAGE FAULTS displays the number of page errors SOURCE displays the function name and location in the source code SWAPS shows the number of SWAP

Ex. :


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)
1

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)
2

ps:
SHOW PROFILE ALL FOR QUERY 2; profiling query_id = 2 ORDER BY seq FROM information_schema.profiling WHERE = 2 ORDER BY seq To obtain.

scope
This command only works within the session, meaning that statements outside the session cannot be analyzed.

With analysis enabled, all the statements in this session are analyzed (even the ones that executed the wrong ones), except for SHOW PROFILE and SHOW PROFILES themselves.

Application example: Use SHOW PROFILE to analyze the performance benefits of query cache hits.


mysql> set profiling=1;

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)
4



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)
5

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)
6

Because query caching is enabled, the same query (non-partitioned table) can be hit directly in the query cache.


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)
7

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


mysql> show profile source for query 1;

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)
9



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)

When you can clearly see hits in the cache, you save a lot of overhead in the background. Of course, the use of caching also needs to be examined according to various scenarios (table data size, update frequency, etc.), which does not necessarily improve query efficiency by enabling caching. This is just one example of SHOW PROFILE.


Related articles: