MySQL Query Profiler 查看Mysql具体执行时间以及资源占用

原文链接： http://blog.longwin.com.tw/2008/10/mysql-query-profiler-cpu-ram-time-2008/

MySQL 的 SQL 語法調整主要都是使用 EXPLAIN, 但是這個並沒辦法知道詳細的 Ram(Memory)/CPU 等使用量.

於 MySQL 5.0.37 以上開始支援 MySQL Query Profiler, 可以查詢到此 SQL 會執行多少時間, 並看出 CPU/Memory 使用量, 執行過程中 System lock, Table lock 花多少時間等等.

MySQL Query Profile 詳細介紹可見: Using the New MySQL Query Profiler(2007.04.05 發表)

效能分析主要分下述三種(轉載自上篇):

• Bottleneck analysis - focuses on answering the questions: What is my database server waiting on; what is a user connection waiting on; what is a piece of SQL code waiting on?
• Workload analysis - examines the server and who is logged on to determine the resource usage and activity of each.
• Ratio-based analysis - utilizes a number of rule-of-thumb ratios to gauge performance of a database, user connection, or piece of code.

MySQL Query Profile 使用方法

啟動

• mysql> set profiling=1; # 此命令於 MySQL 會於 information_schema 的 database 建立一個 PROFILING 的 table 來紀錄.

SQL profiles show

• mysql> show profiles; # 從啟動之後所有語法及使用時間, 含錯誤語法都會紀錄.
• ex: (root@localhost) [test]> show profiles; # 注意 Query_ID, 下面執行時間統計等, 都是依 Query_ID 在紀錄

  +----------+------------+---------------------------+| Query_ID | Duration   | Query                     |+----------+------------+---------------------------+|        1 | 0.00090400 | show profile for query 1  ||        2 | 0.00008700 | select * from users       ||        3 | 0.00183800 | show tables               ||        4 | 0.00027600 | mysql> show profiles      |+----------+------------+---------------------------+

查詢所有花費時間加總

• mysql> select sum(duration) from information_schema.profiling where query_id=1; # Query ID = 1

  +---------------+| sum(duration) |+---------------+|      0.000447 |+---------------+

查詢各執行階段花費多少時間

• mysql> show profile for query 1; # Query ID = 1

  +--------------------+------------+| Status             | Duration   |+--------------------+------------+| (initialization)   | 0.00006300 || Opening tables     | 0.00001400 || System lock        | 0.00000600 || Table lock         | 0.00001000 || init               | 0.00002200 || optimizing         | 0.00001100 || statistics         | 0.00009300 || preparing          | 0.00001700 || executing          | 0.00000700 || Sending data       | 0.00016800 || end                | 0.00000700 || query end          | 0.00000500 || freeing items      | 0.00001200 || closing tables     | 0.00000800 || logging slow query | 0.00000400 |+--------------------+------------+

查詢各執行階段花費的各種資源列表

• mysql> show profile cpu for query 1; # Query ID = 1

  +--------------------------------+----------+----------+------------+| Status                         | Duration | CPU_user | CPU_system |+--------------------------------+----------+----------+------------+| (initialization)               | 0.000007 | 0        | 0          || checking query cache for query | 0.000071 | 0        | 0          || Opening tables                 | 0.000024 | 0        | 0          || System lock                    | 0.000014 | 0        | 0          || Table lock                     | 0.000055 | 0.001    | 0          || init                           | 0.000036 | 0        | 0          || optimizing                     | 0.000013 | 0        | 0          || statistics                     | 0.000021 | 0        | 0          || preparing                      | 0.00002  | 0        | 0          || executing                      | 0.00001  | 0        | 0          || Sending data                   | 0.015072 | 0.011998 | 0          || end                            | 0.000021 | 0        | 0          || query end                      | 0.000011 | 0        | 0          || storing result in query cache  | 0.00001  | 0        | 0          || freeing items                  | 0.000018 | 0        | 0          || closing tables                 | 0.000019 | 0        | 0          || logging slow query             | 0.000009 | 0        | 0          |+--------------------------------+----------+----------+------------+

• mysql> show profile IPC for query 1;

  +--------------------------------+----------+---------------+-------------------+| Status                         | Duration | Messages_sent | Messages_received |+--------------------------------+----------+---------------+-------------------+| (initialization)               | 0.000007 |             0 |                 0 || checking query cache for query | 0.000071 |             0 |                 0 || Opening tables                 | 0.000024 |             0 |                 0 || System lock                    | 0.000014 |             0 |                 0 || Table lock                     | 0.000055 |             0 |                 0 || init                           | 0.000036 |             0 |                 0 || optimizing                     | 0.000013 |             0 |                 0 || statistics                     | 0.000021 |             0 |                 0 || preparing                      | 0.00002  |             0 |                 0 || executing                      | 0.00001  |             0 |                 0 || Sending data                   | 0.015072 |             0 |                 0 || end                            | 0.000021 |             0 |                 0 || query end                      | 0.000011 |             0 |                 0 || storing result in query cache  | 0.00001  |             0 |                 0 || freeing items                  | 0.000018 |             0 |                 0 || closing tables                 | 0.000019 |             0 |                 0 || logging slow query             | 0.000009 |             0 |                 0 |+--------------------------------+----------+---------------+-------------------+