Azure Database for MySQL - フレキシブル サーバーのクエリ パフォーマンスのトラブルシューティング

クエリのパフォーマンスは複数の要因によって影響を受ける可能性があります。そのため、まず、Azure Database for MySQL フレキシブル サーバー インスタンスで発生している症状の範囲を確認することが重要です。 たとえば、以下についてクエリのパフォーマンスが低下していますか?

• Azure Database for MySQL フレキシブル サーバー インスタンス上で実行されるすべてのクエリですか?
• クエリの特定のセット
• 特定のクエリ

また、クエリを実行しているテーブルの構造または基になるデータに対する最近の変更がパフォーマンスに影響を与える可能性があることにも注意してください。

ログ機能の有効化

個々のクエリを分析する前に、クエリ ベンチマークを定義する必要があります。 この情報を使用すると、データベース サーバーにログ機能を実装して、アプリケーションのニーズに基づいて指定したしきい値を超えるクエリをトレースできます。

Azure Database for MySQL フレキシブル サーバーでは、低速クエリ ログ機能を使用して、実行時間が N 秒を超えるクエリを特定することをお勧めします。 低速クエリ ログでクエリを特定したら、MySQL 診断を使用してそれらのクエリをトラブルシューティングできます。

実行時間の長いクエリのトレースを開始するには、Azure portalまたは Azure CLI を使用して slow_query_log パラメーターを有効にしておく必要があります。 このパラメーターを有効にすると、long_query_time パラメーターの値も構成する必要があります。これは、クエリを "実行速度の遅い" クエリとして識別できる最小の実行時間を秒数で指定します。 このパラメーターの既定値は 10 秒ですが、この値は、アプリケーションの SLA のニーズに対応するように調整することができます。

低速クエリ ログは実行時間の長いクエリをトレースするための優れたツールですが、効果がない可能性のあるシナリオもあります。 たとえば、低速クエリ ログは次のようになります。

• クエリの数が非常に多い場合やクエリ ステートメントがきわめて大きい場合は、パフォーマンスに悪影響を与えます。 long_query_time パラメーターの値を適宜調整してください。
• すべての行を取得することが予想されるクエリをログするように指定する log_queries_not_using_index パラメーターも有効にしている場合は、役に立たない可能性があります。 インデックスのフル スキャンを実行するクエリはインデックスを利用しますが、インデックスでは返される行数が制限されないため、これらのクエリはログされます。

ログからの情報の取得

ログは、作成日から最大 7 日間使用できます。 Azure portal または Azure CLI を介して低速クエリ ログをリストおよびダウンロードできます。 Azure portal で、サーバーに移動し、[監視] で [サーバー ログ] を選択し、エントリの横にある下向き矢印を選択して、調査中の日時に関連するログをダウンロードします。

また、低速クエリ ログが診断ログを介して Azure Monitor ログと統合されている場合は、エディターでクエリを実行してそれらをさらに分析できます。

AzureDiagnostics
| where Resource == '<your server name>'
| where Category == 'MySqlSlowLogs'
| project TimeGenerated, Resource , event_class_s, start_time_t , query_time_d, sql_text_s
| where query_time_d > 10

次のスナップショットは、低速クエリのサンプルを示しています。

# Time: 2021-11-13T10:07:52.610719Z
# User@Host: root[root] @  [172.30.209.6]  Id: 735026
# Query_time: 25.314811  Lock_time: 0.000000 Rows_sent: 126  Rows_examined: 443308
use employees;
SET timestamp=1596448847;
select * from titles where DATE(from_date) > DATE('1994-04-05') AND title like '%senior%';;

クエリの実行時間は 26 秒で、443,000 を超える数の行が調べられ、126 行の結果が返されていることに注意してください。

