Lambda関数のhandlerの外側でRDS Proxyの接続をした場合の処理時間を計測してみた

パフォーマンスを優先するならRDS Proxyの接続を使い回した方が良さそう
2022.04.06

RDS Proxyの接続を使い回した場合の影響を知りたい

こんにちは、のんピ(@non____97)です。

以下記事でLambda関数からRDS Proxy経由でAmazon Aurora DBクラスターに接続してみました。

その際のLambda関数ではRDS Proxyの接続をhandler内で行っており、Lambda関数を実行するたびにRDS Proxyに接続をしていました 。

RDS Proxyの接続をhandlerの外側にした場合は、RDS Proxyの接続を維持することができ、ウォームスタート時には接続処理をスキップできるためパフォーマンスの向上が期待できます。

参考:

この情報を見て、「実際Lambda関数のhandlerの外側でRDS Proxyの接続をすると処理時間にどのぐらい影響を与えるのか」が非常に気になったので検証してみます。

こちらのコードのリポジトリは以下になります。

使用するLambda関数

RDS Proxyの接続をhandlerの外側で実行するLambda関数と、内側で実行するLambda関数を用意しました。

RDS Proxyの接続をhandlerの内側で実行するLambda関数はコネクションのクローズもhandler内で行っています。

RDS Proxyの接続をhandlerの外側で実行するLambda関数

import { getSecretValue } from "../utils/getSecretValue";
import { dbConnect } from "../utils/dbConnect";
import { QueryResult } from "../utils/table";

const secret = await getSecretValue();
const dbClient = await dbConnect(secret);

export const handler = async (): Promise<QueryResult | Error> => {
  // Query
  const beforeInsertQuery = await dbClient.query("SELECT * FROM test_table");
  console.log(beforeInsertQuery.rows);

  await dbClient.query("INSERT INTO test_table (name) VALUES ('non-97')");

  const afterInsertQuery = await dbClient.query("SELECT * FROM test_table");
  console.log(afterInsertQuery.rows);

  return {
    beforeInsertQueryRows: beforeInsertQuery.rows,
    afterInsertQueryRows: afterInsertQuery.rows,
  };
};

RDS Proxyの接続をhandlerの内側で実行するLambda関数

import { getSecretValue } from "../utils/getSecretValue";
import { dbConnect } from "../utils/dbConnect";
import { QueryResult } from "../utils/table";

const secret = await getSecretValue();

export const handler = async (): Promise<QueryResult | Error> => {
  const dbClient = await dbConnect(secret);

  // Query
  const beforeInsertQuery = await dbClient.query("SELECT * FROM test_table");
  console.log(beforeInsertQuery.rows);

  await dbClient.query("INSERT INTO test_table (name) VALUES ('non-97')");

  const afterInsertQuery = await dbClient.query("SELECT * FROM test_table");
  console.log(afterInsertQuery.rows);

  dbClient.end();

  return {
    beforeInsertQueryRows: beforeInsertQuery.rows,
    afterInsertQueryRows: afterInsertQuery.rows,
  };
};

Prepared Statementsでクエリを発行してしまうとピン留めされてしまうので、Prepared Statementsは使用しません。ピン留めについては以下記事とAWS公式ドキュメントをご覧ください。

また、こちらのLambda関数ではtop-level awaitを使用しています。

そのため、ターゲットはtop-level awaitをサポートしているv14.8以降を指定し、フォーマットはCommonJSではなくES Modulesにしています。 また、インポートするモジュールをNodejsFunction側でも明示的に指定する必要があったのでnodeModulesでLambda関数で使用するモジュールを指定してあげます。

./lib/lambda-aurora-stack.ts

new nodejs.NodejsFunction(this, "DbAccessDbconnectOutsideHandlerFunction", {
  entry: path.join(
    __dirname,
    "../src/lambda/handlers/db-access-dbconnect-outside-handler.ts"
  ),
  runtime: lambda.Runtime.NODEJS_14_X,
  bundling: {
    minify: true,
    sourceMap: true,
    externalModules: ["pg-native"],
    target: "node14.19",
    tsconfig: path.join(__dirname, "../src/lambda/tsconfig.json"),
    format: nodejs.OutputFormat.ESM,
    nodeModules: ["@aws-sdk/client-secrets-manager", "pg"],
  },
  environment: {
    PROXY_ENDPOINT: rdsProxy.endpoint,
    SECRET_ID: dbAdminSecret.secretArn,
    NODE_OPTIONS: "--enable-source-maps",
  },
  role: dbAccessFunctionIamRole,
  logRetention: logs.RetentionDays.TWO_WEEKS,
  tracing: lambda.Tracing.ACTIVE,
  securityGroups: [dbClientSg],
  vpc,
  vpcSubnets: vpc.selectSubnets({
    subnetType: ec2.SubnetType.PRIVATE_WITH_NAT,
  }),
});

