Use the show profile command to analyze performance in Mysql collation _mysql

Show profile was donated by Jeremy Cole to the MySQL community version. The default is off, but the session level can turn on this feature. Opening it allows MySQL to collect the resources that are used when executing the statement. For statistical statements, set the profiling to 1.

mysql> SET profiling = 1;

After you 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 DES C;
...
997 rows in Set (0.03 sec)

The profiling information for this execution statement is stored in this session. Use show profiles for viewing.

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 parsed data that has been stored. If you do not add parameters, the status is displayed and the duration of their duration.

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 that column and show full processlist should be the same.
This value is derived from the Thd->proc_info variable. So the value you're looking at is directly from within MySQL. Although these values are straightforward, you can also view the MySQL manual.

You can give show profiles a query_id to view the specified statement, and you can add a new column to the output. For example, view user and CPU usage. You can use the following command.

Mysql> Show Profiles CPU for QUERY 1;

Show profile can drill down into the work of the server executing the statement. And also helps you to understand the time consuming of executing statements. Some limitations are functions that it does not implement, cannot view and parse other connected statements, and the consumption caused by profiling.

Show profiles shows the most recent statements sent to the server, the number of bars is defined according to the session variable Profiling_history_size, the default is 15, the maximum is 100. Set to 0 is equivalent to turning off the profiling feature.

Show profiles for QUERY N, where n is the query_id corresponding to 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 tab Les1  |
| 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 profiles for QUERY 2; 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 |
| | | 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 |
| | |   0.000057 |
| closing tables  | 0.000061 |
| freeing items
   
    | 0.000080 |
| Logging Slow Query  | 0.000056 |
| logging slow Query  | 0.000098 |
| cleaning up   | 0.000059 |
    
     +------------------------------+-----------+ rows in Set (0.00 sec) 
    
   

If you do not specify for QUERY, the information for the most recent statement is printed.

The use of the Limit section is consistent with the limit clause in select, not to repeat.

Type is optional, and the range of values can be as follows:

• All Display performance Information
• Block IO shows the number of blocks IO operations
• Context switches shows the number of contextual switches, whether active or passive
• CPU time and system CPU time
• IPC displays the number of messages sent and received
• MEMORY [temporarily not implemented]
• Page faults display number of pages errors
• Source displays the name and location of the function in the source code
• SWAPS the number of swap shows

Cases:

Mysql> Show Profiles 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 |
 +------------------------------+-----------+----------+------------+ rows in Set (0.00 sec)

Ps:
Show profiles all for QUERY 2 can also be obtained by using the SELECT * from information_schema.profiling WHERE query_id = 2 order by seq;

Scope of Action
This command only works within this session, that is, you cannot parse statements outside of this session.

When profiling is turned on, all the statements in this session are parsed (even including the execution of the wrong statement), except for show profile and show profiles.

Application Example: Use show profile to analyze the performance advantages of a query cache hit.

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 query caching is enabled, the same query (not a partitioned table) can be hit directly in the query cache.

Mysql> Select COUNT (1) as CNT from tran_excution;

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

Mysql> Show Profiles 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 | +--------------------------------+----------+-----------------------+---------------+-------------+ rows in Set
 (0.00 sec)

Mysql> Show Profiles 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

can clearly see the cache hit, greatly saving the overhead of the background. Of course, the use of caching also needs to be based on a variety of scenarios (table data size, update frequency, etc.) to use, not enable caching will certainly improve query efficiency. This is just an example of an application of show profile.