MySQLSQL profiling (SQLprofile) _ MySQL

Analyzing SQL execution overhead is an important means to optimize SQL. In MySQL databases, you can configure the profiling parameter to enable SQL profiling. This parameter can be set at the global and session level. The global level applies to the entire MySQL instance, and the session level closely affects the overhead of SQL execution, which is an important means to optimize SQL. In MySQL databases, you can configure the profiling parameter to enable SQL profiling. This parameter can be set at the global and session level. The global level applies to the entire MySQL instance, while the session level closely affects the current session. After this parameter is enabled, subsequent SQL statements record their resource overhead, such as IO, context switching, CPU, and Memory. Based on these overhead, the current SQL bottleneck is further analyzed for optimization and adjustment. This document describes how to use the MySQL profile without a specific sample analysis.

1. profile description

-- Root @ localhost [sakila]> show variables like 'version '; + --------------- + kernel + | Variable_name | Value | + --------------- + kernel + | version | 5.6.17-enterprise-internal cial-advanced | + --------------- + kernel + -- view the profiling system variable root @ localhost [sakila]> show variables like '% profil % '; + ------------------------ + ------- + | Variable_name | Value | + ---------------------- + ------- + | have_profiling | YES | -- Read-only variable, used to control whether profiling is enabled or disabled by system variables | profiling | OFF | -- enable SQL statement profiling | profiling_history_size | 15 | -- set the number of profiling retained. the default value is 15, the range is 0 to 100. If it is 0, profiling + ---------------------- + ------- + profiling [539] If set to 0 or OFF (the default), statement profiling is disabled. if set to 1 or ON, statement prof_enabled and the show profile and show profiles statements provide access to profinformation. see Section 13.7.5.32, "show profiles Syntax ". this variable is deprecated in MySQL 5.6.8 and will be removed in a future MySQL release. profiling_history_size [539] The number of statements for which to maintain profiling information if profiling [539] isenabled. the default value is 15. the maximum value is 100. setting the value to 0 when tivelydisables profiling. see Section 13.7.5.32, "show profiles Syntax ". this variable is deprecated in MySQL 5.6.8 and will be removed in a future MySQL release. -- get the profile help root @ localhost [sakila]> help profile; Name: 'Show PROFILE 'Description: Syntax: show profile [type [, type]...] [for query n] [LIMIT row_count [OFFSET offset] type: ALL -- display ALL overhead information | block io -- Display block io overhead | context switches -- CONTEXT switch overhead | CPU -- display CPU overhead information | IPC -- display sending and receiving overhead information | MEMORY -- display MEMORY overhead information | page faults -- display PAGE error overhead information | SOURCE -- Display and Source_function, source_file, Source_line-related overhead information | SWAPS -- display The show profile and show profiles statements display profilinginformation that indicates resource usage for statements executedduring the course of the current session. * Note *: These statements are deprecated as of MySQL 5.6.7 and will beremoved in a future MySQL release. use the Performance Schema instead; see http://dev.mysql.com/doc/refman/5.6/en/performance-schema.html.-- As described above, this command will be removed from 5.6.7 and replaced with Performance Schema instead. in Oracle databases, autotrace is used to analyze a single SQL statement and obtain the actual execution plan and overhead information.

2. enable porfiling

-- Enable session-level profilingroot @ localhost [sakila]> set profiling = 1; Query OK, 0 rows affected, 1 warning (0.00 sec) -- verify the modified result root @ localhost [sakila]> show variables like '% profil % '; + statement + ------- + | Variable_name | Value | + ------------------------ + ------- + | have_profiling | YES | profiling | ON | profiling_history_size | 15 | + statement + ------- + -- publish SQL query root @ localhost [sakila]> select count (*) from customer; + ---------- + | count (*) | + ---------- + | 599 | + ---------- + -- View all generated profileroot @ localhost [sakila]> show profiles in the current session; + ---------- + ------------ + response + | Query_ID | Duration | Query | + ---------- + ------------ + -------------------------------- + | 1 | 0.00253600 | show variables like '% profil %' | 2 | 0.00138150 | select count (*) from customer | + ---------- + ------------ + -------------------------------- + 2 rows in set, 1 warning (0.01 sec) -- we can see that there are 2 warning, the previous one, now a root @ localhost [sakila]> show warnings; -- The following results indicate that show profiles will be replaced by Performance Schema in the future + --------- + ------ + tables + | Level | Code | Message | + --------- + ------ + tables + | Warning | 1287 | 'show profiles' is deprecated and will be removed in a future release. please use Performance Schema instead | + --------- + ------ + Region +

3. obtain overhead information of SQL statements

-- You can directly use show profile to view the overhead information of the previous SQL statement. Note that statements such as show profile will not be profiling, that is, it will not generate Profiling itself. The show profile below shows the corresponding overhead generated by show warnings. root @ localhost [sakila]> show profile; + ---------------- + ---------- + | Status | Duration | + ---------------- + ---------- + | starting | 0.000141 | query end | 0.000058 | closing tables | 0.000014 | freeing items | 0.001802 | cleaning up | 0.000272 | + ---------------- + ---------- + -- the following query show warnings is added to profilesroot @ localhost [sakila]> show profiles; + ---------- + ------------ + response + | Query_ID | Duration | Query | + ---------- + ------------ + -------------------------------- + | 1 | 0.00253600 | show variables like '% profil %' | 2 | 0.00138150 | select count (*) from customer | 3 | 0.00228600 | show warnings | + ---------- + ------------ + ------------------------------ + -- get the overhead of the specified query root @ localhost [sakila]> show profile for query 2; + ---------------------- + ---------- + | Status | Duration | + ---------------------- + ---------- + | starting | 0.000148 | checking permissions | 0.000014 | Opening tables | 0.000047 | init | 0.000023 | System lock | 0.000035 | optimizing | 0.000012 | statistics | 0.000019 | preparing | 0.000014 | executing | 0.000006 | Sending data | 0.000990 | end | 0.000010 | query end | 0.000011 | | closing tables | 0.000010 | freeing items | 0.000016 | cleaning up | 0.000029 | + -------------------- + ---------- + -- view the overhead of a specific part, root @ localhost [sakila]> show profile CPU for query 2; + Duration + ---------- + ------------ + | Status | Duration | CPU_user | CPU_system | + Duration + ---------- + ------------ + | starting | 0.000148 | 0.000000 | checking permissions | 0.000014 | 0.000000 | 0.000000 | Opening tables | 0.000047 | 0.000000 | 0.000000 | init | 0.000023 | 0.000000 | 0.000000 | System lock | 0.000035 | 0.000000 | 0.000000 | optimizing | 0.000012 | 0.000000 | 0.000000 | statistics | 0.000019 | 0.000000 | 0.000000 | preparing | 0.000014 | 0.000000 | 0.000000 | executing | 0.000006 | 0.000000 | Sending data | 0.000000 | 0.000990 | 0.001000 | 0.000000 | end | 0.000010 | 0.000000 | 0.000000 | query end | 0.000011 | 0.000000 | 0.000000 | closing tables | 0.000010 | 0.000000 | 0.000000 | freeing items | 0.000016 | 0.000000 | 0.000000 | | cleaning up | 0.000029 | 0.000000 | 0.000000 | + ---------------------- + ---------- + ------------ + -- The following is the MEMORY overhead root @ localhost [sakila]> show profile memory for query 2; + ---------------------- + ---------- + | Status | Duration | + ---------------------- + ---------- + | starting | 0.000148 | checking permissions | 0.000014 | Opening tables | 0.000047 | init | 0.000023 | System lock | 0.000035 | optimizing | 0.000012 | statistics | 0.000019 | preparing | 0.000014 | executing | 0.000006 | Sending data | 0.000990 | end | 0.000010 | query end | 0.000011 | | closing tables | 0.000010 | freeing items | 0.000016 | cleaning up | 0.000029 | + ---------------------- + ---------- + -- view different resource overhead root @ localhost [sakila]> show profile block io, cpu for query 2; + Duration + ---------- + ------------ + Duration + | Status | Duration | CPU_user | CPU_system | usage | + Duration + ---------- + ------------ + -------------- + quota + | starting | 0.000148 | 0.000000 | 0.000000 | 0 | 0 | checking permissions | 0.000014 | 0.000000 | 0.000000 | 0 | Opening tables | 0.000047 | 0.000000 | 0 | 0 | 0 | | init | 0.000023 | 0.000000 | 0.000000 | 0 | 0 | System lock | 0.000035 | 0.000000 | 0.000000 | 0 | 0 | optimizing | 0.000012 | 0.000000 | 0.000000 | 0 | 0 | | statistics | 0.000019 | 0.000000 | 0.000000 | 0 | 0 | preparing | 0.000014 | 0.000000 | 0.000000 | 0 | 0 | executing | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | sending data | 0.000990 | 0.001000 | 0.000000 | 0 | 0 | end | 0.000010 | 0.000000 | 0.000000 | 0 | 0 | query end | 0.000011 | 0.000000 | 0.000000 | 0 | 0 | | closing tables | 0.000010 | 0.000000 | 0.000000 | 0 | 0 | freeing items | 0.000016 | 0.000000 | 0.000000 | 0 | 0 | cleaning up | 0.000029 | 0.000000 | 0.000000 | 0 | 0 | + ---------------------- + ---------- + ------------ + -------------- + --------------- + -- Author: leshami -- Blog: http://blog.csdn.net/leshami-- The following SQL statement is used to query the SQL overhead of query_id 2, and the root @ localhost [sakila]> set @ query_id = 2 is sorted in descending order of the maximum consumption time; root @ localhost [sakila]> select state, SUM (DURATION) AS Total_R,-> ROUND (-> 100 * SUM (DURATION)/-> (select sum (DURATION) -> FROM INFORMATION_SCHEMA.PROFILING-> WHERE QUERY_ID = @ query_id->), 2) AS Pct_R,-> COUNT (*) AS cils,-> SUM (DURATION)/COUNT (*) AS "R/Call"-> FROM INFORMATION_SCHEMA.PROFILING-> WHERE QUERY_ID = @ query_id-> group by state-> order by Total_R DESC; + threads + ---------- + ------- + ------------ + | STATE | Total_R | Pct_R | CILS | R/Call | + threads + ---------- + ------- + -------------- + | Sending data | 0.000990 | 71.53 | 1 | 0.0009900000 | -- the maximum consumption time is sent data | starting | 0.000148 | 10.69 | 1 | 0.0001480000 | Opening tables | 0.000047 | 3.40 | 1 | 0.0000470000 | System lock | 0.000035 | 2.53 | 1 | 0.0000350000 | cleaning up | 0.000029 | 2.10 | 1 | 0.0000290000 | init | 0.000023 | 1.66 | 1 | 0.0000230000 | statistics | 0.000019 | 1.37 | 1 | 0.0000190000 | freeing items | 0.000016 | 1.16 | 1 | 0.0000160000 | preparing | 0.000014 | 1.01 | 1 | 0.0000140000 | checking permissions | 0.000014 | 1.01 | 1 | 0.0000140000 | optimizing | 0.000012 | 0.87 | 1 | 0.0000120000 | query end | 0.000011 | 0.79 | 1 | 0.0000110000 | end | 0.000010 | 0.72 | 1 | 0.0000100000 | closing tables | 0.000010 | 0.72 | 1 | 0.0000100000 | executing | 0.000006 | 0.43 | 1 | 0.0000060000 | + ---------------------- + ---------- + ------- + -------------- + -- after profiling is enabled, we can view the overhead information through show profile and other methods. the essence is that the overhead information is recorded in the information_schema.profiling table-the following query, partial information is omitted. profilingroot @ localhost [information_schema]> select * from profiling limit 3 \ G; * *************************** 1. row ************************** QUERY_ID: 1 SEQ: 5 STATE: init DURATION: 0.000020 CPU_USER: 0.000000 CPU_SYSTEM: 0.000000 protocol: Protocol: 0 BLOCK_OPS_IN: 0 BLOCK_OPS_OUT: 0 MESSAGES_SENT: 0 MESSAGES_RECEIVED: 0 protocol: 0 protocol: 0 SWAPS: 0 SOURCE_FUNCTION: export SOURCE_FILE: SQL _select.cc SOURCE_LINE: 1050 -- stop profile. you can set the profiling parameter, or after the session exits, profiling will be automatically disabled. root @ localhost [sakila]> set profiling = off; Query OK, 0 rows affected, 1 warning (0.00 sec)