MySQL のスローログオンラインの問題と最適化ソリューション

MySQL スロー ログは、MySQL DBA やその他の開発および運用担当者が細心の注意を払う必要があるタイプの情報です。スロー ログを使用すると、実行に長い時間がかかったり、インデックスに従わなかったりする SQL ステートメントを識別し、システム チューニングの基礎を提供できます。

この記事では、オンラインケースを使用して、MySQL スローログパラメータを正しく設定してスローログ機能を使用する方法を分析し、NetEase Cloud RDS による MySQL スローログ機能の強化について紹介します。

MySQLパラメータグループ機能

NetEase Cloud RDS インスタンスは、パラメータ グループ管理機能を提供します。最も一般的に使用される MySQL システム パラメータは、パラメータ管理インターフェイスを通じて表示できます。ユーザーは、現在の動作値と推奨値を把握できます。

ユーザーは、パラメータ管理ページからリストされたパラメータを変更することもできます。「パラメータの変更」ボタンをクリックして、パラメータをオンラインに設定します。「変更を保存」をクリックすると、MySQL マスター ノードとスレーブ ノードのパラメータ変更が 1 回のクリックで完了します。

パラメータ管理インターフェースから、スロークエリに関連するパラメータが多数あることを見つけるのは難しくありません。では、これらのパラメータはどのように機能するのでしょうか。それらは互いにどのように関連しているのでしょうか。SQL ステートメントがスローログに記録されるためには、どのような条件を満たす必要があるのでしょうか。これらを理解することによってのみ、スローログをより有効に活用してシステムを調整し、問題を特定できるようになります。

次に、このオンライン ケースを参考にして、スロー ログ パラメータを正しく構成する方法を紹介します。

一部のユーザーから、使用している複数の RDS 5.7 インスタンスのスロー ログが異常であるとの報告がありました。実行に 1 分以上かかる SQL ステートメントはスロー ログに記録されませんでした。再現用のSQL文も用意されています。

スローログパラメータの正しい構成

まず、インスタンスに対してスロー ログ機能が有効になっているかどうかを確認する必要があります。デフォルトでは、MySQL スロー ログ機能は無効になっています。スロー ログ スイッチ パラメータは slow_query_log で、mysqld の起動コマンド ラインまたは構成ファイルで明示的に指定できます。slow_query_log=1 が指定されているか、値が指定されていない場合は、スロー ログがオンになっていることを意味し、値が 0 の場合はオフになっていることを意味します。ユーザーは実行時にこれを動的にオン/オフにすることができます。

NetEase Cloud RDS インスタンスでは、スロー ログ機能がデフォルトで有効になっています。ユーザーがインスタンスのスロー ログ スイッチをオフにしていないことが確認されました。

次に、スロー ログ レコードの場所を確認する必要があります。MySQL は、log_output パラメータを使用して、スロー ログをファイル (FILE) に保存するか、テーブル (TABLE) に保存するかを指定します。 log_output のみを指定し、slow_query_log を 0 に設定すると、スロー ログは記録されないことに注意してください。つまり、slow_query_log はスロー ログのスイッチです。ファイルを使用してスロー ログを記録する場合は、slow_query_log_file でファイル名を指定できます。ユーザーが slow_query_log_file を明示的に指定しない場合、MySQL はそれを host_name-slow.log に初期化します。ここで、host_name は mysqld を実行しているホスト名です。スロー ログ ファイルは、デフォルトでは MySQL データ ディレクトリにあります。

NetEase Cloud RDS インスタンスでは、ユーザーがログ ファイルのパスを変更することはできませんが、log_output パラメータを設定できます。クエリを実行すると、インスタンスがファイルにスロー ログを記録していることを確認できます。ログ ファイルをチェックして、ユーザーが記述した SQL ステートメントがないことを確認します。

ユーザーが再現可能なステートメントを提供したため、SQL ステートメントを実行したところ、確かに 1 分以上かかりました。explain コマンドを実行すると、インデックスを通過せず、大量のレコードをスキャンしていることがわかりました。スロー ログを再度確認したところ、SQL ステートメントはまだ記録されていませんでした。

MySQL は、実行時間が long_query_time 秒を超え、スキャンされたレコード数が min_examined_row_limit 行を超えるという条件を満たす SQL ステートメントを記録します。

