MySQL性能分析工具profile使用教程
分析SQL执行带来的开销是优化SQL的重要手段。在MySQL数据库中,可以通过配置profiling参数来启用SQL剖析。该参数可以在全局和session级别来设置。对于全局级别则作用于整个MySQL实例,而session级别紧影响当前session。该参数开启后,后续执行的SQL语句都将记录其资源开销,诸如IO,上下文切换,CPU,Memory等等。根据这些开销进一步分析当前SQL瓶颈从而进行优化与调整。本文描述了如何使用MySQLprofile,不涉及具体的样例分析。
1、有关profile的描述
--当前版本 root@localhost[sakila]>showvariableslike'version'; +---------------+---------------------------------------+ |Variable_name|Value | +---------------+---------------------------------------+ |version |5.6.17-enterprise-commercial-advanced| +---------------+---------------------------------------+ --查看profiling系统变量 root@localhost[sakila]>showvariableslike'%profil%'; +------------------------+-------+ |Variable_name |Value| +------------------------+-------+ |have_profiling |YES | --只读变量,用于控制是否由系统变量开启或禁用profiling |profiling |OFF | --开启SQL语句剖析功能 |profiling_history_size|15 | --设置保留profiling的数目,缺省为15,范围为0至100,为0时将禁用profiling +------------------------+-------+ profiling[539] Ifsetto0orOFF(thedefault),statementprofilingisdisabled.Ifsetto1orON,statementprof isenabledandtheSHOWPROFILEandSHOWPROFILESstatementsprovideaccesstoprof information.SeeSection13.7.5.32,“SHOWPROFILESSyntax”. ThisvariableisdeprecatedinMySQL5.6.8andwillberemovedinafutureMySQLrelease. profiling_history_size[539] Thenumberofstatementsforwhichtomaintainprofilinginformationifprofiling[539]is enabled.Thedefaultvalueis15.Themaximumvalueis100.Settingthevalueto0effectively disablesprofiling.SeeSection13.7.5.32,“SHOWPROFILESSyntax”. ThisvariableisdeprecatedinMySQL5.6.8andwillberemovedinafutureMySQLrelease. --获取profile的帮助 root@localhost[sakila]>helpprofile; Name:'SHOWPROFILE' Description: Syntax: SHOWPROFILE[type[,type]...] [FORQUERYn] [LIMITrow_count[OFFSEToffset]] type: ALL --显示所有的开销信息 |BLOCKIO --显示块IO相关开销 |CONTEXTSWITCHES --上下文切换相关开销 |CPU --显示CPU相关开销信息 |IPC --显示发送和接收相关开销信息 |MEMORY --显示内存相关开销信息 |PAGEFAULTS --显示页面错误相关开销信息 |SOURCE --显示和Source_function,Source_file,Source_line相关的开销信息 |SWAPS --显示交换次数相关开销的信息 TheSHOWPROFILEandSHOWPROFILESstatementsdisplayprofiling informationthatindicatesresourceusageforstatementsexecuted duringthecourseofthecurrentsession. *Note*:ThesestatementsaredeprecatedasofMySQL5.6.7andwillbe removedinafutureMySQLrelease.UsethePerformanceSchemainstead; seehttp://dev.mysql.com/doc/refman/5.6/en/performance-schema.html. --上面描述从5.6.7开始该命令将会被移除,用PerformanceSchemainstead代替 --在Oracle数据库中,是通过autotrace来剖析单条SQL并获取真实的执行计划以及其开销信息
2、开启porfiling
--启用session级别的profiling root@localhost[sakila]>setprofiling=1; QueryOK,0rowsaffected,1warning(0.00sec) --验证修改后的结果 root@localhost[sakila]>showvariableslike'%profil%'; +------------------------+-------+ |Variable_name |Value| +------------------------+-------+ |have_profiling |YES | |profiling |ON | |profiling_history_size|15 | +------------------------+-------+ --发布SQL查询 root@localhost[sakila]>selectcount(*)fromcustomer; +----------+ |count(*)| +----------+ | 599| +----------+ --查看当前session所有已产生的profile root@localhost[sakila]>showprofiles; +----------+------------+--------------------------------+ |Query_ID|Duration |Query | +----------+------------+--------------------------------+ | 1|0.00253600|showvariableslike'%profil%'| | 2|0.00138150|selectcount(*)fromcustomer | +----------+------------+--------------------------------+ 2rowsinset,1warning(0.01sec) --我们看到有2个warning,之前一个,现在一个 root@localhost[sakila]>showwarnings; --下面的结果表明SHOWPROFILES将来会被PerformanceSchema替换掉 +---------+------+--------------------------------------------------------------------------------------------------------------+ |Level |Code|Message | +---------+------+--------------------------------------------------------------------------------------------------------------+ |Warning|1287|'SHOWPROFILES'isdeprecatedandwillberemovedinafuturerelease.PleaseusePerformanceSchemainstead| +---------+------+--------------------------------------------------------------------------------------------------------------+
3、获取SQL语句的开销信息
--可以直接使用showprofile来查看上一条SQL语句的开销信息
--注,showprofile之类的语句不会被profiling,即自身不会产生Profiling
--我们下面的这个showprofile查看的是showwarnings产生的相应开销
root@localhost[sakila]>showprofile;
+----------------+----------+
|Status |Duration|
+----------------+----------+
|starting |0.000141|
|queryend |0.000058|
|closingtables|0.000014|
|freeingitems |0.001802|
|cleaningup |0.000272|
+----------------+----------+
--如下面的查询showwarnings被添加到profiles
root@localhost[sakila]>showprofiles;
+----------+------------+--------------------------------+
|Query_ID|Duration |Query |
+----------+------------+--------------------------------+
| 1|0.00253600|showvariableslike'%profil%'|
| 2|0.00138150|selectcount(*)fromcustomer |
| 3|0.00228600|showwarnings |
+----------+------------+--------------------------------+
--获取指定查询的开销
root@localhost[sakila]>showprofileforquery2;
+----------------------+----------+
|Status |Duration|
+----------------------+----------+
|starting |0.000148|
|checkingpermissions|0.000014|
|Openingtables |0.000047|
|init |0.000023|
|Systemlock |0.000035|
|optimizing |0.000012|
|statistics |0.000019|
|preparing |0.000014|
|executing |0.000006|
|Sendingdata |0.000990|
|end |0.000010|
|queryend |0.000011|
|closingtables |0.000010|
|freeingitems |0.000016|
|cleaningup |0.000029|
+----------------------+----------+
--查看特定部分的开销,如下为CPU部分的开销
root@localhost[sakila]>showprofilecpuforquery2;
+----------------------+----------+----------+------------+
|Status |Duration|CPU_user|CPU_system|
+----------------------+----------+----------+------------+
|starting |0.000148|0.000000| 0.000000|
|checkingpermissions|0.000014|0.000000| 0.000000|
|Openingtables |0.000047|0.000000| 0.000000|
|init |0.000023|0.000000| 0.000000|
|Systemlock |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| 0.000000|
|Sendingdata |0.000990|0.001000| 0.000000|
|end |0.000010|0.000000| 0.000000|
|queryend |0.000011|0.000000| 0.000000|
|closingtables |0.000010|0.000000| 0.000000|
|freeingitems |0.000016|0.000000| 0.000000|
|cleaningup |0.000029|0.000000| 0.000000|
+----------------------+----------+----------+------------+
--如下为MEMORY部分的开销
root@localhost[sakila]>showprofilememoryforquery2;
+----------------------+----------+
|Status |Duration|
+----------------------+----------+
|starting |0.000148|
|checkingpermissions|0.000014|
|Openingtables |0.000047|
|init |0.000023|
|Systemlock |0.000035|
|optimizing |0.000012|
|statistics |0.000019|
|preparing |0.000014|
|executing |0.000006|
|Sendingdata |0.000990|
|end |0.000010|
|queryend |0.000011|
|closingtables |0.000010|
|freeingitems |0.000016|
|cleaningup |0.000029|
+----------------------+----------+
--同时查看不同资源开销
root@localhost[sakila]>showprofileblockio,cpuforquery2;
+----------------------+----------+----------+------------+--------------+---------------+
|Status |Duration|CPU_user|CPU_system|Block_ops_in|Block_ops_out|
+----------------------+----------+----------+------------+--------------+---------------+
|starting |0.000148|0.000000| 0.000000| 0| 0|
|checkingpermissions|0.000014|0.000000| 0.000000| 0| 0|
|Openingtables |0.000047|0.000000| 0.000000| 0| 0|
|init |0.000023|0.000000| 0.000000| 0| 0|
|Systemlock |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|
|Sendingdata |0.000990|0.001000| 0.000000| 0| 0|
|end |0.000010|0.000000| 0.000000| 0| 0|
|queryend |0.000011|0.000000| 0.000000| 0| 0|
|closingtables |0.000010|0.000000| 0.000000| 0| 0|
|freeingitems |0.000016|0.000000| 0.000000| 0| 0|
|cleaningup |0.000029|0.000000| 0.000000| 0| 0|
+----------------------+----------+----------+------------+--------------+---------------+
--下面的SQL语句用于查询query_id为2的SQL开销,且按最大耗用时间倒序排列
root@localhost[sakila]>set@query_id=2;
root@localhost[sakila]>SELECTSTATE,SUM(DURATION)ASTotal_R,
-> ROUND(
-> 100*SUM(DURATION)/
-> (SELECTSUM(DURATION)
-> FROMINFORMATION_SCHEMA.PROFILING
-> WHEREQUERY_ID=@query_id
-> ),2)ASPct_R,
-> COUNT(*)ASCalls,
-> SUM(DURATION)/COUNT(*)AS"R/Call"
-> FROMINFORMATION_SCHEMA.PROFILING
-> WHEREQUERY_ID=@query_id
-> GROUPBYSTATE
-> ORDERBYTotal_RDESC;
+----------------------+----------+-------+-------+--------------+
|STATE |Total_R |Pct_R|Calls|R/Call |
+----------------------+----------+-------+-------+--------------+
|Sendingdata |0.000990|71.53| 1|0.0009900000|--最大耗用时间部分为发送数据
|starting |0.000148|10.69| 1|0.0001480000|
|Openingtables |0.000047| 3.40| 1|0.0000470000|
|Systemlock |0.000035| 2.53| 1|0.0000350000|
|cleaningup |0.000029| 2.10| 1|0.0000290000|
|init |0.000023| 1.66| 1|0.0000230000|
|statistics |0.000019| 1.37| 1|0.0000190000|
|freeingitems |0.000016| 1.16| 1|0.0000160000|
|preparing |0.000014| 1.01| 1|0.0000140000|
|checkingpermissions|0.000014| 1.01| 1|0.0000140000|
|optimizing |0.000012| 0.87| 1|0.0000120000|
|queryend |0.000011| 0.79| 1|0.0000110000|
|end |0.000010| 0.72| 1|0.0000100000|
|closingtables |0.000010| 0.72| 1|0.0000100000|
|executing |0.000006| 0.43| 1|0.0000060000|
+----------------------+----------+-------+-------+--------------+
--开启profiling后,我们可以通过showprofile等方式查看,其实质是这些开销信息被记录到information_schema.profiling表
--如下面的查询,部分信息省略
profiling
root@localhost[information_schema]>select*fromprofilinglimit3,3\G;
***************************1.row***************************
QUERY_ID:1
SEQ:5
STATE:init
DURATION:0.000020
CPU_USER:0.000000
CPU_SYSTEM:0.000000
CONTEXT_VOLUNTARY:0
CONTEXT_INVOLUNTARY:0
BLOCK_OPS_IN:0
BLOCK_OPS_OUT:0
MESSAGES_SENT:0
MESSAGES_RECEIVED:0
PAGE_FAULTS_MAJOR:0
PAGE_FAULTS_MINOR:0
SWAPS:0
SOURCE_FUNCTION:mysql_prepare_select
SOURCE_FILE:sql_select.cc
SOURCE_LINE:1050
--停止profile,可以设置profiling参数,或者在session退出之后,profiling会被自动关闭
root@localhost[sakila]>setprofiling=off;
QueryOK,0rowsaffected,1warning(0.00sec)