パフォーマンスインサイトを活用してDB負荷を改善する

こんにちは！インフラエンジニアの木村奈美です。

今回は、RDSのパフォーマンスインサイトを活用して問題を解決した事例を紹介します。

はじめに

今回のシステムは、 ALB + EC2 + RDS (Aurora MySQL) というオーソドックスな構成となっています。

ある時期から、EC2上のアプリケーションで5xxエラーやレイテンシー悪化が頻発するようになりました。 CloudWatchでメトリクスを確認すると、EC2の問題と同時刻に、RDSインスタンスのCPUUtilizationの上昇とFreeableMemoryの低下が観測できました。

RDSのCPUUtilizationが上昇し、FreeableMemoryが低下している

同時刻にDatabaseConnectionsが増えていることからアクセス数の増加を疑いましたが、ALBのRequestCountには特に目立った増加は見られませんでした。

この原因を探るためにパフォーマンスインサイトを確認してみました。

パフォーマンスインサイトとは

パフォーマンスインサイト（Performance Insights）とはRDSの機能の1つで、CPU使用率の細かい内訳や負荷の高いSQLといった、パフォーマンスに関わる情報をモニタリングできます。詳しくは公式ドキュメントをご参照ください。

データの保存期間として7日〜2年まで選ぶことができ、7日であればなんと無料で利用することができます。現時点で特に困ったことがなくとも、有事に備えて有効化しておくことをおすすめします。

DBのパフォーマンスへの影響は？

公式のよくある質問によると、パフォーマンスインサイトのエージェントはワークロードへの影響が少ないように作ってあるとのことです。ただし、ワークロードに影響を及ぼさないか事前にテストすることが推奨されています。

AWS では、本番稼働用システムで有効にする前に、ワークロードに対してデータベースオプションをテストすることを推奨します。

サポート範囲は？

エンジンやインスタンスタイプの組み合わせによっては、パフォーマンスインサイトがサポートされていない場合があります。詳しいサポート範囲は公式ドキュメントに記載されています。

例えば、Aurora MySQLのt3系はサポートされていません。コンソールで有効化しようとした場合、パフォーマンスインサイトの有効/無効を指定するチェックボックスがそもそも表示されません。また、CloudFormationで有効化しようとした場合、以下のようなエラーメッセージが表示されます。

Performance Insights not supported for this configuration, please disable this feature.

パフォーマンスインサイトの有効化

コンソールから有効化する手順は公式ドキュメントに記載されています。

CloudFormationで有効化する場合、以下の3つのプロパティを追記します。

  DBInstanceName:
    Type: "AWS::RDS::DBInstance"
    Properties:
      EnablePerformanceInsights: true
      PerformanceInsightsRetentionPeriod: 7
      PerformanceInsightsKMSKeyId: "alias/aws/rds"

いずれの場合も、KMSキーIDは後から変更できない点にご注意ください。

パフォーマンスインサイトの有効化には再起動が不要で、ダウンタイムがありません。 ……と公式ドキュメントに書いてあるものの、自分の目で確かめなければ断言できないので、実際にダウンタイムがないことを検証してみました。本筋からは逸れるためこの記事の末尾に記載しております。「おまけ: 本当にダウンタイムがないのか検証してみた」をご覧ください。

パフォーマンスインサイトで負荷の高いSQLを特定する

それでは、パフォーマンスインサイトのダッシュボードを確認してみましょう。コンソールでRDSにアクセスし、左メニューから「Performance insights」を選択すると、以下のような画面が表示されます。

まずは「メトリクスを表示するDBインスタンスを選択します」から、問題のインスタンスを選択します。

すると、以下のようにメトリクスが表示されます。右上に表示期間を指定するエリアがあるため、調査したい日時を選択します。

この状態で、画面の下の方にある「データベース負荷」と「トップSQL」を見ていきます。まずは「データベース負荷」から確認します。

アクティブセッションとは、DBにSQLを投げてレスポンスを待っている状態の接続です。これが高いほど、処理が詰まっていることを意味します。

上に掲載したメトリクスと比較すると、CPUUtilizationやDatabaseConnectionsの上昇と、平均アクティブセッション（AAS）上昇のタイミングが一致することが分かります。したがって、DatabaseConnectionsが増えていたのは負荷の原因ではなく、負荷が高まって処理が詰まった結果だったと考えられます。

では、どのSQLが問題だったか見ていきましょう。「データベース負荷」の下に「トップSQL」の表示があります。ここで、負荷の高かったSQLを特定することができます。

トップSQLの中からSQLを1つ選択すると、画面下部にある「SQLテキスト」でSQLの内容を確認できます。ここでは、同じ構文のSQLがまとめられています。カラム名やテーブル名は表示されますが、WHERE句の条件やLIMIT句の値が ? となっています。

-- SQLテキストの例
SELECT col1, col2, col3 FROM tablename WHERE col4 = ? ORDER BY col3 DESC LIMIT ?

