MySQL Query Profile
MySQL Query Profiler, 可以查询到此 SQL 语句会执行多少, 并看出 CPU/Memory 使用量, 执行过程 System lock, Table lock 花多少时间等等.从启动Profile之后的所有查询包括错误语句都会被记录。mysql的sql语句优化也可以使用explain，但是执行计划是没有办法知道详细的Memory/CPU等使用量。
SHOW PROFILE [type [, type] ... ] [FOR QUERY n] [LIMIT row_count [OFFSET offset]]
type： ALL | BLOCK IO | CONTEXT SWITCHES | CPU | IPC | MEMORY | PAGE FAULTS | SOURCE | SWAPS
Optional type values may be specified to display specific additional types of information:
• ALL displays all information
• BLOCK IO displays counts for block input and output operations
• CONTEXT SWITCHES displays counts for voluntary and involuntary context switches
• CPU displays user and system CPU usage times
• 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
默认情况下Mysql的profiling是关闭的，所以首先必须打开profiling
mysql> set profiling='on';
再查看变量：
mysql> show variables like '%profi%';
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| profiling | ON |
| profiling_history_size | 15 | -- profiling_history_size记录多少次查询
+------------------------+-------+
2 rows in set (0.00 sec)
然后show profiles来查看query ID，然后使用这个query ID进行查询分析。试例如下：
首先也打开了Query Profile，然后执行一条查询语句：
mysql> show profiles;
+----------+------------+-------------------------------+
| Query_ID | Duration | Query |
+----------+------------+-------------------------------+
| 1 | 0.00122000 | show variables like '%profi%' |
| 2 | 0.65738175 | show processlist |
| 3 | 0.00022550 | SELECT DATABASE() |
| 4 | 1.18196350 | select * from order_item |
+----------+------------+-------------------------------+
4 rows in set (0.59 sec)
mysql> show profile cpu, memory for query 4;
+--------------------+----------+----------+------------+
| Status | Duration | CPU_user | CPU_system |
+--------------------+----------+----------+------------+
| starting | 0.055033 | NULL | NULL |
| Opening tables | 0.967959 | NULL | NULL |
| System lock | 0.000010 | NULL | NULL |
| Table lock | 0.000017 | NULL | NULL |
| init | 0.000121 | NULL | NULL |
| optimizing | 0.000007 | NULL | NULL |
| statistics | 0.000017 | NULL | NULL |
| preparing | 0.000014 | NULL | NULL |
| executing | 0.000006 | NULL | NULL |
| Sending data | 0.158729 | NULL | NULL |
| end | 0.000009 | NULL | NULL |
| query end | 0.000005 | NULL | NULL |
| freeing items | 0.000031 | NULL | NULL |
| logging slow query | 0.000003 | NULL | NULL |
| cleaning up | 0.000005 | NULL | NULL |
+--------------------+----------+----------+------------+
15 rows in set (0.59 sec)
mysql> show profile all for query 4;
+--------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------+-----------------+-------------+
| 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.055033 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | NULL | NULL | NULL |
| Opening tables | 0.967959 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_base.cc | 4483 |
| System lock | 0.000010 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\lock.cc | 258 |
| Table lock | 0.000017 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\lock.cc | 269 |
| init | 0.000121 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_select.cc | 2354 |
| optimizing | 0.000007 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_select.cc | 771 |
| statistics | 0.000017 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_select.cc | 953 |
| preparing | 0.000014 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_select.cc | 963 |
| executing | 0.000006 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_select.cc | 1647 |
| Sending data | 0.158729 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_select.cc | 2194 |
| end | 0.000009 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_select.cc | 2399 |
| query end | 0.000005 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_parse.cc | 4822 |
| freeing items | 0.000031 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_parse.cc | 5849 |
| logging slow query | 0.000003 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_parse.cc | 1628 |
| cleaning up | 0.000005 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_parse.cc | 1595 |
+--------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------+--------
---------+-------------+
15 rows in set (0.00 sec)
每行都是状态变化的过程以及它们持续的时间。
• QUERY_ID is a numeric statement identifier.
• SEQ is a sequence number indicating the display order for rows with the same QUERY_ID value.
• STATE is the profiling state to which the row measurements apply.
• DURATION indicates how long statement execution remained in the given state, in seconds.
• CPU_USER and CPU_SYSTEM indicate user and system CPU use, in seconds.
• CONTEXT_VOLUNTARY and CONTEXT_INVOLUNTARY indicate how many voluntary and involuntary context switches occurred.
• BLOCK_OPS_IN and BLOCK_OPS_OUT indicate the number of block input and output operations.
• MESSAGES_SENT and MESSAGES_RECEIVED indicate the number of communication messages sent and received.
• PAGE_FAULTS_MAJOR and PAGE_FAULTS_MINOR indicate the number of major and minor page faults.
• SWAPS indicates how many swaps occurred.
• SOURCE_FUNCTION, SOURCE_FILE, and SOURCE_LINE provide information indicating where in the source code the profiled state executes.
Status是关于sql语句的状态，和SHOW FULL PROCESSLIST显示的State一致。关于sql语句状态主要有以下几种：
|
Checking table |
正在检查数据表（这是自动的）。 |
|
Closing tables |
正在将表中修改的数据刷新到磁盘中，同时正在关闭已经用完的表。这是一个很快的操作，如果不是这样的话，就应该确认磁盘空间是否已经满了或者磁盘是否正处于重负中。 |
|
Connect Out |
复制从服务器正在连接主服务器 |
|
Copying to tmp table on disk |
由于临时结果集大于 tmp_table_size ，正在将临时表从内存存储转为磁盘存储以此节省内存 |
|
Creating tmp table |
正在创建临时表以存放部分查询结果 |
|
deleting from main table |
服务器正在执行多表删除中的第一部分，刚删除第一个表。 |
|
deleting from reference tables |
服务器正在执行多表删除中的第二部分，正在删除其他 表的记录。 |
|
Flushing tables |
正在执行 FLUSH TABLES ，等待其他线程关闭数据表 |
|
Killed |
发送了一个 kill 请求给某线程，那么这个线程将会检查 kill 标志位，同时会放弃下一个 kill 请求。 MySQL 会在每次的主循环中检查 kill 标志位，不过有些情况下该线程可能会过一小段才能死掉。如果该线程程被其他线程锁住了，那么 kill 请求会在锁释放时马上生效。 |
|
Locked |
被其他查询锁住了 |
|
Sending data |
正在处理 SELECT 查询的记录，同时正在把结果发送给客户端 |
|
Sorting for group |
正在为 GROUP BY 做排序 |
|
Sorting for order |
正在为 ORDER BY 做排序 |
|
Opening tables |
这个过程应该会很快，除非受到其他因素的干扰。例如，在执 ALTER TABLE 或 LOCK TABLE 语句行完以前，数据表无法被其他线程打开。 正尝试打开一个表 |
|
Removing duplicates |
正在执行一个 SELECT DISTINCT 方式的查询，但是 MySQL 无法在前一个阶段优化掉那些重复的记录。因此， MySQL 需要再次去掉重复的记录，然后再把结果发送给客户端 |
|
Reopen table |
获得了对一个表的锁，但是必须在表结构修改之后才能获得这个锁。已经释放锁，关闭数据表，正尝试重新打开数据表 |
|
Repair by sorting |
修复指令正在排序以创建索引 |
|
Repair with keycache |
修复指令正在利用索引缓存一个一个地创建新索引。它会比 Repair by sorting 慢些 |
|
Searching rows for update |
正在讲符合条件的记录找出来以备更新。它必须在 UPDATE 要修改相关的记录之前就完成了 |
|
Sleeping |
正在等待客户端发送新请求 |
|
System lock |
正在等待取得一个外部的系统锁。如果当前没有运行多个 mysqld 服务器同时请求同一个表，那么可以通过增加 --skip-external-locking 参数来禁止外部系统锁 |
|
Upgrading lock |
INSERT DELAYED 正在尝试取得一个锁表以插入新记录 |
|
Updating |
正在搜索匹配的记录，并且修改它们 |
|
User Lock |
正在等待 GET_LOCK() |
|
Waiting for tables |
该线程得到通知，数据表结构已经被修改了，需要重新打开数据表以取得新的结构。然后，为了能的重新打开数据表，必须等到所有其他线程关闭这个表。以下几种情况下会产生这个通知： FLUSH TABLES tbl_name, ALTER TABLE, RENAME TABLE, REPAIR TABLE, ANALYZE TABLE, 或 OPTIMIZE TABLE |
|
waiting for handler insert |
INSERT DELAYED 已经处理完了所有待处理的插入操作，正在等待新的请求 |
