Feb
03
2009
プロファイリングで快適MySQLチューニング生活
Posted by Mikiya Okuno on Tue 03 Feb 2009 00:50 UTC
Tags:

MySQL 5.1からデフォルトで有効になっている便利な機能としてプロファイリングというものがある。MySQL 5.0でも利用出来たのだが、実験的な機能という位置づけであり、搭載されていたのはGPL版のMySQL Community Server限定だった。MySQL 5.1からは全てのエディションでプロファイリングを利用することができる。

プロファイリング機能を利用すると、クエリの状態（特に状態遷移やリソースの消費状況）を詳細に分析できるのでとても便利だ。MySQLエンジニア必携の機能といって良いだろう。というわけでプロファイリング機能の使い方を説明しよう。

MySQLサーバにログインしたら、まずは次のようにしてプロファイリングを有効にする。

mysql> SET profiling=1;


すると、クエリの情報が記録されるようになる。次に、分析したいクエリを実行する。クエリはなんでもいい。SHOWコマンドでもOKだ。

mysql> SHOW LOCAL STATUS;
+-----------------------------------+-----------+
| Variable_name                     | Value     |
+-----------------------------------+-----------+
| Aborted_clients                   | 0         |
| Aborted_connects                  | 0         |
| Binlog_cache_disk_use             | 0         |

・・・中略・・・

| Uptime                            | 1034      |
| Uptime_since_flush_status         | 1034      |
+-----------------------------------+-----------+
290 rows in set (1.07 sec)


すると、クエリの情報が記録される。すると、その情報を次のコマンドで見ることができる。

mysql> SHOW PROFILE;
+---------------------------+----------+
| Status                    | Duration |
+---------------------------+----------+
| starting                  | 0.000089 |
| Opening tables            | 0.000237 |
| System lock               | 0.000005 |
| Table lock                | 0.000009 |
| init                      | 0.000009 |
| optimizing                | 0.000005 |
| statistics                | 0.000009 |
| preparing                 | 0.000009 |
| executing                 | 0.001803 |
| converting HEAP to MyISAM | 0.003110 |
| executing                 | 0.982382 |
| Sending data              | 0.031821 |
| end                       | 0.000017 |
| query end                 | 0.000006 |
| freeing items             | 0.000080 |
| removing tmp table        | 0.020215 |
| closing tables            | 0.000021 |
| logging slow query        | 0.000007 |
| cleaning up               | 0.000009 |
+---------------------------+----------+
19 rows in set (0.00 sec)


SHOW PROFILEは、デフォルトではStatusとDurationを表示する。StatusはSHOW PROCESSLISTで表示されるステータスと同じだ。Durationは経過時間である。つまり、どの段階の処理にどのぐらい時間がかかったのかが一目で分かるのである。しかし、ステータス表示だけでは具体的に何をしていたのか・・・つまりどの関数が呼ばれたのかが分かりにくい。それを調べるにはソースコードからthd_proc_info()によってステータスがセットされている箇所（またはthd->proc_info="..."となっている箇所）を探し出さないといけないのか？！そんな面倒なことをしなければいけないのかぁ〜〜〜ッ？！！と思うかも知れないが、焦ることはない。ちゃんとそのための機能も備わっている。

