![variable.jp [データベース,パフォーマンス,運用]](https://variable.jp/wp-content/uploads/2013/09/cropped-variable.jp_.jpg)
MYSQLにもMSSQLやOracleのようにProfilerが無いか以前にも検証したのですが、
暫く現場を離れていて忘れていたのでセルフリマインドの為に再確認です。
MYSQL Profiling
Queryの実行プランは、その他DBと同じく実行プランの確認とインデックスの有無で対応可能ですが、
サーバーパラメーターのチューニングにPROFILEを利用してどのDB処理が遅いが確認する事が出来ます。
必要に応じてmy.cnfや動的パラメーターを変更しましょう。
Oracle (例)
EXPLAIN PLAN FOR select * from テーブル名;
MYSQL (例)
EXPLAIN select * from テーブル名;
mysql> explain select * from orders where o_id = 100; +----+-------------+--------+------+---------------+------+---------+------+-------+-------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +----+-------------+--------+------+---------------+------+---------+------+-------+-------------+ | 1 | SIMPLE | orders | ALL | NULL | NULL | NULL | NULL | 71933 | Using where | +----+-------------+--------+------+---------------+------+---------+------+-------+-------------+ 1 row in set (0.01 sec) mysql>
PROFILEのONとOFFについて
mysql> SET profiling=1; Query OK, 0 rows affected (0.00 sec) mysql> SHOW VARIABLES LIKE 'profil%'; +------------------------+-------+ | Variable_name | Value | +------------------------+-------+ | profiling | ON | | profiling_history_size | 15 | +------------------------+-------+ 2 rows in set (0.00 sec) mysql> SET profiling=0; Query OK, 0 rows affected (0.00 sec) mysql> SHOW VARIABLES LIKE 'profil%'; +------------------------+-------+ | Variable_name | Value | +------------------------+-------+ | profiling | OFF | | profiling_history_size | 15 | +------------------------+-------+ 2 rows in set (0.00 sec) mysql> mysql> show variables like 'profiling_history_size'; +------------------------+-------+ | Variable_name | Value | +------------------------+-------+ | profiling_history_size | 15 | +------------------------+-------+ 1 row in set (0.00 sec) mysql>
実際に実行してみると、Source_functionとDurationでどの処理が、
どの位内部処理に時間がかかっているか確認出来る。
mysql> set profiling=1;
Query OK, 0 rows affected (0.00 sec)[省略]
mysql> show databases;
+——————–+
| Database |
+——————–+
| information_schema |
| mysql |
| performance_schema |
| test |
| tpcc |
+——————–+
5 rows in set (0.00 sec)mysql> show profiles;
+———-+————+——————-+
| Query_ID | Duration | Query |
+———-+————+——————-+
| 1 | 0.00636075 | show local status |
| 2 | 0.00027875 | set profiling=1 |
| 3 | 0.01078700 | show local status |
| 4 | 0.01107825 | show databases |
+———-+————+——————-+
4 rows in set (0.00 sec)mysql> SHOW PROFILE SOURCE;
+——————–+———-+———————–+—————+————-+
| Status | Duration | Source_function | Source_file | Source_line |
+——————–+———-+———————–+—————+————-+
| starting | 0.001011 | NULL | NULL | NULL |
| Opening tables | 0.000583 | open_tables | sql_base.cc | 4838 |
| System lock | 0.000057 | mysql_lock_tables | lock.cc | 299 |
| init | 0.000062 | mysql_select | sql_select.cc | 2554 |
| optimizing | 0.000026 | optimize | sql_select.cc | 863 |
| statistics | 0.000055 | optimize | sql_select.cc | 1054 |
| preparing | 0.000041 | optimize | sql_select.cc | 1076 |
| executing | 0.003726 | exec | sql_select.cc | 1823 |
| Sending data | 0.000117 | exec | sql_select.cc | 2365 |
| end | 0.000026 | mysql_select | sql_select.cc | 2590 |
| query end | 0.000017 | mysql_execute_command | sql_parse.cc | 4439 |
| closing tables | 0.000007 | mysql_execute_command | sql_parse.cc | 4491 |
| removing tmp table | 0.000100 | free_tmp_table | sql_select.cc | 11180 |
| closing tables | 0.000015 | free_tmp_table | sql_select.cc | 11205 |
| freeing items | 0.004987 | mysql_parse | sql_parse.cc | 5639 |
| logging slow query | 0.000031 | log_slow_statement | sql_parse.cc | 1460 |
| cleaning up | 0.000218 | dispatch_command | sql_parse.cc | 1416 |
+——————–+———-+———————–+—————+————-+
17 rows in set (0.00 sec)
Query_IDを指定して過去に実行したQuery詳細を確認
mysql> SHOW PROFILEs;
+———-+————+———————————————-+
| Query_ID | Duration | Query |
+———-+————+———————————————-+
| 1 | 0.00636075 | show local status |
| 2 | 0.00027875 | set profiling=1 |
| 3 | 0.01078700 | show local status |
| 4 | 0.01107825 | show databases |
| 5 | 0.00268775 | SHOW VARIABLES LIKE ‘tmp_table_size’ |
| 6 | 0.01079550 | show local status |
| 7 | 0.00259425 | show variables like ‘profiling_history_size’ |
+———-+————+———————————————-+
7 rows in set (0.00 sec)mysql> SHOW PROFILE SOURCE FOR QUERY 7;
+——————–+———-+———————–+—————+————-+
| Status | Duration | Source_function | Source_file | Source_line |
+——————–+———-+———————–+—————+————-+
| starting | 0.000268 | NULL | NULL | NULL |
| Opening tables | 0.000510 | open_tables | sql_base.cc | 4838 |
| System lock | 0.000055 | mysql_lock_tables | lock.cc | 299 |
| init | 0.000050 | mysql_select | sql_select.cc | 2554 |
| optimizing | 0.000018 | optimize | sql_select.cc | 863 |
| statistics | 0.000028 | optimize | sql_select.cc | 1054 |
| preparing | 0.000023 | optimize | sql_select.cc | 1076 |
| executing | 0.001354 | exec | sql_select.cc | 1823 |
| Sending data | 0.000089 | exec | sql_select.cc | 2365 |
| end | 0.000016 | mysql_select | sql_select.cc | 2590 |
| query end | 0.000010 | mysql_execute_command | sql_parse.cc | 4439 |
| closing tables | 0.000005 | mysql_execute_command | sql_parse.cc | 4491 |
| removing tmp table | 0.000080 | free_tmp_table | sql_select.cc | 11180 |
| closing tables | 0.000014 | free_tmp_table | sql_select.cc | 11205 |
| freeing items | 0.000058 | mysql_parse | sql_parse.cc | 5639 |
| logging slow query | 0.000008 | log_slow_statement | sql_parse.cc | 1460 |
| cleaning up | 0.000010 | dispatch_command | sql_parse.cc | 1416 |
+——————–+———-+———————–+—————+————-+
17 rows in set (0.01 sec)mysql>
その他のProfileオプション
mysql> SHOW PROFILE ALL; mysql> SHOW PROFILE BLOCK IO; mysql> SHOW PROFILE CONTEXT SWITCHES; mysql> SHOW PROFILE CPU; mysql> SHOW PROFILE IPC; mysql> SHOW PROFILE MEMORY; mysql> SHOW PROFILE PAGE FAULTS;
最後にシンプルに特定クエリーだけ確認
mysql> SET profiling = 1; Query OK, 0 rows affected (0.01 sec) mysql> select * from T_Archive_Log where id = 100; +-----+---------------------+------------------------------------------------------------------+------------+------------+-------------+ | id | Sdd | Rdd | Error_Code | conf_time | flag | +-----+---------------------+------------------------------------------------------------------+------------+------------+-------------+ | 100 | admin@variable.jp | 59AA9E550C91F84FCD7777713258CBA9E56655E6089F2657838AFFE48BDCC6F9 | 550 | 2011-10-12 | 0 | +-----+---------------------+------------------------------------------------------------------+------------+------------+-------------+ 1 row in set (0.01 sec) mysql> SHOW PROFILES; +----------+------------+--------------------------------------------+ | Query_ID | Duration | Query | +----------+------------+--------------------------------------------+ | 1 | 0.00117200 | select * from T_Archive_Log where id = 100 | +----------+------------+--------------------------------------------+ 1 row in set (0.00 sec) mysql> SHOW PROFILE FOR QUERY 1; +--------------------------------+----------+ | Status | Duration | +--------------------------------+----------+ | starting | 0.000789 | | Waiting for query cache lock | 0.000005 | | checking query cache for query | 0.000022 | | checking permissions | 0.000005 | | Opening tables | 0.000016 | | System lock | 0.000012 | | Waiting for query cache lock | 0.000005 | | init | 0.000017 | | optimizing | 0.000010 | | statistics | 0.000071 | | preparing | 0.000013 | | executing | 0.000003 | | Sending data | 0.000154 | | end | 0.000012 | | query end | 0.000004 | | closing tables | 0.000009 | | freeing items | 0.000016 | | logging slow query | 0.000004 | | cleaning up | 0.000005 | +--------------------------------+----------+ 19 rows in set (0.02 sec) mysql> SHOW PROFILE SOURCE FOR QUERY 1; +--------------------------------+----------+-----------------------+---------------+-------------+ | Status | Duration | Source_function | Source_file | Source_line | +--------------------------------+----------+-----------------------+---------------+-------------+ | starting | 0.000789 | NULL | NULL | NULL | | Waiting for query cache lock | 0.000005 | try_lock | sql_cache.cc | 454 | | checking query cache for query | 0.000022 | send_result_to_client | sql_cache.cc | 1561 | | checking permissions | 0.000005 | check_access | sql_parse.cc | 4745 | | Opening tables | 0.000016 | open_tables | sql_base.cc | 4837 | | System lock | 0.000012 | mysql_lock_tables | lock.cc | 299 | | Waiting for query cache lock | 0.000005 | try_lock | sql_cache.cc | 454 | | init | 0.000017 | mysql_select | sql_select.cc | 2554 | | optimizing | 0.000010 | optimize | sql_select.cc | 863 | | statistics | 0.000071 | optimize | sql_select.cc | 1054 | | preparing | 0.000013 | optimize | sql_select.cc | 1076 | | executing | 0.000003 | exec | sql_select.cc | 1823 | | Sending data | 0.000154 | exec | sql_select.cc | 2365 | | end | 0.000012 | mysql_select | sql_select.cc | 2590 | | query end | 0.000004 | mysql_execute_command | sql_parse.cc | 4434 | | closing tables | 0.000009 | mysql_execute_command | sql_parse.cc | 4486 | | freeing items | 0.000016 | mysql_parse | sql_parse.cc | 5634 | | logging slow query | 0.000004 | log_slow_statement | sql_parse.cc | 1460 | | cleaning up | 0.000005 | dispatch_command | sql_parse.cc | 1416 | +--------------------------------+----------+-----------------------+---------------+-------------+ 19 rows in set (0.00 sec) mysql> SET profiling = 0; Query OK, 0 rows affected (0.00 sec) mysql>
参考サイト：
MYSQL Profiling
MySQLのEXPLAINを徹底解説!!
プロファイリングで快適MySQLチューニング生活