通常は、Query_time と Rows_examined の値が高いクエリに焦点を当てる必要があります。 ただし、クエリの Query_time は高いが、Rows_examined がわずかしかない場合は、多くの場合、リソースのボトルネックが存在することを示しています。 このような場合は、IO スロットルがあるかどうかや CPU 使用率を確認する必要があります。

クエリのプロファイリング

実行速度が遅い特定のクエリを特定したら、EXPLAIN コマンドとプロファイリングを使用して詳細を収集できます。

クエリ プランを確認するには、次のコマンドを実行します。

EXPLAIN <QUERY>

クエリの EXPLAIN プランの作成に加えて、SHOW PROFILE コマンドを使用して、現在のセッション内で実行されたステートメントの実行を診断できます。

プロファイリングを有効にして、セッションで特定のクエリをプロファイリングするには、次の一連のコマンドを実行します。

SET profiling = 1;
<QUERY>;
SHOW PROFILES;
SHOW PROFILE FOR QUERY <X>;

これらのコマンドを使用してクエリをプロファイリングする方法を詳しく見てみましょう。 まず、現在のセッションのプロファイリングを有効にして、SET PROFILING = 1 コマンドを次のように実行します。

SET PROFILING = 1;
Query OK, 0 rows affected, 1 warning (0.00 sec)

次に、完全なテーブル スキャンを実行する準最適のクエリを実行します。

mysql> select * from sbtest8 where c like '%99098187165%';
+----+---------+-------------------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------+
| id | k | c | pad |
| +----+---------+-------------------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------+ |
| 10 | 5035785 | 81674956652-89815953173-84507133182-62502329576-99098187165-62672357237-37910808188-52047270287-89115790749-78840418590 | 91637025586-81807791530-84338237594-90990131533-07427691758 |
| +----+---------+-------------------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------+ |
| 1 row in set (27.60 sec) |

次に、SHOW PROFILES コマンドを実行して、使用可能なすべてのクエリ プロファイルの一覧を表示します。

SHOW PROFILES;
+----------+-------------+----------------------------------------------------+
| Query_ID | Duration | Query |
| +----------+-------------+----------------------------------------------------+ |
| 1 | 27.59450000 | select * from sbtest8 where c like '%99098187165%' |
| +----------+-------------+----------------------------------------------------+ |
| 1 row in set, 1 warning (0.00 sec) |

最後に、クエリ 1 のプロファイルを表示するには、コマンド SHOW PROFILE FOR QUERY 1 を実行します。

SHOW PROFILE FOR QUERY 1;
+----------------------+-----------+
| Status | Duration |
| +----------------------+-----------+ |
| starting | 0.000102 |
| checking permissions | 0.000028 |
| Opening tables | 0.000033 |
| init | 0.000035 |
| System lock | 0.000018 |
| optimizing | 0.000017 |
| statistics | 0.000025 |
| preparing | 0.000019 |
| executing | 0.000011 |
| Sending data | 27.594038 |
| end | 0.000041 |
| query end | 0.000014 |
| closing tables | 0.000013 |
| freeing items | 0.000088 |
| cleaning up | 0.000020 |
| +----------------------+-----------+ |
| 15 rows in set, 1 warning (0.00 sec) |

データベース サーバーで最もよく使用されるクエリを一覧表示する

クエリのパフォーマンスをトラブルシューティングするときは常に、Azure Database for MySQL フレキシブル サーバー インスタンスで最も頻繁に実行されるクエリを把握しておくと役立ちます。 この情報を使用して、上位のいずれかのクエリで実行に通常よりも時間がかかっているかどうかを判断できます。 さらに、開発者または DBA は、この情報を使用して、クエリの実行回数と期間が急激に増加したクエリがあるかどうかを確認できます。

Azure Database for MySQL フレキシブル サーバー インスタンスに対して最も多く実行された上位 10 個のクエリを一覧表示するには、次のクエリを実行します。