mysql> SHOW PROFILE SOURCE;
+---------------------------+----------+-------------------------+---------------+-------------+
| Status                    | Duration | Source_function         | Source_file   | Source_line |
+---------------------------+----------+-------------------------+---------------+-------------+
| starting                  | 0.000157 | NULL                    | NULL          |        NULL |
| Opening tables            | 0.000277 | open_tables             | sql_base.cc   |        4450 |
| System lock               | 0.000004 | mysql_lock_tables       | lock.cc       |         258 |
| Table lock                | 0.000015 | mysql_lock_tables       | lock.cc       |         269 |
| init                      | 0.000032 | mysql_select            | sql_select.cc |        2337 |
| optimizing                | 0.000015 | optimize                | sql_select.cc |         762 |
| statistics                | 0.000028 | optimize                | sql_select.cc |         944 |
| preparing                 | 0.000018 | optimize                | sql_select.cc |         954 |
| executing                 | 0.001802 | exec                    | sql_select.cc |        1638 |
| converting HEAP to MyISAM | 0.004623 | create_myisam_from_heap | sql_select.cc |       10583 |
| executing                 | 0.635508 | create_myisam_from_heap | sql_select.cc |       10648 |
| Sending data              | 0.031459 | exec                    | sql_select.cc |        2177 |
| end                       | 0.000027 | mysql_select            | sql_select.cc |        2382 |
| query end                 | 0.000005 | mysql_execute_command   | sql_parse.cc  |        4799 |
| freeing items             | 0.000130 | mysql_parse             | sql_parse.cc  |        5805 |
| removing tmp table        | 0.023404 | free_tmp_table          | sql_select.cc |       10527 |
| closing tables            | 0.000014 | free_tmp_table          | sql_select.cc |       10549 |
| logging slow query        | 0.000004 | log_slow_statement      | sql_parse.cc  |        1608 |
| cleaning up               | 0.000007 | dispatch_command        | sql_parse.cc  |        1575 |
+---------------------------+----------+-------------------------+---------------+-------------+
19 rows in set (0.00 sec)


おおっ！これは直感的で便利である。

ところで、実はこのプロファイルから一つ問題を見付けることができる。SHOW LOCAL STATUSごときで何の問題が出るんだ？！と思うかも知れないがよく見てみて欲しい。中ほどに「converting HEAP to MyISAM」となっている行があるのが分かるだろう。えっ？なんでHEAPテーブルからMyISAMテーブルへの変換が？？なんで？？と思うだろう。

MySQLのSHOWコマンドは、ほとんどがメモリベースのテンポラリテーブルを利用して実装されている。必要な情報を収集してメモリテーブルに格納し、そのメモリテーブルからデータをクライアントへ送信するという仕組みである。もしテンポラリテーブルが小さ過ぎて、テンポラリテーブルのサイズ上限に達してしまうと、内部的にMyISAMテーブルに変換される。が、そのような処理はとても重いので、本番環境ではMyISAMへの変換が起きないよう適切にテンポラリテーブルのサイズを調整する必要がある。MyISAMへの変換がどれぐらい重いかということは、クエリの実行時間を見れば分かるだろう。なんと1秒以上もかかっている！

実はこのMySQLサーバではテンポラリテーブルのサイズは次のようになっている。

mysql> SHOW VARIABLES LIKE 'tmp_table_size';
+----------------+---------+
| Variable_name  | Value   |
+----------------+---------+
| tmp_table_size | 1048576 |
+----------------+---------+
1 row in set (0.00 sec)


たったの1Mである。もちろんこれは人為的に作り出した状況なので、実際の運用ではあまり見かけない小さな値である。というわけでこれを次のように修正してからSHOW LOCAL STATUSを実行してみよう。

mysql> SET tmp_table_size=64*1024*1024;
Query OK, 0 rows affected (0.00 sec)

mysql> SHOW LOCAL STATUS;
+-----------------------------------+-----------+
| Variable_name                     | Value     |
+-----------------------------------+-----------+
| Aborted_clients                   | 0         |
| Aborted_connects                  | 0         |
| Binlog_cache_disk_use             | 0         |

・・・中略・・・

| Uptime                            | 917       |
| Uptime_since_flush_status         | 917       |
+-----------------------------------+-----------+
290 rows in set (0.05 sec)


おおっ。経過時間がたったの0.05秒まで下がった！実際、これによりコマンドに対するレスポンスの向上が体感できる。そしてSHOW PROFILEからも改善の様子がうかがえる。（HEAPらMyISAMへの変換が行われていないでしょ？）

