查看 MySQL 語法 詳細執行時間 與 CPU/記憶體使用量: MySQL Query Profiler

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 |
    	+--------------------------------+----------+---------------+-------------------+
    	
其它屬性列表
  • ALL - displays all information
  • BLOCK IO - displays counts for block input and output operations
  • CONTEXT SWITCHES - displays counts for voluntary and involuntary context switches
  • 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
設定 Profiling 存的 Size
  • mysql> show variables where variable_name='profiling_history_size'; # 預設是 15筆
關閉
  • mysql> set profiling=0;

相關文章

作者: Tsung

對新奇的事物都很有興趣, 喜歡簡單的東西, 過簡單的生活.

在〈查看 MySQL 語法 詳細執行時間 與 CPU/記憶體使用量: MySQL Query Profiler〉中有 7 則留言

  1. 你好,我是在用debian的,我的MYSQL版本是5.0.32-Debian_7etch6-log
    我怎樣也不能啟動set profiling=1
    回應是: #1193 - Unknown system variable 'profiling'
    請問你有沒有遇到這個問題? 有沒有方法解決? 我已經找了很久!
    我REDHAT上的版本是可以用的...

  2. 這個 "於 MySQL 5.0.37 以上開始支援 MySQL Query Profiler", etch 預設的 5.0.32 是沒有的. XD
    我也是用 Debian 測試的, 不過我是跑 lenny => 5.0.51, 是可以用的.

  3. 先謝謝回覆!
    選擇DEBIAN就是貪它的"STABLE",那我唯有等了!
    ^_^
    P.S. 非常喜歡你的文章,繼續努力呀!

  4. 嗯, Debian 的 stable, leeny 是有預計要進 stable 了, 不過最近一次的消息是說 9月來不及了, 大概還有 200 個重大修正在進行中, 需要再等待一下.. 🙂

發表迴響

這個網站採用 Akismet 服務減少垃圾留言。進一步了解 Akismet 如何處理網站訪客的留言資料