long_query_time パラメータの最小値とデフォルト値はそれぞれ 1 と 10 秒です。パラメータの精度はマイクロ秒 (ms) まで指定できます。スロー ログをファイルに記録する場合、記録される時間はマイクロ秒単位の精度になります。スロー ログ テーブル (mysql.slow_log) に記録する場合、記録される時間は秒単位のみの精度となり、マイクロ秒部分は無視されます。

NetEase Cloud RDS インスタンスでは、ユーザーがこれら 2 つのパラメータ値を設定できます。では、ユーザーが上記 2 つのしきい値を調整した結果、録画条件を満たせなくなったのでしょうか? さらに調査したところ、これが問題の原因ではないことが判明しました。

MySQL には log_queries_not_using_indexes というパラメータもあり、これはインデックスを使用しない SQL クエリをログに記録するかどうかを制御するために使用されます。コードは次のとおりです。

矢印で示した内容に特に注意してください。クエリがインデックスを通過しなかったり、インデックスが無効であったり、関連するパラメータがオンになっている場合は、warn_no_indexがtrueに設定されます。同時にスキャンされたレコード数がしきい値を超えた場合も、遅いクエリのように記録されます。では、このパラメータはオンになっていないのでしょうか？結果は依然として否定的です。

問題の原因

データベース インスタンスにはインデックスを使用しない SQL 文が多数存在する可能性があるため、log_queries_not_using_indexes を有効にすると、ログ ファイルまたはテーブル容量が急激に増加するリスクがあります。この場合、log_throttle_queries_not_using_indexes を設定することで、スロー ログに 1 分あたりに書き込まれるインデックスを使用しない SQL 文の数を制限できます。このパラメータのデフォルト値は 0 で、これは有効ではないこと、つまり書き込まれる SQL 文の数が制御されないことを意味します。

有効にすると、インデックスを使用しない最初のクエリが実行された後、システムは 60 秒のウィンドウを開きます。このウィンドウ中は、最大で log_throttle_queries_not_using_indexes 個の SQL ステートメントのみが記録されます。超過分は抑制されます。時間枠の終了時に、その時間枠内で抑制された低速クエリの数と、これらの低速クエリに費やされた合計時間が出力されます。次の統計時間ウィンドウはすぐには作成されず、インデックスを使用しない次のクエリが実行された後に開かれます。

このオンラインの問題に対応して、log_throttle_queries_not_using_indexes が 10 に設定され、次の内容がログ ファイルに定期的に出力されます。

これは確かに上記の現象と一致しています。ユーザーのスローログは抑制され、359 に集約されるはずです。 log_throttle_queries_not_using_indexes を 0 に設定して、対応する SQL ステートメントを実行してみました。確かに、対応する SQL ステートメントがログ ファイルに記録されました。

このオンラインの問題は特定されたようです。システムによってインデックス化されていないスロー ログが大量に生成され、log_throttle_queries_not_using_indexes の設定が小さすぎるため、ユーザーによってインデックス化されていないスロー ログを正常に記録することができません。しかし、まだ解決されていないパズルが 1 つあります。つまり、log_throttle_queries_not_using_indexes が 0 の場合、スロットルによって要求される 359 は言うまでもなく、1 分あたり 10 を超えるスロー ログは印刷されません。したがって、10 に設定されている場合、ユーザーが指定した SQL ステートメントはスロー ログに記録されるはずです。なぜ記録されないのでしょうか。理由は何でしょうか。実際、インデックスを使用しない MySQL ログのコード ロジックを注意深く調べると、答えが見つかります。

上の図は、スローログを記録する主なロジックを示しています。ログを記録するかどうかは、関数 log_slow_applicable によって制御されます。この関数の一部は以前に分析されています。下の図の赤いボックスに示すように、この関数のその他の関連コンテンツを詳しく見てみましょう。

Suppress_logging は決定的な変数です。これが false の場合にのみ、SQL 文を記録できます。この結果は、log_throttle_queries_not_using_indexes に関連しています。以下に示すように、log_throttle_qni.log の実装を詳しく見てみましょう。

対象は warn_no_index です。inc_log_count() 関数は、1 分以内にインデックスを使用しないステートメントの合計数が log_throttle_queries_not_using_indexes を超えると true を返します。warn_no_index と inc_log_count() が true を返し、suppress_current が true で、suppress_current が suppress_logging である場合にのみ有効です。

上記の 2 つのスクリーンショットを分析することで、これまでの疑問に答えることができます。