top-level awaitを使用するには以下の条件を満たす必要があります。

  • moduleオプションが以下のいずれか
    • es2022
    • esnext
    • system
    • nodenext
  • targetオプションが以下のバージョン以上
    • es2017

こちらの条件を満たすようにLambda関数のトランスコンパイルに使用するtsconfig.jsonを用意してあげます。

./src/lambda/tsconfig.json

{
  "extends": "../../tsconfig.json",
  "compilerOptions": {
    "target": "es2019",
    "module": "es2022",
    "moduleResolution": "node",
    "allowSyntheticDefaultImports": true,
    "esModuleInterop":true
  }
}

計測してみた

計測のレギュレーション

計測するにあたってのレギュレーションは以下の通りです。

  • メモリを128MB割り当てたLambda関数からRDS Proxy経由でAurora DBクラスターに接続
  • Lambda関数から簡単なSQL(SELECTINSERT)を発行
  • 計測は以下の状態で行う
    • DBのテーブルがクリアされている
    • RDS ProxyとAurora DBクラスター間のコネクションが無い
    • Lambda関数とRDS Proxy間のコネクションが無い
  • プレウォーミング(Provisioned Concurrency)は使用しない
  • 処理時間(Duration)とコールドスタートの所要時間(Init Duration)をCloudWatch Logs Insightsで集計
  • CloudWatchで以下メトリクスを確認
    • RDS Proxyの現在のクライアント接続の数(ClientConnections)
    • RDS Proxyの現在のデータベース接続の数(DatabaseConnections)
    • RDS Proxyの現在ピン留めされているデータベース接続の数(DatabaseConnectionsCurrentlySessionPinned)
    • Lambda関数のイベントを処理している関数インスタンスの数(ConcurrentExecutions)
  • Aurora DBクラスターはシングルAZ構成
  • Lambda関数、RDS ProxyはマルチAZ構成

計測パターン

計測パターンは以下の4つです。

  1. RDS Proxyの接続をhandlerの外側で実行するLambda関数 × 直列100回実行
  2. RDS Proxyの接続をhandlerの内側で実行するLambda関数 × 直列100回実行
  3. RDS Proxyの接続をhandlerの外側で実行するLambda関数 × 並列100回実行
  4. RDS Proxyの接続をhandlerの内側で実行するLambda関数 × 並列100回実行

直列実行 VS 並列実行だとウォームスタートとコールドスタートの差で勝負にならないので、直列実行 VS 並列実行というよりも直列実行内、並列実行内で比較する形をとります。

また、各パターンの計測する際は各パターン毎に準備したステートマシンを実行して計測します。

./lib/lambda-aurora-stack.ts

// State Machine Tasks
const patternDbConnectTasks = [
  new tasks.LambdaInvoke(this, "Pattern1DbConnectTask", {
    lambdaFunction: dbAccessDbConnectOutsideHandlerFunction,
    invocationType: tasks.LambdaInvocationType.REQUEST_RESPONSE,
    payload: sfn.TaskInput.fromObject({
      payload: sfn.JsonPath.stringAt("$"),
    }),
    outputPath: "$.StatusCode",
  }),
  new tasks.LambdaInvoke(this, "Pattern2DbConnectTask", {
    lambdaFunction: dbAccessDbConnectInsideHandlerFunction,
    invocationType: tasks.LambdaInvocationType.REQUEST_RESPONSE,
    payload: sfn.TaskInput.fromObject({
      payload: sfn.JsonPath.stringAt("$"),
    }),
    outputPath: "$.StatusCode",
  }),
  new tasks.LambdaInvoke(this, "Pattern3DbConnectTask", {
    lambdaFunction: dbAccessDbConnectOutsideHandlerFunction,
    invocationType: tasks.LambdaInvocationType.EVENT,
    payload: sfn.TaskInput.fromObject({
      payload: sfn.JsonPath.stringAt("$"),
    }),
    outputPath: "$.StatusCode",
  }),
  new tasks.LambdaInvoke(this, "Pattern4DbConnectTask", {
    lambdaFunction: dbAccessDbConnectInsideHandlerFunction,
    invocationType: tasks.LambdaInvocationType.EVENT,
    payload: sfn.TaskInput.fromObject({
      payload: sfn.JsonPath.stringAt("$"),
    }),
    outputPath: "$.StatusCode",
  }),
];

