CREATE TEMPORARY TABLE `PROFILING` (
`QUERY_ID` int(20) NOT NULL DEFAULT '0',
`SEQ` int(20) NOT NULL DEFAULT '0',
`STATE` varchar(30) NOT NULL DEFAULT '',
`DURATION` decimal(9,6) NOT NULL DEFAULT '0.000000',
`CPU_USER` decimal(9,6) DEFAULT NULL,
`CPU_SYSTEM` decimal(9,6) DEFAULT NULL,
`CONTEXT_VOLUNTARY` int(20) DEFAULT NULL,
`CONTEXT_INVOLUNTARY` int(20) DEFAULT NULL,
`BLOCK_OPS_IN` int(20) DEFAULT NULL,
`BLOCK_OPS_OUT` int(20) DEFAULT NULL,
`MESSAGES_SENT` int(20) DEFAULT NULL,
`MESSAGES_RECEIVED` int(20) DEFAULT NULL,
`PAGE_FAULTS_MAJOR` int(20) DEFAULT NULL,
`PAGE_FAULTS_MINOR` int(20) DEFAULT NULL,
`SWAPS` int(20) DEFAULT NULL,
`SOURCE_FUNCTION` varchar(30) DEFAULT NULL,
`SOURCE_FILE` varchar(20) DEFAULT NULL,
`SOURCE_LINE` int(20) DEFAULT NULL
) ENGINE=MEMORY DEFAULT CHARSET=utf8
root@localhost : sbtest 04:47:17> set profiling=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
root@localhost : (none) 04:47:10> use sbtest
Database changed
root@localhost : sbtest 04:47:21> select min(id) from sbtest1;
+---------+
| min(id) |
+---------+
| 1 |
+---------+
1 row in set (0.00 sec)
root@localhost : sbtest 04:47:33> select * from information_schema.profiling;
+----------+-----+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
| QUERY_ID | SEQ | STATE | DURATION | CPU_USER | CPU_SYSTEM | CONTEXT_VOLUNTARY | CONTEXT_INVOLUNTARY | BLOCK_OPS_IN | BLOCK_OPS_OUT | MESSAGES_SENT | MESSAGES_RECEIVED | PAGE_FAULTS_MAJOR | PAGE_FAULTS_MINOR | SWAPS | SOURCE_FUNCTION | SOURCE_FILE | SOURCE_LINE |
+----------+-----+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
| 1 | 2 | starting | 0.000040 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL |
| 1 | 3 | query end | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 4968 |
| 1 | 4 | closing tables | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 5020 |
| 1 | 5 | freeing items | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_parse | sql_parse.cc | 5596 |
| 1 | 6 | cleaning up | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 1902 |
| 2 | 2 | starting | 0.000107 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL |
| 2 | 3 | checking permissions | 0.000022 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_authorization.cc | 810 |
| 2 | 4 | Opening tables | 0.000080 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | open_tables | sql_base.cc | 5650 |
| 2 | 5 | init | 0.000056 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | handle_query | sql_select.cc | 121 |
| 2 | 6 | System lock | 0.000021 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_lock_tables | lock.cc | 323 |
| 2 | 7 | optimizing | 0.000057 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 151 |
| 2 | 8 | executing | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec | sql_executor.cc | 119 |
| 2 | 9 | end | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | handle_query | sql_select.cc | 199 |
| 2 | 10 | query end | 0.000023 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 4968 |
| 2 | 11 | closing tables | 0.000016 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 5020 |
| 2 | 12 | freeing items | 0.000012 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_parse | sql_parse.cc | 5596 |
| 2 | 13 | cleaning up | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 1902 |
+----------+-----+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
17 rows in set, 1 warning (0.00 sec)
# 需要使用set profiling=1;语句开启,该功能即将废弃,使用performance_schema中的阶段事件代替
## 启用
root@localhost : information_schema 02:30:20> set profiling=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
## 列出查询语句的query id和语句文本等信息
root@localhost : sbtest 04:33:47> show profiles;
+----------+------------+-----------------------------+
| Query_ID | Duration | Query |
+----------+------------+-----------------------------+
| 1 | 0.00005125 | show warnings |
| 2 | 0.00073950 | select * from profiling |
| 3 | 0.00007150 | show warnings |
| 4 | 0.00021025 | set profiling=1 |
| 5 | 0.00003250 | show warnings |
| 6 | 0.00038300 | select * from profiling |
| 7 | 0.00003625 | show warnings |
| 8 | 0.00018250 | SELECT DATABASE() |
| 9 | 0.08272525 | select max(id) from sbtest1 |
+----------+------------+-----------------------------+
9 rows in set, 1 warning (0.00 sec)
## 找到query id为9,查询该ID的性能分析数据
root@localhost : sbtest 04:33:53> show profile all for query 9;
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file | Source_line |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
| starting | 0.000089 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | NULL | NULL | NULL |
| checking permissions | 0.000011 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_authorization.cc | 810 |
| Opening tables | 0.082168 | 0.000000 | 0.081988 | 25 | 2 | 128 | 0 | 0 | 0 | 0 | 800 | 0 | open_tables | sql_base.cc | 5650 |
| init | 0.000173 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 10 | 0 | handle_query | sql_select.cc | 121 |
| System lock | 0.000012 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_lock_tables | lock.cc | 323 |
| optimizing | 0.000079 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2 | 0 | optimize | sql_optimizer.cc | 151 |
| executing | 0.000010 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec | sql_executor.cc | 119 |
| end | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | handle_query | sql_select.cc | 199 |
| query end | 0.000009 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 4968 |
| closing tables | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 5020 |
| freeing items | 0.000150 | 0.000000 | 0.000000 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 3 | 0 | mysql_parse | sql_parse.cc | 5596 |
| cleaning up | 0.000013 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 1902 |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
12 rows in set, 1 warning (0.00 sec)