log_throttle_queries_not_using_indexes は、インデックスを使用しないすべてのステートメントをカウントします。これらのステートメントの一部は、スキャンされたレコードの数の制約を満たしていないため、スロー ログに記録されません。この値が 10 の場合、スロー ログ ファイルに 10 個のレコードが存在しないのはそのためです。これは、スキャンされたレコード数が少なすぎたため、10 個の SQL ステートメントのうち 8 個が記録されなかったためです。

これは、上の図の 359 という数字にも当てはまります。これは、この時間枠内でインデックスを使用しない SQL ステートメントの合計数です。したがって、log_throttle_queries_not_using_indexes は重要なパラメータです。不適切な設定により、インデックスを使用しないスロー クエリが適切に記録されず、スロー ログ機能が部分的に失敗する可能性があります。したがって、ユーザーはまず、インデックスを使用しない大量の SQL ステートメントをできるだけ避ける必要があります。RDS ヘルス チェック機能を使用してステートメントを最適化できます。次に、スロー ログに上記のプロンプトが表示された場合は、log_throttle_queries_not_using_indexes の値を増やして、問題をさらに分析する必要があります。

InnoSQL スローログ機能の強化

RDS インスタンスのユーザーの中には、SQL ステートメントの実行時間が設定された long_query_time を超えず、インデックスが使用されていないのに、スロー ログに記録される理由を尋ねる人もいました。バグでしょうか?実は、これはバグではありません。NetEase Cloud RDS で使用されている InnoSQL (NetEase が管理する MySQL オープンソースブランチ) バージョンでは、スローログが最適化されているためです。SQL ステートメントの実行時間を調べるだけでなく、クエリに必要なディスク ページ数にも注目しています。必要なページ数が多すぎると、システム負荷にさらに大きな影響を与える可能性があります。統計を定量化するために、SQL クエリで読み取る必要のあるページの合計数と、これらのページで実際に実行された IO の数を収集しました。これらはそれぞれ logical_reads と physical_reads として記録されます。前者には、InnoDB バッファー プールにヒットするページ リクエストと、ヒットせず IO を必要とするページ リクエストが含まれます。

この機能は、slow_query_type と long_query_io という 2 つのパラメータを導入することでユーザーに提供されます。前者は0/1/2/3に設定できます。 「1」は実行時間に基づいてスローログの記録を有効にすることを意味し、「2」は検索されたページの総数に基づいてスローログを記録することを意味し、「3」は「1」と「2」の組み合わせを意味します。したがって、InnoSQL では、実行時間が十分に長い場合、または必要なページの合計数が十分に大きい場合にのみ、SQL クエリをスロー ログに記録できます。コードスニペットは次のとおりです。

ページ数のしきい値は long_query_io パラメータによって測定され、ユーザーが動的に設定できます。m_logical_reads の合計ページ数がこの値を超えると、実行時間が制限を超えなくても記録されます。それに応じて、RDS インスタンスのスロー ログ テーブル構造とスロー ログ ファイルの出力内容に新しいフィールドが追加されます。

上の図は、slow_log テーブル構造の InnoSQL バージョンを示しています。ここで、logical_reads と physical_reads は InnoSQL によって追加されたフィールドです。同様に、以下に示すように、スロー ログ ファイルの出力に 2 つのフィールドが追加されます。

上記の詳細な説明に加えて、MySQL スロー ログ モジュールには注目すべき次の機能があります。

○ スロー ログ統計およびスロー ログに記録される時間には、SQL ステートメントの実行が開始される前にロックを取得するために必要な待機時間は含まれません。

○ MySQL は、SQL 文が実行され、保持されているすべてのロックが解放された後にのみ、SQL 文をスロー ログに書き込みます。そのため、スロー ログに記録される SQL 文の順序は、これらの SQL 文の実際の実行順序を正確に反映するものではありません。

○ 各スロー ログにはタイムスタンプが含まれます。ファイルに書き込まれる場合、log_timestamps パラメータを使用して、スロー ログのタイムスタンプを指定されたタイム ゾーンの時刻に変換します。ただし、このパラメータは mysql.slow_log テーブル内のスロー ログには影響しません。

○ log_slow_slave_statements を設定することで、MySQL スレーブ ライブラリのスロー ログ機能を有効にすることができます。

○ ALTER TABLE、ANALYZE TABLE、CHECK TABLE、CREATE INDEX、DROP INDEX、OPTIMIZE TABLE、REPAIR TABLE などのテーブル管理操作もスロー ログに記録できます。これは、log_slow_admin_statements オプションで有効にできます。