// State Machine
patternDbConnectTasks.forEach((patternDbConnectTask, index) => {
  const createNumberArrayTask = new tasks.LambdaInvoke(
    this,
    `Pattern${index + 1}CreateNumberArrayTask`,
    {
      lambdaFunction: createNumberArrayFunction,
      payload: sfn.TaskInput.fromObject({
        number: sfn.JsonPath.stringAt("$.numberForInputMap"),
      }),
    }
  );

  const map = new sfn.Map(this, `Pattern${index + 1}MapState`, {
    maxConcurrency: index < 2 ? 1 : 0,
    itemsPath: sfn.JsonPath.stringAt("$.Payload.numberArray"),
  });

  new sfn.StateMachine(this, `Pattern${index + 1}StateMachine`, {
    definition: createNumberArrayTask
      .next(map.iterator(patternDbConnectTask))
      .next(new sfn.Succeed(this, `Pattern${index + 1}SuccessState`)),
    logs: {
      destination: stateMachineLogGroup,
      level: sfn.LogLevel.ALL,
    },
    tracingEnabled: true,
  });
});

100回Lambda関数を直列 or 並列実行したい場合は、ステートマシンに以下のJSONを渡します。

{
  "numberForInputMap": 100
}

CloudWatch Logs Insightsのクエリ

各パターン実行後に以下のCloudWatch Logs Insightsのクエリを実行して集計します。

filter @type = "REPORT"
| stats 
  avg(@duration) as duration_avg, 
  max(@duration) as duration_max,  
  min(@duration) as duration_min,  
  pct(@duration, 25) as duration_pct25,    
  pct(@duration, 50) as duration_pct50,    
  pct(@duration, 75) as duration_pct75,    
  count(@duration) as duration_count,     
  avg(@initDuration) as initDuration_avg, 
  max(@initDuration) as initDuration_max,  
  min(@initDuration) as initDuration_min,  
  pct(@initDuration, 25) as initDuration_pct25,    
  pct(@initDuration, 50) as initDuration_pct50,    
  pct(@initDuration, 75) as initDuration_pct75,    
  count(@initDuration) as initDuration_count     
| display 
  duration_avg,
  duration_max,
  duration_min,
  duration_pct25,
  duration_pct50,
  duration_pct75,
  duration_count,
  initDuration_avg,
  initDuration_max,
  initDuration_min,
  initDuration_pct25,
  initDuration_pct50,
  initDuration_pct75,
  initDuration_count

CloudWatch Logs Insights のクエリ構文は以下AWS公式ドキュメントをご覧ください。

各パターン終了毎にDBで行う作業

各パターン終了毎にDBで行う作業は以下の通りです。EC2インスタンスからRDS Porxyを経由せずAurora DBクラスターに接続してテーブルをクリアしたり、コネクションを削除したりします。

# Secrets ManagerからAurora DBクラスターのシークレットを取得
$ get_secrets_value=$(aws secretsmanager get-secret-value \
    --secret-id prd-db-cluster/AdminLoginInfo \
    --region us-east-1 \
    | jq -r .SecretString)

# シークレットを環境変数にセット
$ export PGHOST=$(echo "${get_secrets_value}" | jq -r .host)
$ export PGPORT=$(echo "${get_secrets_value}" | jq -r .port)
$ export PGDATABASE=$(echo "${get_secrets_value}" | jq -r .dbname)
$ export PGUSER=$(echo "${get_secrets_value}" | jq -r .username)
$ export PGPASSWORD=$(echo "${get_secrets_value}" | jq -r .password)

# Aurora DBクラスターに接続
$ psql

# テーブルを一度削除する
=> DROP TABLE test_table;

# テーブルを作成し直す
=> CREATE TABLE test_table (
    id SERIAL NOT NULL,
    name VARCHAR(255) NOT NULL,
    created_at TIMESTAMP NOT NULL DEFAULT CURRENT_TIMESTAMP,
    PRIMARY KEY (id)
);

# 自分以外のコネクションを確認する
=> SELECT *
     FROM pg_stat_activity
   WHERE datname = 'testDB'
     AND pid <> pg_backend_pid();

# 自分以外のコネクションを切断する
=> SELECT pg_terminate_backend(pid)
     FROM pg_stat_activity
   WHERE datname = 'testDB'
     AND pid <> pg_backend_pid();

パターン1. RDS Proxyの接続をhandlerの外側で実行するLambda関数 × 直列100回実行

