MySQL Query Profile

MySQL Query Profiler, 能够查询到此 SQL 语句会执行多少, 并看出 CPU/Memory 使用量, 执行过程 System lock, Table lock 花多少时间等等.从启动Profile以后的全部查询包括错误语句都会被记录。mysql的sql语句优化也可使用explain,可是执行计划是没有办法知道详细的Memory/CPU等使用量。html

         SHOW PROFILE [type [, type] ... ] [FOR QUERY n] [LIMIT row_count [OFFSET offset]]mysql

type:    ALL  | BLOCK IO  | CONTEXT SWITCHES  | CPU  | IPC  | MEMORY  | PAGE FAULTS  | SOURCE  | SWAPSsql

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 operationsapp

    • CONTEXT SWITCHES displays counts for voluntary and involuntary context switcheside

    • CPU displays user and system CPU usage times优化

    • IPC displays counts for messages sent and receivedspa

    • 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 已经处理完了全部待处理的插入操做,正在等待新的请求

 

http://dev.mysql.com/doc/refman/5.1/en/show-profile.html

相关文章
相关标签/搜索