SELECT digest_text AS normalized_query,
 count_star AS all_occurrences,
 Concat(Round(sum_timer_wait / 1000000000000, 3), ' s') AS total_time,
 Concat(Round(min_timer_wait / 1000000000000, 3), ' s') AS min_time,
 Concat(Round(max_timer_wait / 1000000000000, 3), ' s') AS max_time,
 Concat(Round(avg_timer_wait / 1000000000000, 3), ' s') AS avg_time,
 Concat(Round(sum_lock_time / 1000000000000, 3), ' s') AS total_locktime,
 sum_rows_affected AS sum_rows_changed,
 sum_rows_sent AS sum_rows_selected,
 sum_rows_examined AS sum_rows_scanned,
 sum_created_tmp_tables,
 sum_select_scan,
 sum_no_index_used,
 sum_no_good_index_used
FROM performance_schema.events_statements_summary_by_digest
ORDER BY sum_timer_wait DESC LIMIT 10;

合計実行時間別に最も負荷の高い 10 個のクエリを一覧表示する

次のクエリの出力では、データベース サーバーに対して実行されている上位 10 個のクエリとそれらのデータベース サーバーでの実行回数に関する情報が提供されます。 さらに、クエリの待機時間、ロック時間、クエリ ランタイムの一部として作成された一時テーブルの数など、他の有用な情報も提供されます。このクエリ出力を使用して、データベースへの上位のクエリと待機時間などの要因の変化を追跡します。これは、将来のリスクを回避するためにクエリをさらに微調整する機会を示している可能性があります。

SELECT REPLACE(event_name, 'statement/sql/', '') AS statement,
 count_star AS all_occurrences ,
 Concat(Round(sum_timer_wait / 1000000000000, 2), ' s') AS total_latency,
 Concat(Round(avg_timer_wait / 1000000000000, 2), ' s') AS avg_latency,
 Concat(Round(sum_lock_time / 1000000000000, 2), ' s') AS total_lock_time  ,
 sum_rows_affected AS sum_rows_changed,
 sum_rows_sent AS  sum_rows_selected,
 sum_rows_examined AS  sum_rows_scanned,
 sum_created_tmp_tables,  sum_created_tmp_disk_tables,
 IF(sum_created_tmp_tables = 0, 0, Concat( Truncate(sum_created_tmp_disk_tables /
 sum_created_tmp_tables * 100, 0))) AS
 tmp_disk_tables_percent,
 sum_select_scan,
 sum_no_index_used,
 sum_no_good_index_used
FROM performance_schema.events_statements_summary_global_by_event_name
WHERE event_name LIKE 'statement/sql/%'
 AND count_star > 0
ORDER BY sum_timer_wait DESC
LIMIT 10;

InnoDB ガベージ コレクションの監視

InnoDB ガベージ コレクションがブロックされたり遅延したりすると、データベースで大幅なパージ ラグが発生し、ストレージの使用率とクエリのパフォーマンスに悪影響を及ぼす可能性があります。

InnoDB ロールバック セグメントの履歴リストの長さ (HLL) は、undo (元に戻す) ログに保存されている変更レコードの数を測定します。 HLL 値の増加は、InnoDB の GC スレッド (消去スレッド) が書き込みワークロードに追いついていないか、実行時間の長いクエリまたはトランザクションによって消去がブロックされていることを示します。

ガベージ コレクションの過度の遅延は、次のような重大な悪影響を及ぼす可能性があります。

• InnoDB システムのテーブルスペースが拡大するため、基になるストレージ ボリュームの増加が加速します。 場合によっては、システム テーブルスペースは、パージがブロックされた結果、数テラバイトまで膨れ上がる可能性があります。
• 削除のマークが付けられたレコードが、タイムリーに削除されません。 これにより、InnoDB テーブルスペースが拡大する可能性があり、これらのレコードによって占有されているストレージをエンジンで再利用できなくなります。
• InnoDB ストレージ構造の拡大により、すべてのクエリのパフォーマンスが低下し、CPU 使用率が増加する可能性があります。