まず、RDS Proxyの接続をhandlerの外側で実行するLambda関数を直列で繋いだ場合を試します。

ステートマシンを実行すると以下のように正常に終了しました。

パターン1. RDS Proxyの接続をhandlerの外側で実行するLambda関数 × 直列100回実行_ステートマシン実行完了確認

X-Rayトレースからタイムラインを確認すると、確かに直列で実行されていることが確認できます。

パターン1. RDS Proxyの接続をhandlerの外側で実行するLambda関数 × 直列100回実行_X-Rayトレース

実行時のCloudWatchメトリクスは以下のようになっていました。

パターン1. RDS Proxyの接続をhandlerの外側で実行するLambda関数 × 直列100回実行_CloudWatchメトリクス

ClientConnectionsDatabaseConnectionsは共に1であることからRDS Proxyへのコネクションを使い回していることが分かります。

CloudWatch Logs Insightsで集計した結果は以下の通りです。

フィールド
duration_avg 45.8541
duration_max 237.3
duration_min 13.29
duration_pct25 23.33
duration_pct50 34.88
duration_pct75 51.42
duration_count 100
initDuration_avg 696.14
initDuration_max 696.14
initDuration_min 696.14
initDuration_pct25 696.14
initDuration_pct50 696.14
initDuration_pct75 696.14
initDuration_count 1

パターン1. RDS Proxyの接続をhandlerの外側で実行するLambda関数 × 直列100回実行_CloudWatch Logs Insights

initDuration_countが1になっていることからコールドスタートになったのは一回のみだったことが分かります。

パターン2. RDS Proxyの接続をhandlerの内側で実行するLambda関数 × 直列100回実行

続いて、RDS Proxyの接続をhandlerの内側で実行するLambda関数を直列で繋いだ場合を試します。

ステートマシンを実行すると以下のように正常に終了しました。

パターン2. RDS Proxyの接続をhandlerの内側で実行するLambda関数 × 直列100回実行_ステートマシン実行完了確認

X-Rayトレースからタイムラインを確認すると、確かに直列で実行されていることが確認できます。

パターン2. RDS Proxyの接続をhandlerの内側で実行するLambda関数 × 直列100回実行_X-Rayトレース

実行時のCloudWatchメトリクスは以下のようになっていました。

パターン2. RDS Proxyの接続をhandlerの内側で実行するLambda関数 × 直列100回実行_CloudWatchメトリクス

ClientConnectionsDatabaseConnectionsは共に1であることからRDS Proxyへのコネクションを使い回していることが分かります。

CloudWatch Logs Insightsで集計した結果は以下の通りです。

フィールド
duration_avg 119.3956
duration_max 261.13
duration_min 82.56
duration_pct25 94.8905
duration_pct50 105.2851
duration_pct75 124.7844
duration_count 100
initDuration_avg 690.17
initDuration_max 690.17
initDuration_min 690.17
initDuration_pct25 690.17
initDuration_pct50 690.17
initDuration_pct75 690.17
initDuration_count 1

パターン2. RDS Proxyの接続をhandlerの内側で実行するLambda関数 × 直列100回実行_CloudWatch Logs Insights

initDuration_countが1になっていることからコールドスタートになったのは一回のみだったことが分かります。

パターン3. RDS Proxyの接続をhandlerの外側で実行するLambda関数 × 並列100回実行

続いて、RDS Proxyの接続をhandlerの外側で実行するLambda関数を並列で繋いだ場合を試します。

ステートマシンを実行すると以下のように正常に終了しました。

パターン3. RDS Proxyの接続をhandlerの外側で実行するLambda関数 × 並列100回実行_ステートマシン実行完了確認

X-Rayトレースからタイムラインを確認すると、確かに並列で実行されていることが確認できます。

パターン3. RDS Proxyの接続をhandlerの外側で実行するLambda関数 × 並列100回実行_X-Rayトレース

実行時のCloudWatchメトリクスは以下のようになっていました。

パターン3. RDS Proxyの接続をhandlerの外側で実行するLambda関数 × 並列100回実行_CloudWatchメトリクス

Lambda関数が最大33多重で実行され、Lambda関数からRDS Proxyへのコネクションが19個あることが分かります。

CloudWatch Logs Insightsで集計した結果は以下の通りです。

フィールド
duration_avg 113.3586
duration_max 341.75
duration_min 25.12
duration_pct25 61.7404
duration_pct50 97.3888
duration_pct75 146.7171
duration_count 100
initDuration_avg 801.1223
initDuration_max 1273.24
initDuration_min 616.83
initDuration_pct25 729.95
initDuration_pct50 794.79
initDuration_pct75 842.5
initDuration_count 30

