37
mysql 下 show profile 備忘
mysql 中可利用 show profile 進行性能分析
show profile 功能默認狀態下為關閉， 因消耗一定資源
查詢方法
mysql> select @@profiling;
+-------------+
| @@profiling |
+-------------+
| 0 | 0 = 關閉 1 = 啟用
+-------------+
1 row in set (0.00 sec)
打開方法
mysql> set profiling = 1;
Query OK, 0 rows affected (0.00 sec)
mysql> select @@profiling;
+-------------+
| @@profiling |
+-------------+
| 1 |
+-------------+
1 row in set (0.00 sec)
啟用 profiling 功能後就可以對 SQL 進行分析。
為避免之前已經把 SQL 存放在 QCACHE 中， 建議在執行 SQL 時， 強製 SELECT 語句不進行 QCACHE 檢測
如下麵 SQL
mysql> select sql_no_cache distinct prewarebro0_.ID as ID471_, prewarebro0_.SPECIFICATION_ID as SPECIFIC2_471_, prewarebro0_.SPECIES_ID as SPECIES3_471_, prewarebro0_.SPECIES_CODE as SPECIES4_471_,
prewarebro0_.DETAIL_URL as DETAIL5_471_, prewarebro0_.SALEPRICE as SALEPRICE471_, prewarebro0_.TYPE as TYPE471_, prewarebro0_.CREATE_TIME as CREATE8_471_, prewarebro0_.PICTUREURL as PICTUREURL471_, prewarebro0_.USER_KO as USER10_471_ from PRE_WARE_BROSWERS
prewarebro0_ cross join WARE_DIRECTORY_SUMA waredirect1_ cross join WARE_CON_DIECTORY warecondir2_ cross join WARE_MOUNTED waremounte3_ cross join WARE_CATALOG specificat4_ where waredirect1_.ID=warecondir2_.SUMA_ID and warecondir2_.ID=waremounte3_.CON_CODE
and prewarebro0_.SPECIFICATION_ID=waremounte3_.MOUNT_CODE and prewarebro0_.SPECIFICATION_ID=specificat4_.ID and waredirect1_.STATUS='1' and waremounte3_.STATUS='1' and specificat4_.STATUS=1 and prewarebro0_.USER_KO='38a89ba4e0595ff0d06ab0744f64344f' order
by prewarebro0_.CREATE_TIME desc limit 3 ;
Empty set (0.51 sec)
當執行完 SQL 之後，可以對該 SQL 進行分析， 如
mysql> show profile;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000793 |
| checking permissions | 0.000012 |
| checking permissions | 0.000006 |
| checking permissions | 0.000005 |
| checking permissions | 0.000005 |
| checking permissions | 0.000010 |
| Opening tables | 0.000132 |
| System lock | 0.000047 |
| init | 0.000160 |
| optimizing | 0.000084 |
| statistics | 0.000264 |
| preparing | 0.000146 |
| Creating tmp table | 0.000100 |
| executing | 0.000008 |
| Copying to tmp table | 0.515277 |
| Sorting result | 0.000045 |
| Sending data | 0.000039 |
| end | 0.000012 |
| removing tmp table | 0.000019 |
| end | 0.000008 |
| query end | 0.000014 |
| closing tables | 0.000055 |
| freeing items | 0.000087 |
| logging slow query | 0.000005 |
| cleaning up | 0.000014 |
+----------------------+----------+
25 rows in set (0.00 sec)
我們看到了， 明顯就是 copying to tmp table 值比較不正常，不進行字麵解釋了
看看當前我們電腦緩存了多少可以進行分析的 SQL
mysql> show profiles;
+----------+------------+------------------------------------------+
| Query_ID | Duration | Query |
+----------+------------+------------------------------------------+
| 1 | 0.00026925 | select * from ware_stocks where id < 15 |
| 2 | 0.00032250 | SELECT DATABASE() |
| 3 | 0.00102075 | show databases |
| 4 | 0.00388575 | show tables |
| 5 | 0.00021200 | select * from ware_stocks where id < 15 |
| 6 | 0.01826000 | select * from ware_stocks where id < 55 |
| 7 | 0.02039825 | select * from ware_stocks where id < 155 |
| 8 | 0.03401675 | select * from ware_stocks where id > 3 |
+----------+------------+------------------------------------------+
8 rows in set (0.00 sec)
上麵記錄了一共 8 條 SQL 分析， 假如要分析某一條， 那麼可以執行 (參考上表中 ID 值進行分析)
mysql> show profile for query 8;
+--------------------------------+----------+
| Status | Duration |
+--------------------------------+----------+
| starting | 0.000164 |
| Waiting for query cache lock | 0.000010 |
| checking query cache for query | 0.000197 |
| checking permissions | 0.000026 |
| Opening tables | 0.000094 |
| System lock | 0.000038 |
| Waiting for query cache lock | 0.000095 |
| init | 0.000122 |
| optimizing | 0.000025 |
| statistics | 0.000073 |
| preparing | 0.000032 |
| executing | 0.000008 |
| Sending data | 0.010331 |
| Waiting for query cache lock | 0.000020 |
| Sending data | 0.005885 |
| Waiting for query cache lock | 0.000011 |
| Sending data | 0.005877 |
| Waiting for query cache lock | 0.000010 |
| Sending data | 0.005998 |
| Waiting for query cache lock | 0.000011 |
| Sending data | 0.004589 |
| end | 0.000022 |
| query end | 0.000031 |
| closing tables | 0.000050 |
| freeing items | 0.000038 |
| Waiting for query cache lock | 0.000010 |
| freeing items | 0.000213 |
| Waiting for query cache lock | 0.000009 |
| freeing items | 0.000005 |
| storing result in query cache | 0.000009 |
| logging slow query | 0.000006 |
| cleaning up | 0.000010 |
+--------------------------------+----------+
32 rows in set (0.01 sec)
另外，還可以獨立地分析某項資源，方便參考
o ALL displays all information
o BLOCK IO displays counts for block input and output operations
o CONTEXT SWITCHESdisplays counts for voluntary and involuntary
context switches
o CPU displays user and system CPU usage times
o IPC displays counts for messages sent and received
o MEMORY is not currently implemented
o PAGE FAULTS displays counts for major and minor page faults
o 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
o SWAPS displays swap counts
參考之前信息，我們看看 Copying to tmp table的IO情況
mysql> show profile block io for query 9;
+----------------------+----------+--------------+---------------+
| Status | Duration | Block_ops_in | Block_ops_out |
+----------------------+----------+--------------+---------------+
| starting | 0.000483 | 0 | 0 |
| checking permissions | 0.000012 | 0 | 0 |
| checking permissions | 0.000006 | 0 | 0 |
| checking permissions | 0.000006 | 0 | 0 |
| checking permissions | 0.000006 | 0 | 0 |
| checking permissions | 0.000010 | 0 | 0 |
| Opening tables | 0.000162 | 0 | 0 |
| System lock | 0.000056 | 0 | 0 |
| init | 0.000179 | 0 | 0 |
| optimizing | 0.000074 | 0 | 0 |
| statistics | 0.000225 | 0 | 0 |
| preparing | 0.000173 | 0 | 0 |
| Creating tmp table | 0.000127 | 0 | 0 |
| executing | 0.000008 | 0 | 0 |
| Copying to tmp table | 0.837154 | 0 | 8 | 產生 8 次的 IO 了用於創建 TMP TABLE 了
| Sorting result | 0.000059 | 0 | 0 |
| Sending data | 0.000050 | 0 | 0 |
| end | 0.000017 | 0 | 0 |
| removing tmp table | 0.000025 | 0 | 0 |
| end | 0.000012 | 0 | 0 |
| query end | 0.000018 | 0 | 0 |
| closing tables | 0.000071 | 0 | 0 |
| freeing items | 0.000097 | 0 | 0 |
| logging slow query | 0.000006 | 0 | 0 |
| cleaning up | 0.000012 | 0 | 0 |
+----------------------+----------+--------------+---------------+
25 rows in set (0.00 sec)
參考 CPU
mysql> show profile CPU for query 9;
+----------------------+----------+----------+------------+
| Status | Duration | CPU_user | CPU_system |
+----------------------+----------+----------+------------+
| starting | 0.000483 | 0.000000 | 0.000000 |
| checking permissions | 0.000012 | 0.000000 | 0.000000 |
| checking permissions | 0.000006 | 0.000000 | 0.000000 |
| checking permissions | 0.000006 | 0.000000 | 0.000000 |
| checking permissions | 0.000006 | 0.000000 | 0.000000 |
| checking permissions | 0.000010 | 0.000000 | 0.000000 |
| Opening tables | 0.000162 | 0.002000 | 0.000000 |
| System lock | 0.000056 | 0.000000 | 0.000000 |
| init | 0.000179 | 0.000000 | 0.000000 |
| optimizing | 0.000074 | 0.000000 | 0.000000 |
| statistics | 0.000225 | 0.000000 | 0.000000 |
| preparing | 0.000173 | 0.000000 | 0.000000 |
| Creating tmp table | 0.000127 | 0.000000 | 0.000000 |
| executing | 0.000008 | 0.000000 | 0.000000 |
| Copying to tmp table | 0.837154 | 1.166823 | 0.001000| 也嚴重消耗了 CPU
| Sorting result | 0.000059 | 0.000000 | 0.000000 |
| Sending data | 0.000050 | 0.000000 | 0.000000 |
| end | 0.000017 | 0.000000 | 0.000000 |
| removing tmp table | 0.000025 | 0.000000 | 0.000000 |
| end | 0.000012 | 0.000000 | 0.000000 |
| query end | 0.000018 | 0.000000 | 0.000000 |
| closing tables | 0.000071 | 0.000000 | 0.000000 |
| freeing items | 0.000097 | 0.000000 | 0.000000 |
| logging slow query | 0.000006 | 0.000000 | 0.000000 |
| cleaning up | 0.000012 | 0.000000 | 0.000000 |
+----------------------+----------+----------+------------+
25 rows in set (0.01 sec)
總結, 分析後，切記 set profiling = 0 , 另外可以配合 explain 更方便地對執行計劃進行分析。
最後更新：2017-04-03 14:54:00