そのため、HLL の値、パターン、傾向を監視することが重要です。

HLL 値の検索

HLL 値を検索するには、show engine innodb status コマンドを実行します。 この値は、TRANSACTIONS 見出しの下の出力にリストされます。

show engine innodb status\G

****************** 1. row ******************

(...)

------------
TRANSACTIONS
------------
Trx id counter 52685768
Purge done for trx's n:o < 52680802 undo n:o < 0 state: running but idle
History list length 2964300

(...)

HLL 値は、information_schema.innodb_metrics テーブルに対してクエリを実行して確認することもできます。

mysql> select count from information_schema.innodb_metrics
    -> where name = 'trx_rseg_history_len';

+---------+
| count |
| +---------+ |
| 2964300 |
| +---------+ |
| 1 row in set (0.00 sec) |

HLL 値の解釈

HLL 値を解釈するときは、次の表に示すガイドラインを考慮してください。

過剰な HLL 値への対処

HLL が急激な増加を示しているか、定期的な増加のパターンを示している場合は、Azure Database for MySQL フレキシブル サーバー インスタンスで実行されているクエリとトランザクションを直ちに調査します。 その後、ガベージ コレクション プロセスの進行を妨げている可能性があるワークロードの問題を解決できます。 データベースで消去ラグが発生しないことは期待できませんが、ラグが制御できないほど増大しないようにする必要があります。

たとえば、information_schema.innodb_trx テーブルからトランザクション情報を取得するには、次のコマンドを実行します。

select * from information_schema.innodb_trx
order by trx_started asc\G

trx_started 列の詳細は、トランザクションの経過時間を計算するのに役立ちます。

mysql> select * from information_schema.innodb_trx
    -> order by trx_started asc\G

****************** 1. row ******************
                    trx_id: 8150550
                 trx_state: RUNNING
               trx_started: 2021-11-13 20:50:11
     trx_requested_lock_id: NULL
          trx_wait_started: NULL
                trx_weight: 0
       trx_mysql_thread_id: 19
                 trx_query: select * from employees where DATE(hire_date) > DATE('1998-04-05') AND first_name like '%geo%';
(...)

セッションの現在の状態で費やされた時間など、現在のデータベース セッションの詳細については、information_schema.processlist テーブルを確認してください。 たとえば、次の出力は、過去 1462 秒間クエリをアクティブに実行しているセッションを示しています。

mysql> select user, host, db, command, time, info
    -> from information_schema.processlist
    -> order by time desc\G

****************** 1. row ******************
   user: test
   host: 172.31.19.159:38004
     db: employees
command: Query
   time: 1462
   info: select * from employees where DATE(hire_date) > DATE('1998-04-05') AND first_name like '%geo%';

(...)

推奨事項

• クエリを実行するのに十分なリソースがデータベースに割り当てられていることを確認します。 場合によっては、ワークロードに合わせて、インスタンス サイズをスケールアップして、CPU コアとメモリをさらに取得する必要が生じることもあります。

• 小さいトランザクションに分割することにより、大規模または実行時間の長いトランザクションを回避します。

• ワークロードに応じて innodb_purge_threads を構成し、バックグラウンドのパージ操作の効率を向上させます。

  注意

  環境ごとにこのサーバー変数に対する変更をテストして、エンジン動作の変化を確認します。

• "ホストの CPU 使用率"、"ホストのメモリ使用率"、"合計接続数" のアラートを使用して、システムが指定されたしきい値のいずれかを超えた場合に通知を受け取るようにします。

• Query Performance Insights または Azure Workbooks を使用して、問題が発生していたり実行に時間がかかったりするクエリを特定し、それらを最適化します。

• 運用データベース サーバーの場合は、診断を定期的に収集して、すべてがスムーズに実行されていることを確認します。 そうでない場合は、特定した問題をトラブルシューティングして解決します。

次のステップ