博客文章除注明转载外，均为原创。转载请注明出处。
本文链接地址：http://blog.chinaunix.net/uid-31396856-id-5772891.html
先打开profile，默认是关闭的。
(mysql5.7)root@localhost [(none)]> show variables like '%profil%';
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| have_profiling | YES |
| profiling | OFF |
| profiling_history_size | 15 |
+------------------------+-------+
3 rows in set (0.00 sec)
打开当前会话的profile
(mysql5.7)root@localhost [(none)]> set profiling = 1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
开始使用
(mysql5.7)root@localhost [(none)]> select count(*) from dbtest1.sbtest;
ERROR 1146 (42S02): Table 'dbtest1.sbtest' doesn't exist
(mysql5.7)root@localhost [(none)]>
(mysql5.7)root@localhost [(none)]>
(mysql5.7)root@localhost [(none)]> select count(*) from dbtest1.sbtest1;
+----------+
| count(*) |
+----------+
| 10000 |
+----------+
1 row in set (1.30 sec)
找到sql对应的query_id
(mysql5.7)root@localhost [(none)]> show profiles;
+----------+------------+--------------------------------------+
| Query_ID | Duration | Query |
+----------+------------+--------------------------------------+
| 1 | 0.00035325 | select count(*) from dbtest1.sbtest |
| 2 | 1.29764525 | select count(*) from dbtest1.sbtest1 |
+----------+------------+--------------------------------------+
2 rows in set, 1 warning (0.00 sec)
开始查询sql的性能数据。
(mysql5.7)root@localhost [(none)]> show profile for query 2;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000130 |
| checking permissions | 0.000012 |
| Opening tables | 0.134251 |
| init | 0.000023 |
| System lock | 0.000011 |
| optimizing | 1.163107 |
| executing | 0.000019 |
| end | 0.000004 |
| query end | 0.000008 |
| closing tables | 0.000032 |
| freeing items | 0.000029 |
| cleaning up | 0.000020 |
+----------------------+----------+
12 rows in set, 1 warning (0.00 sec)
(mysql5.7)root@localhost [(none)]>
sql消耗cpu的性能指标
(mysql5.7)root@localhost [(none)]> show profile cpu for query 2;
+----------------------+----------+----------+------------+
| Status | Duration | CPU_user | CPU_system |
+----------------------+----------+----------+------------+
| starting | 0.000130 | 0.000000 | 0.000000 |
| checking permissions | 0.000012 | 0.000000 | 0.000000 |
| Opening tables | 0.134251 | 0.001000 | 0.000000 |
| init | 0.000023 | 0.000000 | 0.000000 |
| System lock | 0.000011 | 0.000000 | 0.000000 |
| optimizing | 1.163107 | 0.000000 | 0.013998 |
| executing | 0.000019 | 0.000000 | 0.000000 |
| end | 0.000004 | 0.000000 | 0.000000 |
| query end | 0.000008 | 0.000000 | 0.000000 |
| closing tables | 0.000032 | 0.000000 | 0.000000 |
| freeing items | 0.000029 | 0.000000 | 0.000000 |
| cleaning up | 0.000020 | 0.000000 | 0.000000 |
+----------------------+----------+----------+------------+
12 rows in set, 1 warning (0.00 sec)
sql消耗内存的性能指标
(mysql5.7)root@localhost [(none)]> show profile memory for query 2;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000130 |
| checking permissions | 0.000012 |
| Opening tables | 0.134251 |
| init | 0.000023 |
| System lock | 0.000011 |
| optimizing | 1.163107 |
| executing | 0.000019 |
| end | 0.000004 |
| query end | 0.000008 |
| closing tables | 0.000032 |
| freeing items | 0.000029 |
| cleaning up | 0.000020 |
+----------------------+----------+
12 rows in set, 1 warning (0.00 sec)
sql消耗io的性能指标
(mysql5.7)root@localhost [(none)]> show profile block io for query 2;
+----------------------+----------+--------------+---------------+
| Status | Duration | Block_ops_in | Block_ops_out |
+----------------------+----------+--------------+---------------+
| starting | 0.000130 | 0 | 8 |
| checking permissions | 0.000012 | 0 | 0 |
| Opening tables | 0.134251 | 96 | 0 |
| init | 0.000023 | 0 | 0 |
| System lock | 0.000011 | 0 | 0 |
| optimizing | 1.163107 | 5088 | 0 |
| executing | 0.000019 | 0 | 0 |
| end | 0.000004 | 0 | 0 |
| query end | 0.000008 | 0 | 0 |
| closing tables | 0.000032 | 0 | 0 |
| freeing items | 0.000029 | 0 | 0 |
| cleaning up | 0.000020 | 0 | 0 |
+----------------------+----------+--------------+---------------+
12 rows in set, 1 warning (0.00 sec)
也可以联合起来查询
(mysql5.7)root@localhost [(none)]> show profile block io,cpu for query 2;
+----------------------+----------+----------+------------+--------------+---------------+
| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting | 0.000130 | 0.000000 | 0.000000 | 0 | 8 |
| checking permissions | 0.000012 | 0.000000 | 0.000000 | 0 | 0 |
| Opening tables | 0.134251 | 0.001000 | 0.000000 | 96 | 0 |
| init | 0.000023 | 0.000000 | 0.000000 | 0 | 0 |
| System lock | 0.000011 | 0.000000 | 0.000000 | 0 | 0 |
| optimizing | 1.163107 | 0.000000 | 0.013998 | 5088 | 0 |
| executing | 0.000019 | 0.000000 | 0.000000 | 0 | 0 |
| end | 0.000004 | 0.000000 | 0.000000 | 0 | 0 |
| query end | 0.000008 | 0.000000 | 0.000000 | 0 | 0 |
| closing tables | 0.000032 | 0.000000 | 0.000000 | 0 | 0 |
| freeing items | 0.000029 | 0.000000 | 0.000000 | 0 | 0 |
| cleaning up | 0.000020 | 0.000000 | 0.000000 | 0 | 0 |
+----------------------+----------+----------+------------+--------------+---------------+
12 rows in set, 1 warning (0.00 sec)
也可以通过sql语句查询
(mysql5.7)root@localhost [(none)]> select min(seq) seq,state,count(*) numb_ops,
-> round(sum(duration),5) sum_dur, round(avg(duration),5) avg_dur,
-> round(sum(cpu_user),5) sum_cpu, round(avg(cpu_user),5) avg_cpu
-> from information_schema.profiling
-> where query_id = 2
-> group by state
-> order by seq;
+------+----------------------+----------+---------+---------+---------+---------+
| seq | state | numb_ops | sum_dur | avg_dur | sum_cpu | avg_cpu |
+------+----------------------+----------+---------+---------+---------+---------+
| 2 | starting | 1 | 0.00013 | 0.00013 | 0.00000 | 0.00000 |
| 3 | checking permissions | 1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
| 4 | Opening tables | 1 | 0.13425 | 0.13425 | 0.00100 | 0.00100 |
| 5 | init | 1 | 0.00002 | 0.00002 | 0.00000 | 0.00000 |
| 6 | System lock | 1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
| 7 | optimizing | 1 | 1.16311 | 1.16311 | 0.00000 | 0.00000 |
| 8 | executing | 1 | 0.00002 | 0.00002 | 0.00000 | 0.00000 |
| 9 | end | 1 | 0.00000 | 0.00000 | 0.00000 | 0.00000 |
| 10 | query end | 1 | 0.00001 | 0.00001 | 0.00000 | 0.00000 |
| 11 | closing tables | 1 | 0.00003 | 0.00003 | 0.00000 | 0.00000 |
| 12 | freeing items | 1 | 0.00003 | 0.00003 | 0.00000 | 0.00000 |
| 13 | cleaning up | 1 | 0.00002 | 0.00002 | 0.00000 | 0.00000 |
+------+----------------------+----------+---------+---------+---------+---------+
12 rows in set, 1 warning (0.00 sec)
(mysql5.7)root@localhost [(none)]> SELECT STATE, SUM(DURATION) AS Total_R,ROUND( 100 * SUM(DURATION) / (SELECT SUM(DURATION)
-> FROM INFORMATION_SCHEMA.PROFILING
-> WHERE QUERY_ID = 2), 2) AS Pct_R, COUNT(*) AS Calls,SUM(DURATION) / COUNT(*) AS "R/Call"
-> FROM INFORMATION_SCHEMA.PROFILING WHERE QUERY_ID = 2 GROUP BY STATE
-> ordER BY Total_R DESC;
+----------------------+----------+-------+-------+--------------+
| STATE | Total_R | Pct_R | Calls | R/Call |
+----------------------+----------+-------+-------+--------------+
| optimizing | 1.163107 | 89.63 | 1 | 1.1631070000 |
| Opening tables | 0.134251 | 10.35 | 1 | 0.1342510000 |
| starting | 0.000130 | 0.01 | 1 | 0.0001300000 |
| closing tables | 0.000032 | 0.00 | 1 | 0.0000320000 |
| freeing items | 0.000029 | 0.00 | 1 | 0.0000290000 |
| init | 0.000023 | 0.00 | 1 | 0.0000230000 |
| cleaning up | 0.000020 | 0.00 | 1 | 0.0000200000 |
| executing | 0.000019 | 0.00 | 1 | 0.0000190000 |
| checking permissions | 0.000012 | 0.00 | 1 | 0.0000120000 |
| System lock | 0.000011 | 0.00 | 1 | 0.0000110000 |
| query end | 0.000008 | 0.00 | 1 | 0.0000080000 |
| end | 0.000004 | 0.00 | 1 | 0.0000040000 |
+----------------------+----------+-------+-------+--------------+
12 rows in set, 2 warnings (0.00 sec)
---The end
(mysql5.7)root@localhost [(none)]> set profiling = off;
Query OK, 0 rows affected, 1 warning (0.00 sec)