トップSQLの左の方にある+ボタンを押して開くと、実際のSQLの内容を確認できます。

さきほどは ? となっていたWHERE句やLIMIT句の内容を確認できます。

今回はある1つのSQLによって負荷がかかっていることが分かりました。

SELECT `col1`, `col2`, `col3`
FROM `tablename`
WHERE `col4` = '5...a'
ORDER BY `col3` DESC
LIMIT 1;

以上がパフォーマンスインサイトで得られた調査結果です。ここからは、実際に問題を改善した手順を紹介します。

チューニングする

問題のSQLは一見単純に見えますが、データを確認すると、WHERE句の条件にヒットするレコードは6万件以上ありました。これをソートするのは、確かにCPUにもメモリにも負荷がかかりそうです。

> SELECT count(*) FROM `tablename` WHERE `col4` = '5...a';
+----------+
| count(*) |
+----------+
|    66505 |
+----------+
1 row in set (0.06 sec)

問題のSQLについて、EXPLAINを確認してみます。

EXPLAIN SELECT `col1`, `col2`, `col3`
FROM `tablename`
WHERE `col4` = '5...a'
ORDER BY `col3` DESC
LIMIT 1\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: tablename
         type: ref
possible_keys: idx_col4,idx_a,idx_b
          key: idx_col4
      key_len: 386
          ref: const
         rows: 114294
        Extra: Using index condition; Using where; Using filesort
1 row in set (0.00 sec)

key が col4 のインデックス idx_col4 となっていることから、WHERE句にはインデックスが効いていると考えられます。しかし、ORDER BY句で使えるインデックスはないため、filesortが実行されていることが Extra より分かります。

今回は、WHERE句とORDER BY句の両方に効くマルチカラムインデックスの作成を試すことにしました。以下のように、 (WHERE句のキー, ORDER BY句のキー) の順序でインデックスを作成します。

ALTER TABLE tablename ADD INDEX idx_col4_col3(col4, col3);

再度EXPLAINを見てみます。上で作成したインデックス idx_col4_col3 が効いていることが key より分かります。また、 Extra からfilesortがなくなることを確認できました。

EXPLAIN SELECT `col1`, `col2`, `col3`
FROM `tablename`
WHERE `col4` = '5...a'
ORDER BY `col3` DESC
LIMIT 1\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: access_authentications
         type: ref
possible_keys: idx_col4,idx_a,idx_b,idx_col4_col3
          key: idx_col4_col3
      key_len: 386
          ref: const
         rows: 116996
        Extra: Using where
1 row in set (0.00 sec)

SQL実行速度は10分の1以下まで短縮できました！

インデックス作成前: 630.0ms
インデックス作成後: 60.2ms

今回はインデックスを作成することで改善しましたが、必ずしもインデックスの作成が正解ではない点にご注意ください。 SQLの構文によってはインデックスが使われない場合があったり、書き込みが多いワークロードではインデックスの更新に時間がかかるようになってしまうデメリットもあるため、状況に応じた対応が必要です。まずは、本番に近い量のデータが入った検証環境で試してみることをおすすめします。

まとめ

パフォーマンスインサイトは無料かつ簡単な手順で始めることができ、DBのチューニングに大いに役立ちます。 DBのパフォーマンスにお困りの方はぜひ使ってみてください。

おまけ: 本当にダウンタイムがないのか検証してみた

検証方法

1秒おきにSQLを実行する簡単なシェルを用意しました。このシェルを実行し続けた状態で、RDSインスタンスのパフォーマンスインサイトを有効化します。もしダウンタイムがあれば mysql コマンドの実行結果がエラーや遅延となり、結果の欠落として現れる想定です。

$ cat test.sh
while true
do
    mysql -ss -u*** -p*** -h XXXX.cluster-XXXX.us-west-2.rds.amazonaws.com -e 'SELECT CURTIME(), 1' dbname >> pitest.log
    sleep 1
done

なお、ネットワークによる遅延が極力少なくなるよう、対象のRDSインスタンス同じAZのEC2でシェルを実行しました。

結果

パフォーマンスインサイトの有効化にかかった時間は16:39〜16:42の約4分間です。その間、インスタンスの状態は「変更中」となっていました。

mysqlコマンドの実行結果を書き出した pitest.log は以下のようになっています。

$ head -3 pitest.log
07:39:25    1
07:39:26    1
07:39:27    1

これをグラフにして欠落を確認しました。

30秒に1回ほどのペースで欠落が発生していますが、これはシェル実行側の問題であると考えられます。今回のwhile文は1ループにつき sleep 1 の1秒 + mysql 実行時間、つまり1秒以上かかっているため、厳密には毎秒実行ではなく多少の遅延が発生します。そのため、この欠落については無視することにします。

それ以外に大きな欠落がないことから、ダウンタイムはないか、あったとしても1秒未満であると言えそうです。本番利用中のDBインスタンスでも有効化できるのは大きなメリットですね！