パターン3. RDS Proxyの接続をhandlerの外側で実行するLambda関数 × 並列100回実行_CloudWatch Logs Insights

initDuration_countが30になっていることから30回コールドスタートが発生したことが分かります。

パターン4. RDS Proxyの接続をhandlerの内側で実行するLambda関数 × 並列100回実行

最後に、RDS Proxyの接続をhandlerの内側で実行するLambda関数を並列で繋いだ場合を試します。

ステートマシンを実行すると以下のように正常に終了しました。

パターン4. RDS Proxyの接続をhandlerの内側で実行するLambda関数 × 並列100回実行_ステートマシン実行完了確認

X-Rayトレースからタイムラインを確認すると、確かに並列で実行されていることが確認できます。

パターン4. RDS Proxyの接続をhandlerの内側で実行するLambda関数 × 並列100回実行_X-Rayトレース

実行時のCloudWatchメトリクスは以下のようになっていました。

パターン4. RDS Proxyの接続をhandlerの内側で実行するLambda関数 × 並列100回実行_CloudWatchメトリクス

ClientConnectionsよりもDatabaseConnectionsが大きいという何とも不思議な結果になっています。(この後2回実行しましたが同様にClientConnectionsよりもDatabaseConnectionsが大きくなりました)

CloudWatch Logs Insightsで集計した結果は以下の通りです。

フィールド
duration_avg 245.7216
duration_max 479.79
duration_min 93.94
duration_pct25 164.38
duration_pct50 222.96
duration_pct75 321.28
duration_count 100
initDuration_avg 666.3295
initDuration_max 747.01
initDuration_min 569.76
initDuration_pct25 643.28
initDuration_pct50 669.78
initDuration_pct75 687.03
initDuration_count 43

パターン4. RDS Proxyの接続をhandlerの内側で実行するLambda関数 × 並列100回実行_CloudWatch Logs Insights

initDuration_countが43になっていることから43回コールドスタートが発生したことが分かります。

各パターンの結果比較

各パターンの結果比較します。

フィールド パターン1 パターン2 パターン3 パターン4
duration_avg 45.8541 119.3956 113.3586 245.7216
duration_max 237.3 261.13 341.75 479.79
duration_min 13.29 82.56 25.12 93.94
duration_pct25 23.33 94.8905 61.7404 164.38
duration_pct50 34.88 105.2851 97.3888 222.96
duration_pct75 51.42 124.7844 146.7171 321.28
duration_count 100 100 100 100
initDuration_avg 696.14 690.17 801.1223 666.3295
initDuration_max 696.14 690.17 1273.24 747.01
initDuration_min 696.14 690.17 616.83 569.76
initDuration_pct25 696.14 690.17 729.95 643.28
initDuration_pct50 696.14 690.17 794.79 669.78
initDuration_pct75 696.14 690.17 842.5 687.03
initDuration_count 1 1 30 43

直列実行内、並列実行内で見比べると、duration_から始まる項目はRDS Proxyの接続をhandlerの外側で実行するLambda関数の方が処理時間が短いですね。

また、直列実行と並列実行で比較すると、ウォームスタートの差で直列実行の方が処理時間が短くなっていることも分かります。

ただし、各パターンのステートマシンの開始から終了までの時間を比較すると、直列実行よりも並列実行の方が圧倒的に短いことが分かります。並列実行の場合はLambda関数が30多重以上で実行されていたので、ウォームスタートの差が全体の処理完了までに与える影響を小さくしていたと判断できます。

パターン ステートマシンの開始から終了までの時間
パターン1 24秒
パターン2 30秒
パターン3 4秒
パターン4 4秒

パフォーマンスを優先するならRDS Proxyの接続を使い回した方が良さそう

Lambda関数のhandlerの外側でRDS Proxyの接続をした場合の処理時間を計測してみました。

Lambda関数のhandlerの外側でRDS Proxyに接続することで、RDS Proxyへのコネクションを使い回すことができ、後続のLambda関数の処理時間を減らすことが確認できました。

Lambda関数のhandlerの外側でRDS Proxyの接続をする場合の注意点は接続を確立したままになる点です。そのため、長時間接続が放置されないようにアイドルクライアントの接続タイムアウトを適切な時間にする必要があります。(デフォルトは30分で最大8時間)

この記事が誰かの助けになれば幸いです。

以上、AWS事業本部 コンサルティング部の のんピ(@non____97)でした!