mysql> SHOW PROFILE SOURCE;
+--------------------+----------+-----------------------+---------------+-------------+
| Status             | Duration | Source_function       | Source_file   | Source_line |
+--------------------+----------+-----------------------+---------------+-------------+
| starting           | 0.000095 | NULL                  | NULL          |        NULL |
| Opening tables     | 0.000286 | open_tables           | sql_base.cc   |        4450 |
| System lock        | 0.000005 | mysql_lock_tables     | lock.cc       |         258 |
| Table lock         | 0.000020 | mysql_lock_tables     | lock.cc       |         269 |
| init               | 0.000011 | mysql_select          | sql_select.cc |        2337 |
| optimizing         | 0.000005 | optimize              | sql_select.cc |         762 |
| statistics         | 0.000010 | optimize              | sql_select.cc |         944 |
| preparing          | 0.000008 | optimize              | sql_select.cc |         954 |
| executing          | 0.028799 | exec                  | sql_select.cc |        1638 |
| Sending data       | 0.009732 | exec                  | sql_select.cc |        2177 |
| end                | 0.000031 | mysql_select          | sql_select.cc |        2382 |
| query end          | 0.000004 | mysql_execute_command | sql_parse.cc  |        4799 |
| freeing items      | 0.000094 | mysql_parse           | sql_parse.cc  |        5805 |
| removing tmp table | 0.003427 | free_tmp_table        | sql_select.cc |       10527 |
| closing tables     | 0.000007 | free_tmp_table        | sql_select.cc |       10549 |
| logging slow query | 0.000002 | log_slow_statement    | sql_parse.cc  |        1608 |
| cleaning up        | 0.000004 | dispatch_command      | sql_parse.cc  |        1575 |
+--------------------+----------+-----------------------+---------------+-------------+
17 rows in set (0.00 sec)


PROFILEの種類はSOURCE以外にも次のものを指定することができる。

  • ALL・・・すべての情報を表示。
  • BLOCK IO・・・ディスクへのBlock I/Oの回数。
  • CONTEXT SWITCHES・・・コンテキストスイッチの回数。
  • CPU・・・CPUの使用時間。（システム、ユーザの内訳など。）
  • IPC・・・メッセージ送受信。
  • MEMORY・・・未実装。（これは待望の機能である！！）
  • PAGE FAULTS・・・ページフォルト回数。
  • SWAPS・・・スワップアウトの回数。

ただし、CPUなどのリソース情報に関しては一つだけ注意点がある。SHOW PROFILEはgetrusage()システムコールを用いて情報を取得しているのだが、getrusage()はスレッド単位ではなくプロセス単位の情報しか取得することができない。そのため、MySQLサーバに対して負荷のまったくない状態でないと正確なプロファイル情報を取得できないのである。（Durationについても同じことが言えるが、MySQLサーバの負荷が低いときのほうがクエリの実行時間が短くなるのは当然だろう。）

ところで、実はプロファイル情報は過去の履歴がストックされている。最大でprofiling_history_size個まで履歴を参照することが可能である。profiling_history_sizeのデフォルト値は15、最大値は100なので、ステップ数の多いトランザクションを処理する場合などには増やすといいだろう。プロファイル情報の履歴は次のようにして参照することができる。

mysql> SHOW PROFILES;
+----------+------------+-------------------------------+
| Query_ID | Duration   | Query                         |
+----------+------------+-------------------------------+
|        1 | 1.03984300 | SHOW LOCAL STATUS             |
|        2 | 0.69961500 | SHOW GLOBAL STATUS            |
|        3 | 0.00078000 | SHOW DATABASES                |
|        4 | 0.00022000 | SELECT DATABASE()             |
|        5 | 0.00059500 | show databases                |
|        6 | 0.54332000 | show tables                   |
|        7 | 0.00092800 | SHOW TABLES                   |
|        8 | 0.00031400 | SELECT * FROM ptest LIMIT 100 |
+----------+------------+-------------------------------+
8 rows in set (0.00 sec)


特定のクエリの情報を見たい場合には次のコマンドを実行する。

mysql> SHOW PROFILE SOURCE FOR QUERY 1;


プロファイリングは、クエリの実行計画はそんなに問題ないのにどこかで時間がかかってしまう、つまりサーバパラメータの調整が必要になるような場合に威力を発揮する。プロファイリングがクエリのチューニングに役立つことは間違いないので、ぜひ活用して遅いクエリを撲滅しよう！！だがその前により基本であるEXPLAINを忘れるべからず！！