mysql的profiling功能要在mysql版本5.0.37以上才能使用。
查看profile是否开启
mysql> show variables like '%profil%';
+------------------------+-------+ | variable_name | value | +------------------------+-------+ | profiling | off | --开启sql语句剖析功能 | profiling_history_size | 15 | --设置保留profiling的数目，缺省为15，范围为0至100，为0时将禁用profiling +------------------------+-------+ 2 rows in set (0.00 sec)
基于会话级别开启
mysql> set profiling = 1; --关闭则用set profiling = off
query ok, 0 rows affected (0.00 sec)
mysql> select distinct d.account,a.server_id from tab_appserver_user a -> inner join tab_department_parent b on a.key_id = b.parent_id -> inner join tab_department_member c on b.department_id = c.department_id and c.state=1 -> and c.isdefault=1 inner join tab_user_info d on c.user_id = d.user_id and d.state=1 -> where a.type=1 -> union -> select distinct b.account,a.server_id from tab_appserver_user a -> inner join tab_user_info b on a.key_id = b.user_id and b.state=1 -> where a.type=0;
查看是否设置生效：
select @@profiling;
默认是0，设置成功是1
运行sql语句：
mysql> select * from hx_line where id = '1455023';
查看profiles
mysql> show profiles;
+----------+------------+---------------------------------------------+ | query_id | duration | query | +----------+------------+---------------------------------------------+ | 1 | 0.00036150 | select * from hx_line where id = '1455023' | +----------+------------+---------------------------------------------+
查看具体某条的profile
mysql> show profile for query 1;
+--------------------------------+----------+ | status | duration | +--------------------------------+----------+ | starting | 0.000013 | | waiting for query cache lock | 0.000014 | | checking query cache for query | 0.000038 | | checking permissions | 0.000006 | | opening tables | 0.000013 | | system lock | 0.000009 | | waiting for query cache lock | 0.000024 | | init | 0.000060 | | optimizing | 0.000014 | | statistics | 0.000046 | | preparing | 0.000017 | | executing | 0.000004 | | sending data | 0.000081 | | end | 0.000005 | | query end | 0.000004 | | closing tables | 0.000008 | | freeing items | 0.000009 | | waiting for query cache lock | 0.000003 | | freeing items | 0.000013 | | waiting for query cache lock | 0.000003 | | freeing items | 0.000003 | | storing result in query cache | 0.000005 | | logging slow query | 0.000003 | | cleaning up | 0.000004 | +--------------------------------+----------+ 24 rows
我们看到了一个简单的查询，mysql内部做了24次操作。
另外，看到了一堆query cache的操作，试着把query_cache_size=0，把query_cache关闭，再次测试：
mysql> show profile for query 1;
+----------------------+----------+ | status | duration | +----------------------+----------+ | starting | 0.000040 | | checking permissions | 0.000007 | | opening tables | 0.000015 | | system lock | 0.000010 | | init | 0.000061 | | optimizing | 0.000013 | | statistics | 0.000059 | | preparing | 0.000018 | | executing | 0.000004 | | sending data | 0.000092 | | end | 0.000006 | | query end | 0.000004 | | closing tables | 0.000008 | | freeing items | 0.000020 | | logging slow query | 0.000003 | | cleaning up | 0.000004 | +----------------------+----------+ 16 rows in set (0.00 sec)
当开启了query_cache的情况下，需要多操作6次，在这个示例里面多化了0.000087s。
查询这条语句对cpu的使用情况：
mysql> show profile cpu for query 1;
+----------------------+----------+----------+------------+ | status | duration | cpu_user | cpu_system | +----------------------+----------+----------+------------+ | starting | 0.000037 | 0.000000 | 0.000000 | | checking permissions | 0.000009 | 0.000000 | 0.000000 | | opening tables | 0.000014 | 0.000000 | 0.000000 | | system lock | 0.000009 | 0.000000 | 0.000000 | | init | 0.000059 | 0.000000 | 0.000000 | | optimizing | 0.000009 | 0.000000 | 0.000000 | | statistics | 0.000044 | 0.000000 | 0.000000 | | preparing | 0.000015 | 0.000000 | 0.000000 | | executing | 0.000004 | 0.000000 | 0.000000 | | sending data | 0.000081 | 0.000000 | 0.000000 | | end | 0.000006 | 0.000000 | 0.000000 | | query end | 0.000004 | 0.000000 | 0.000000 | | closing tables | 0.000008 | 0.000000 | 0.000000 | | freeing items | 0.000021 | 0.000000 | 0.000000 | | logging slow query | 0.000004 | 0.000000 | 0.000000 | | cleaning up | 0.000004 | 0.000000 | 0.000000 | +----------------------+----------+----------+------------+
查看io及cpu的消耗
mysql> show profile block io,cpu for query 1;
+--------------------------------+----------+----------+------------+--------------+---------------+ | status | duration | cpu_user | cpu_system | block_ops_in | block_ops_out | +--------------------------------+----------+----------+------------+--------------+---------------+ | starting | 0.000018 | null | null | null | null | | checking query cache for query | 0.000099 | null | null | null | null | | opening tables | 0.000963 | null | null | null | null | | system lock | 0.000015 | null | null | null | null | | table lock | 0.000169 | null | null | null | null | | optimizing | 0.000020 | null | null | null | null | | statistics | 0.000027 | null | null | null | null | | preparing | 0.000018 | null | null | null | null | | creating tmp table | 0.000055 | null | null | null | null | | executing | 0.000003 | null | null | null | null | | copying to tmp table | 0.704845 | null | null | null | null | | sending data | 0.130039 | null | null | null | null | | optimizing | 0.000029 | null | null | null | null | | statistics | 0.000029 | null | null | null | null | | preparing | 0.000020 | null | null | null | null | | creating tmp table | 0.000142 | null | null | null | null | | executing | 0.000003 | null | null | null | null | | copying to tmp table | 0.000086 | null | null | null | null | | sending data | 0.000067 | null | null | null | null | | optimizing | 0.000004 | null | null | null | null | | statistics | 0.000005 | null | null | null | null | | preparing | 0.000005 | null | null | null | null | | executing | 0.000002 | null | null | null | null | | sending data | 0.023963 | null | null | null | null | | removing tmp table | 0.003420 | null | null | null | null | | sending data | 0.000005 | null | null | null | null | | removing tmp table | 0.003308 | null | null | null | null | | sending data | 0.000006 | null | null | null | null | | removing tmp table | 0.000007 | null | null | null | null | | sending data | 0.000009 | null | null | null | null | | query end | 0.000003 | null | null | null | null | | freeing items | 0.000144 | null | null | null | null | | storing result in query cache | 0.000011 | null | null | null | null | | logging slow query | 0.000003 | null | null | null | null | | cleaning up | 0.000006 | null | null | null | null | +--------------------------------+----------+----------+------------+--------------+---------------+ 35 rows in set (0.00 sec)
使用查询语句对消耗进行排序
mysql> select state, sum(duration) as total_r,round( 100 * sum(duration) / (se ct sum(duration) -> from information_schema.profiling where query_id = 1), 2) as pct_r, co t(*) as calls,sum(duration) / count(*) as "r/call" -> from information_schema.profiling where query_id = 1 group by state o er by total_r desc;
+--------------------------------+----------+-------+-------+--------------+ | state | total_r | pct_r | calls | r/call | +--------------------------------+----------+-------+-------+--------------+ | copying to tmp table | 0.704931 | 81.26 | 2 | 0.3524655000 | | sending data | 0.154089 | 17.76 | 6 | 0.0256815000 | | removing tmp table | 0.006735 | 0.78 | 3 | 0.0022450000 | | opening tables | 0.000963 | 0.11 | 1 | 0.0009630000 | | creating tmp table | 0.000197 | 0.02 | 2 | 0.0000985000 | | table lock | 0.000169 | 0.02 | 1 | 0.0001690000 | | freeing items | 0.000144 | 0.02 | 1 | 0.0001440000 | | checking query cache for query | 0.000099 | 0.01 | 1 | 0.0000990000 | | statistics | 0.000061 | 0.01 | 3 | 0.0000203333 | | optimizing | 0.000053 | 0.01 | 3 | 0.0000176667 | | preparing | 0.000043 | 0.00 | 3 | 0.0000143333 | | starting | 0.000018 | 0.00 | 1 | 0.0000180000 | | system lock | 0.000015 | 0.00 | 1 | 0.0000150000 | | storing result in query cache | 0.000011 | 0.00 | 1 | 0.0000110000 | | executing | 0.000008 | 0.00 | 3 | 0.0000026667 | | cleaning up | 0.000006 | 0.00 | 1 | 0.0000060000 | | logging slow query | 0.000003 | 0.00 | 1 | 0.0000030000 | | query end | 0.000003 | 0.00 | 1 | 0.0000030000 | +--------------------------------+----------+-------+-------+--------------+ 18 rows in set (0.01 sec)
show profile额外一些命令：
* all - displays all information
* block io - displays counts for block input and output operations
* context switches - displays counts for voluntary and involuntary context switches
* ipc - displays counts for messages sent and received
* memory - is not currently implemented
* page faults - displays counts for major and minor page faults
* source - displays the names of functions from the source code, together with the name and line number of the file in which the function occurs
* swaps - displays swap counts
最后说明：profile是一个非常量化的子标，可以根据这些量化指标来比较各项资源的消耗，有利于我们对该语句的整体把控！
如对本文有疑问， 点击进行留言回复！！
一步步教你用Prometheus搭建实时监控系统系列(一)——上帝之火，普罗米修斯的崛起
我要评论
网友评论