コンソールに出力せずにMySQLクエリの実行時間を確認する方法

MySQLクエリの実行時間を確認する基本：プロファイリング機能

コンソールに余計な結果を出力することなく、MySQLのクエリが実際にどれほどの時間で処理されたのかを知りたい場合には、「プロファイリング」機能を利用します。プロファイリング情報には、現在のセッション内で実行されたステートメントのリソース使用状況が記録されており、SHOW PROFILE および SHOW PROFILES ステートメントによって取得できます。

手順1：プロファイリングを有効にする

これらのステートメントを実行する前に、セッション変数 profiling を 1 に設定しておく必要があります。設定は以下のように行います。

mysql> set profiling = 1;
Query OK, 0 rows affected (0.00 sec)

手順2：実行したクエリの一覧と所要時間を表示する（SHOW PROFILES）

プロファイリングを有効にした状態で SHOW PROFILES を実行すると、サーバーに送信された直近のステートメントの一覧が、クエリID（Query_ID）と所要時間（Duration）とともに表示されます。

mysql> show profiles;
+----------+------------+--------------------------------------+
| Query_ID | Duration   | Query                                |
+----------+------------+--------------------------------------+
| 1        | 0.01602200 | drop table if exists t1              |
| 2        | 0.57223450 | create table t1(id int)              |
| 3        | 0.00015425 | show profile for query1              |
| 4        | 0.22945050 | create table e1(id int)              |
| 5        | 0.09977025 | insert into e1(id) values(3),(4),(5) |
+----------+------------+--------------------------------------+
5 rows in set (0.00 sec)

手順3：特定のクエリの詳細な内訳を確認する（SHOW PROFILE）

個別のクエリについてさらに詳しく調査したい場合は、SHOW PROFILE FOR QUERY クエリ番号 を実行します。たとえば query_id = 5 のクエリに対して実行すると、次のような段階ごとの所要時間が出力されます。

mysql> show profile for query 5;
+------------------------------+--------------+
| Status                       | Duration     |
+------------------------------+--------------+
| starting                     | 0.000138     |
| checking permissions         | 0.000024     |
| Opening tables               | 0.000057     |
| System lock                  | 0.035186     |
| init                         | 0.000035     |
| update                       | 0.021484     |
| Waiting for query cache lock | 0.000021     |
| update                       | 0.000005     |
| end                          | 0.000024     |
| query end                    | 0.042700     |
| closing tables               | 0.000017     |
| freeing items                | 0.000076     |
| logging slow query           | 0.000003     |
| cleaning up                  | 0.000002     |
+------------------------------+--------------+
14 rows in set (0.00 sec)

この結果を見れば、権限チェック、テーブルのオープン、システムロックの待機、クエリ終了後の後始末など、どの処理段階に時間がかかっているのかを把握できます。ボトルネックの特定やパフォーマンスチューニングを行う際に非常に役立つ情報です。

補足：非推奨機能である点に注意

SHOW PROFILE / SHOW PROFILES は MySQL 5.6.7 以降では非推奨（Deprecated）とされており、将来のバージョンで削除される可能性があります。最新のMySQL環境では、パフォーマンススキーマ（Performance Schema）の events_statements_history_long テーブルなどを利用して、同様の実行時間情報を取得することが推奨されています。既存システムでの簡易的な確認には引き続き便利ですが、新規開発ではパフォーマンススキーマの活用を検討しましょう。