Aurora ServerlessのData APIは裏側でコネクションプーリングを実現してくれているという話

CX事業本部の岩田です。 Aurora ServerlessのData APIがリリースされた際に「Lambda <-> RDSの最大同時接続数の問題が改善される」といった話を聞くことが多かったのですが、なぜhttpsのエンドポイントができただけで同時接続数の問題が解決するのか、いまいち良く分かりませんでした。

1
2
3
4
5
# DBへの接続処理
# コールドスタート時のみ接続し、接続を使い回すことでオーバーヘッドを低減する
 
def handler(event, conext):
    # lambdasのメイン処理

こういう実装のLambdaだとアイドル中にもDB接続を消費してムダなのは分かりますが、それなら

1
2
3
4
def handler(event, conext):
    # DBへの接続処理
    # lambdasのメイン処理
    # DB切断処理

みたいな組み方をすれば良い訳で、Data APIの存在と同時接続に対する耐性の関連性がイマイチ腑に落ちていなかったのです。という訳で、本当にData APIを利用することで同時接続に対する耐性が上がるのか実験してみました。

環境

今回検証に利用した環境です

  • DBエンジン： Aurora PostgreSQL (compatible with PostgreSQL 10.7)
  • データベースの機能: サーバーレス
  • アイドル状態になった後の一時停止: 5分
  • マスターユーザー名: postgres
  • 検証用のデータベース: iwatadb
  • 検証用のDBユーザー: cm-iwata
  • キャパシティの設定(最小):2(4GBRAM)
  • キャパシティの設定(最大):2(4GBRAM)

事前準備としてパラメターグループを以下の通り変更しています

  • log_statementをallに
  • log_connectionsをtrueに

結論

まずはじめに結論をData APIの裏側ではpgpool-IIのようなプロキシ型のコネクションプーリング機構が動作しているようです。よって、Data APIによって同時接続数の問題が改善されるという話は正しいと言えそうです。 ※詳しくは後述しますが、ユースケースにもよります。

検証1 普通にData APIからSQLを実行した時のログを確認

まず手始めに自分のローカルPCからAWS CLIでData APIを叩いてみます。前提としてしばらくアイドル時間を設けてDBインスタンスが一時停止している状態から実行しています。

1
aws rds-data execute-statement --database iwatadb --sql 'select pg_sleep(10)' --resource-arn  arn:aws:rds:ap-northeast-1:xxxxxxxxxxx:cluster:aurora-sls-db --secret-arn arn:aws:secretsmanager:ap-northeast-1:xxxxxxxxxxxx:secret:sls-db-cm-iwata-MlSjOK

無事に実行できました

1
2
3
4
5
6
7
8
9
10
{
    "numberOfRecordsUpdated": 0,
    "records": [
        [
            {
                "stringValue": ""
            }
        ]
    ]
}

この後は何もせず10分ほど放置し、10分後にログを確認してみます。一時停止状態から起動するログが色々出力されていたので、関連しそうな部分だけ抜粋しています。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
2019-11-11 04:35:42 UTC:10.1.21.74(33953):[unknown]@[unknown]:[7146]:LOG: connection received: host=10.1.21.74 port=33953
2019-11-11 04:35:42 UTC:10.1.21.74(33953):cm-iwata@iwatadb:[7146]:LOG: connection authorized: user=cm-iwata database=iwatadb
2019-11-11 04:35:42 UTC:10.1.21.74(33953):cm-iwata@iwatadb:[7146]:LOG: execute <unnamed>: SET extra_float_digits = 3
2019-11-11 04:35:42 UTC:10.1.21.74(33953):cm-iwata@iwatadb:[7146]:LOG: execute <unnamed>: SET application_name = 'PostgreSQL JDBC Driver'
2019-11-11 04:35:42 UTC:10.1.21.74(33953):cm-iwata@iwatadb:[7146]:LOG: execute <unnamed>: SHOW TRANSACTION ISOLATION LEVEL
2019-11-11 04:35:42 UTC:10.1.21.74(33953):cm-iwata@iwatadb:[7146]:LOG: disconnection: session time: 0:00:00.156 user=cm-iwata database=iwatadb host=10.1.21.74 port=33953
 
 
2019-11-11 04:35:42 UTC:10.1.13.68(24081):[unknown]@[unknown]:[7147]:LOG: connection received: host=10.1.13.68 port=24081
2019-11-11 04:35:42 UTC:10.1.13.68(24081):cm-iwata@iwatadb:[7147]:LOG: connection authorized: user=cm-iwata database=iwatadb
2019-11-11 04:35:42 UTC:10.1.13.68(24081):cm-iwata@iwatadb:[7147]:LOG: execute <unnamed>: SET extra_float_digits = 3
2019-11-11 04:35:42 UTC:10.1.13.68(24081):cm-iwata@iwatadb:[7147]:LOG: execute <unnamed>: SET application_name = 'PostgreSQL JDBC Driver'
2019-11-11 04:35:42 UTC:10.1.13.68(24081):cm-iwata@iwatadb:[7147]:LOG: execute <unnamed>: select pg_sleep(10)
2019-11-11 04:35:52 UTC:10.1.13.68(24081):cm-iwata@iwatadb:[7147]:LOG: execute <unnamed>: DISCARD ALL
2019-11-11 04:35:53 UTC:10.1.13.68(24081):cm-iwata@iwatadb:[7147]:LOG: execute <unnamed>: SELECT n.nspname = ANY(current_schemas(true)), n.nspname, t.typname FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON t.typnamespace = n.oid WHERE t.oid = $1
2019-11-11 04:35:53 UTC:10.1.13.68(24081):cm-iwata@iwatadb:[7147]:DETAIL: parameters: $1 = '2278'
2019-11-11 04:35:53 UTC:10.1.13.68(24081):cm-iwata@iwatadb:[7147]:LOG:  execute <unnamed>: SELECT typinput='array_in'::regproc, typtype   FROM pg_catalog.pg_type   LEFT   JOIN (select ns.oid as nspoid, ns.nspname, r.r           from pg_namespace as ns           join ( select s.r, (current_schemas(false))[s.r] as nspname                    from generate_series(1, array_upper(current_schemas(false), 1)) as s(r) ) as r          using ( nspname )        ) as sp     ON sp.nspoid = typnamespace  WHERE typname = $1  ORDER BY sp.r, pg_type.oid DESC LIMIT 1
2019-11-11 04:35:53 UTC:10.1.13.68(24081):cm-iwata@iwatadb:[7147]:DETAIL: parameters: $1 = 'void'
2019-11-11 04:41:14 UTC:10.1.13.68(24081):cm-iwata@iwatadb:[7147]:LOG: disconnection: session time: 0:05:31.980 user=cm-iwata database=iwatadb host=10.1.13.68 port=24081

まず10.1.21.74というIPがAuroraに接続、SHOW TRANSACTION ISOLATION LEVELを実行後に接続を切断しています。何やってるんでしょうね？インスタンスが一時停止から復旧した後の初期処理とかでしょうか？ 見やすいようにprefixを削除すると以下のようになります。

1
2
3
4
5
6
connection received: host=10.1.21.74 port=33953
connection authorized: user=cm-iwata database=iwatadb
execute <unnamed>: SET extra_float_digits = 3
execute <unnamed>: SET application_name = 'PostgreSQL JDBC Driver'
execute <unnamed>: SHOW TRANSACTION ISOLATION LEVEL
disconnection: session time: 0:00:00.156 user=cm-iwata database=iwatadb host=10.1.21.74 port=33953

その後10.1.13.68というIPが接続し、以下の順番でクエリを実行しています。

  • SET extra_float_digits = 3
  • SET application_name = 'PostgreSQL JDBC Driver'
  • Data APIで指定したSQL
  • DISCARD ALL
  • SELECT n.nspname = ANY(current_schemas(true)), n.nspname, t.typname FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON t.typnamespace = n.oid WHERE t.oid = $1
  • SELECT typinput='array_in'::regproc, typtype FROM pg_catalog.pg_type LEFT JOIN (select ns.oid as nspoid, ns.nspname, r.r from pg_namespace as ns join ( select s.r, (current_schemas(false))[s.r] as nspname from generate_series(1, array_upper(current_schemas(false), 1)) as s(r) ) as r using ( nspname ) ) as sp ON sp.nspoid = typnamespace WHERE typname = $1 ORDER BY sp.r, pg_type.oid DESC LIMIT 1

発行しているSQLの内容からしてこちらのセッションがData APIのセッションのようです。 こちらもprefixを削除したログを乗せておきます。

1
2
3
4
5
6
7
8
9
10
11
connection received: host=10.1.13.68 port=24081
connection authorized: user=cm-iwata database=iwatadb
execute <unnamed>: SET extra_float_digits = 3
execute <unnamed>: SET application_name = 'PostgreSQL JDBC Driver'
execute <unnamed>: select pg_sleep(10)
execute <unnamed>: DISCARD ALL
execute <unnamed>: SELECT n.nspname = ANY(current_schemas(true)), n.nspname, t.typname FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON t.typnamespace = n.oid WHERE t.oid = $1
parameters: $1 = '2278'
execute <unnamed>: SELECT typinput='array_in'::regproc, typtype   FROM pg_catalog.pg_type   LEFT   JOIN (select ns.oid as nspoid, ns.nspname, r.r           from pg_namespace as ns           join ( select s.r, (current_schemas(false))[s.r] as nspname                    from generate_series(1, array_upper(current_schemas(false), 1)) as s(r) ) as r          using ( nspname )        ) as sp     ON sp.nspoid = typnamespace  WHERE typname = $1  ORDER BY sp.r, pg_type.oid DESC LIMIT 1
parameters: $1 = 'void'
disconnection: session time: 0:05:31.980 user=cm-iwata database=iwatadb host=10.1.13.68 port=24081

その後5分ほど経過した後disconnection: session time: 0:05:31.980...の部分でDBから切断しています。このことから、Data APIはSQL発行後も内部的にはDB接続を維持しているということが分かります。Data APIの基盤がpgpool-IIのような中間層として働いているようです。

検証2 Data APIから定期的にSQLを実行した時のログ

先ほどの検証はData APIから1回だけSQLを発行して終了しました。ログを確認するとData APIで指定したSQL以外にも色々なSQLが発行されていたので、インスタンス一時停止からの復旧時やData APIが内部的に使い回す接続確立時の初期化処理でも色々とSQLを発行していそうです。このあたりの基板側で自動発行しているSQLを見分けるために、今度は5分の間隔を空けずに何度かData APIからSQLを発行しログを確認してみます。

結果は以下のようになりました。 検証1と同様にSHOW TRANSACTION ISOLATION LEVELを実行するセッションが接続後すぐに切断されていたので、その分のログは省略しています。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
2019-11-11 05:40:47 UTC:10.1.18.254(46141):[unknown]@[unknown]:[11167]:LOG: connection received: host=10.1.18.254 port=46141
2019-11-11 05:40:47 UTC:10.1.18.254(46141):cm-iwata@iwatadb:[11167]:LOG: connection authorized: user=cm-iwata database=iwatadb
2019-11-11 05:40:47 UTC:10.1.18.254(46141):cm-iwata@iwatadb:[11167]:LOG: execute <unnamed>: SET extra_float_digits = 3
2019-11-11 05:40:47 UTC:10.1.18.254(46141):cm-iwata@iwatadb:[11167]:LOG: execute <unnamed>: SET application_name = 'PostgreSQL JDBC Driver'
2019-11-11 05:40:47 UTC:10.1.18.254(46141):cm-iwata@iwatadb:[11167]:LOG: execute <unnamed>: select pg_sleep(10)
2019-11-11 05:40:57 UTC:10.1.18.254(46141):cm-iwata@iwatadb:[11167]:LOG: execute <unnamed>: DISCARD ALL
2019-11-11 05:40:57 UTC:10.1.18.254(46141):cm-iwata@iwatadb:[11167]:LOG: execute <unnamed>: SELECT n.nspname = ANY(current_schemas(true)), n.nspname, t.typname FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON t.typnamespace = n.oid WHERE t.oid = $1
2019-11-11 05:40:57 UTC:10.1.18.254(46141):cm-iwata@iwatadb:[11167]:DETAIL: parameters: $1 = '2278'
2019-11-11 05:40:57 UTC:10.1.18.254(46141):cm-iwata@iwatadb:[11167]:LOG: execute <unnamed>: SELECT typinput='array_in'::regproc, typtype FROM pg_catalog.pg_type LEFT JOIN (select ns.oid as nspoid, ns.nspname, r.r from pg_namespace as ns join ( select s.r, (current_schemas(false))[s.r] as nspname from generate_series(1, array_upper(current_schemas(false
2019-11-11 05:40:57 UTC:10.1.18.254(46141):cm-iwata@iwatadb:[11167]:DETAIL: parameters: $1 = 'void'
2019-11-11 05:43:16 UTC:10.1.18.254(46141):cm-iwata@iwatadb:[11167]:LOG: execute <unnamed>: select pg_sleep(10)
2019-11-11 05:43:26 UTC:10.1.18.254(46141):cm-iwata@iwatadb:[11167]:LOG: execute <unnamed>: DISCARD ALL
2019-11-11 05:44:20 UTC:10.1.18.254(46141):cm-iwata@iwatadb:[11167]:LOG: execute <unnamed>: select pg_sleep(10)
2019-11-11 05:44:30 UTC:10.1.18.254(46141):cm-iwata@iwatadb:[11167]:LOG: execute <unnamed>: DISCARD ALL
2019-11-11 05:46:22 UTC:10.1.18.254(46141):cm-iwata@iwatadb:[11167]:LOG: execute <unnamed>: select pg_sleep(10)
2019-11-11 05:46:32 UTC:10.1.18.254(46141):cm-iwata@iwatadb:[11167]:LOG: execute <unnamed>: DISCARD ALL

このログを見る限り

  • SET extra_float_digits = 3
  • SET application_name = 'PostgreSQL JDBC Driver'
  • Data APIで指定したSQL
  • DISCARD ALL
  • SELECT n.nspname = ANY(current_schemas(true)), n.nspname, t.typname FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON t.typnamespace = n.oid WHERE t.oid = $1
  • SELECT typinput='array_in'::regproc, typtype FROM pg_catalog.pg_type LEFT JOIN (select ns.oid as nspoid, ns.nspname, r.r from pg_namespace as ns join ( select s.r, (current_schemas(false))[s.r] as nspname from generate_series(1, array_upper(current_schemas(false), 1)) as s(r) ) as r using ( nspname ) ) as sp ON sp.nspoid = typnamespace WHERE typname = $1 ORDER BY sp.r, pg_type.oid DESC LIMIT 1

という流れは同様で、以後Data APIを呼ぶごとに

  • Data APIで指定したSQL
  • DISCARD ALL

を繰り返していそうです。SELECT n.nspname =...というSQLとSELECT typinput='array_in...というSQLはData APIの初回実行時のみ発行されています。レスポンスをJSON形式で生成するために必要なメタデータを取得しているとかでしょうか？

検証3 Data APIが確立した接続を強制的に切断してみる

SHOW TRANSACTION ISOLATION LEVEL等のSQLを発行しているのはData API用の初期化処理なのか、インスタンスが一時停止から復旧した際固有の処理なのかを切り分けたいと思います。EC2から普通にpsqlでAuroraに接続し、Data API用のセッションを強制的に切断します。

まずpg_stat_activityからData API用セッションのPIDを確認します。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
postgres=> select *  from pg_stat_activity where usename <> 'rdsadmin' and usename <> 'postgres' ;
-[ RECORD 1 ]----+------------------------------
datid            | 20494
datname          | iwatadb
pid              | 624
usesysid         | 20493
usename          | cm-iwata
application_name |
client_addr      | 10.1.13.68
client_hostname  |
client_port      | 40893
backend_start    | 2019-11-11 06:11:41.079755+00
xact_start       |
query_start      | 2019-11-11 06:13:58.101254+00
state_change     | 2019-11-11 06:13:58.101365+00
wait_event_type  | Client
wait_event       | ClientRead
state            | idle
backend_xid      |
backend_xmin     |
query            | DISCARD ALL
backend_type     | client backend

pg_terminate_backendで強制終了します。※pg_cancel_backendだと止まってくれませんでした。

1
2
3
postgres=> select pg_terminate_backend(624);
-[ RECORD 1 ]--------+--
pg_terminate_backend | t

pg_stat_activityからセッションが切断されたことを確認し、再度Data APIを叩いてログを確認してみます。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
2019-11-11 06:15:37 UTC:10.1.11.126(32095):postgres@postgres:[4323]:LOG: statement: select pg_terminate_backend(624);
2019-11-11 06:15:37 UTC:10.1.13.68(40893):cm-iwata@iwatadb:[624]:FATAL: terminating connection due to administrator command
2019-11-11 06:15:37 UTC:10.1.13.68(40893):cm-iwata@iwatadb:[624]:LOG: disconnection: session time: 0:03:56.365 user=cm-iwata database=iwatadb host=10.1.13.68 port=40893
2019-11-11 06:15:40 UTC:10.1.11.126(32095):postgres@postgres:[4323]:LOG: statement: select * from pg_stat_activity where usename <> 'rdsadmin' and usename <> 'postgres' ;
2019-11-11 06:16:01 UTC:10.1.21.74(59949):[unknown]@[unknown]:[6461]:LOG: connection received: host=10.1.21.74 port=59949
2019-11-11 06:16:01 UTC:10.1.21.74(59949):cm-iwata@iwatadb:[6461]:LOG: connection authorized: user=cm-iwata database=iwatadb
2019-11-11 06:16:01 UTC:10.1.21.74(59949):cm-iwata@iwatadb:[6461]:LOG: execute <unnamed>: SET extra_float_digits = 3
2019-11-11 06:16:01 UTC:10.1.21.74(59949):cm-iwata@iwatadb:[6461]:LOG: execute <unnamed>: SET application_name = 'PostgreSQL JDBC Driver'
2019-11-11 06:16:01 UTC:10.1.21.74(59949):cm-iwata@iwatadb:[6461]:LOG: execute <unnamed>: select pg_sleep(1)
2019-11-11 06:16:02 UTC:10.1.21.74(59949):cm-iwata@iwatadb:[6461]:LOG: execute <unnamed>: DISCARD ALL
2019-11-11 06:16:02 UTC:10.1.21.74(59949):cm-iwata@iwatadb:[6461]:LOG: execute <unnamed>: SELECT n.nspname = ANY(current_schemas(true)), n.nspname, t.typname FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON t.typnamespace = n.oid WHERE t.oid = $1
2019-11-11 06:16:02 UTC:10.1.21.74(59949):cm-iwata@iwatadb:[6461]:DETAIL: parameters: $1 = '2278'
2019-11-11 06:16:02 UTC:10.1.21.74(59949):cm-iwata@iwatadb:[6461]:LOG:  execute <unnamed>: SELECT typinput='array_in'::regproc, typtype   FROM pg_catalog.pg_type   LEFT   JOIN (select ns.oid as nspoid, ns.nspname, r.r           from pg_namespace as ns           join ( select s.r, (current_schemas(false))[s.r] as nspname                    from generate_series(1, array_upper(current_schemas(false), 1)) as s(r) ) as r          using ( nspname )        ) as sp     ON sp.nspoid = typnamespace  WHERE typname = $1  ORDER BY sp.r, pg_type.oid DESC LIMIT 1
2019-11-11 06:16:02 UTC:10.1.21.74(59949):cm-iwata@iwatadb:[6461]:DETAIL: parameters: $1 = 'void'

SHOW TRANSACTION ISOLATION LEVELから始まる一連のSQLが実行されたログはありませんでした。つまりこの一連のSQLはData API用の接続確立時ではなく、DBインスタンスが一時停止から復旧した際に実行される初期処理のようです。

検証3 Data APIから並列にSQLを実行してみる

もう少しData APIの管理用コネクションについて深掘りしてみようと思います。 簡単なシェルスクリプトとxargsを使ってData API経由でSQLを並列実行してみます。

1
2
3
#!/bin/bash
 
aws rds-data execute-statement --database iwatadb --sql 'select pg_sleep(10)' ...略
1
seq 10 | xargs -n 1 -P 10  sh test.sh

実行後にpg_stat_activityの状況を確認してみます。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
select client_addr,client_port,state from pg_stat_activity where usename <> 'rdsadmin' and usename <> 'postgres' order by 1,2;
 
 client_addr | client_port | state
-------------+-------------+-------
 10.1.5.186  |       17877 | idle
 10.1.5.186  |       17887 | idle
 10.1.11.126 |       46717 | idle
 10.1.11.126 |       46719 | idle
 10.1.13.68  |       57565 | idle
 10.1.18.117 |        3641 | idle
 10.1.18.254 |       57589 | idle
 10.1.21.74  |        8297 | idle
 10.1.23.67  |       16005 | idle
 10.1.23.67  |       16541 | idle

接続元のIPアドレスがバラバラになっており、Data APIの接続元コンポーネントが多重に分散していることが分かります。接続元のIPでグルーピングしてみます。

1
2
3
4
5
6
7
8
9
10
11
postgres=> select client_addr,count(*) from pg_stat_activity where usename <> 'rdsadmin' and usename <> 'postgres' group by client_addr order by 1;
 client_addr | count
-------------+-------
 10.1.5.186  |     2
 10.1.11.126 |     2
 10.1.13.68  |     1
 10.1.18.117 |     1
 10.1.18.254 |     1
 10.1.21.74  |     1
 10.1.23.67  |     2
(7 rows)

こんな感じでした。

検証4 Data APIからmax_connections以上の並列度でSQLを実行してみる

検証3は10並列で流しただけだったのでさらに並列度を上げて負荷をかけてみます。まずAuroraの最大同時接続数を確認します。

1
2
3
4
5
postgres=> show max_connections ;
 max_connections
-----------------
 180
(1 row)

Aurora PostgreSQL (compatible with PostgreSQL 10.7)でキャパシティが2の場合、最大同時接続数は180になるようです。

※手動でパラメータグループのmax_connectionsを10とかに変更しましたが、psql上から確認すると反映されていなかったので、恐らくパラメータグループの設定は無視されるのだと思います。

という訳でData APIを200も並列実行すれば最大同時接続数をオーバーしそうです。 API GWのバックエンドにData API経由でselect pg_sleep(10)を実行するだけのLambdaを紐づけ、Lambdaのタイムアウトは15秒に設定、heyコマンドを使って200並列でAPI GWにアクセスします。

1
hey -t 0 -n 200 -c 200 https://xxxxxxxxxx.execute-api.ap-northeast-1.amazonaws.com/dev

実行結果です

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
Summary:
  Total:  15.2422 secs
  Slowest:  15.2376 secs
  Fastest:  10.4117 secs
  Average:  12.8745 secs
  Requests/sec: 13.1214
 
  Total data: 5600 bytes
  Size/request: 28 bytes
 
Response time histogram:
  10.412 [1]  |
  10.894 [99] |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  11.377 [0]  |
  11.859 [0]  |
  12.342 [0]  |
  12.825 [0]  |
  13.307 [0]  |
  13.790 [0]  |
  14.272 [0]  |
  14.755 [0]  |
  15.238 [100]  |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
 
 
Latency distribution:
  10% in 10.4629 secs
  25% in 10.5464 secs
  50% in 15.1961 secs
  75% in 15.2271 secs
  90% in 15.2325 secs
  95% in 15.2347 secs
  99% in 15.2375 secs
 
Details (average, fastest, slowest):
  DNS+dialup: 0.1704 secs, 10.4117 secs, 15.2376 secs
  DNS-lookup: 0.0374 secs, 0.0320 secs, 0.0502 secs
  req write:  0.0088 secs, 0.0000 secs, 0.0497 secs
  resp wait:  12.6952 secs, 10.2242 secs, 15.0572 secs
  resp read:  0.0000 secs, 0.0000 secs, 0.0001 secs
 
Status code distribution:
  [200] 100 responses
  [502] 100 responses

100/200が200OKで正常終了、100/200が502でエラーになっています。

Auroraの接続状況を確認してみます。

1
2
3
4
5
postgres=> select count(*) from pg_stat_activity where usename <> 'rdsadmin' and usename <> 'postgres' ;
 count
-------
   100
(1 row)

200並列でアクセスしましたが、Data API用のコネクションは100までしか確保されていないようです。

接続元IPごとの接続数はこんな感じでした

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
postgres=> select client_addr,count(*) from pg_stat_activity where usename <> 'rdsadmin' and usename <> 'postgres' group by client_addr order by 1;
 
 client_addr | count
-------------+-------
 10.1.0.53   |    11
 10.1.1.21   |    10
 10.1.4.140  |     7
 10.1.5.186  |    13
 10.1.8.81   |     6
 10.1.11.126 |     9
 10.1.12.48  |     5
 10.1.13.68  |     6
 10.1.18.117 |     8
 10.1.18.254 |     7
 10.1.21.74  |     6
 10.1.23.67  |    12
(12 rows)

この状態でCloud Watch Logsのログにmax_connections超過のログが出ていないか確認しましたが、max_connections超過のログは出力されていませんでした。 Lambdaの方のログを確認してみると、、、

1
2019-11-11T08:27:05.995Z 27ec5f17-e5fe-4e32-a70f-fd88ab0e0620 Task timed out after 15.02 seconds

こんなログが出ていました。このことから、今回の検証環境の設定ではAurora Data APIの裏側で

  • 最大100本のDB接続を確立してプールする
  • 101以上の接続要求が来た場合はエラーを返却するのではなく、プールしている接続が空くまで待機する

と言えそうです。

検証5 Data APIからmax_connections以上の並列度でSQLを実行してみる(Lambdaのタイムアウトを延長)

検証4でLambdaのタイムアウトが出ていたのでLambdaのタイムアウト設定を30秒に延長して再トライしてみました。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
Summary:
  Total:  29.1756 secs
  Slowest:  29.1715 secs
  Fastest:  10.3421 secs
  Average:  15.6850 secs
  Requests/sec: 6.8550
 
  Total data: 4084 bytes
  Size/request: 20 bytes
 
Response time histogram:
  10.342 [1]  |
  12.225 [99] |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  14.108 [0]  |
  15.991 [0]  |
  17.874 [0]  |
  19.757 [0]  |
  21.640 [96] |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  23.523 [0]  |
  25.406 [0]  |
  27.289 [0]  |
  29.172 [4]  |■■
 
 
Latency distribution:
  10% in 10.4481 secs
  25% in 10.4780 secs
  50% in 20.4086 secs
  75% in 20.5387 secs
  90% in 20.5911 secs
  95% in 20.5974 secs
  99% in 29.1703 secs
 
Details (average, fastest, slowest):
  DNS+dialup: 0.1489 secs, 10.3421 secs, 29.1715 secs
  DNS-lookup: 0.0158 secs, 0.0117 secs, 0.0176 secs
  req write:  0.0076 secs, 0.0000 secs, 0.0584 secs
  resp wait:  15.5285 secs, 10.1793 secs, 29.0095 secs
  resp read:  0.0000 secs, 0.0000 secs, 0.0001 secs
 
Status code distribution:
  [200] 196 responses
  [504] 4 responses

4/200がAPI GWのタイムアウト上限29秒に抵触してそうですが、

  • 100クライアントが10秒程度で応答受信
  • 96クライアントが20秒程度で応答受信

といいう結果に終わりました。 検証4の結果から予測した通り、Data APIが管理する接続数を超過したリクエストに関しては一旦待機状態になり、接続が空き次第実行されるという動作で間違い無さそうです。

まとめ

Data APIの裏側ではpgpool-IIのようなプロキシ型のコネクションプーリング機構が動作していることが確認できました。 VPC Lambdaのコールドスタート改善によって影が薄くなった感のあるData APIですが、同時接続数の問題に対してはData APIの方が有利な面があるかもしれません。Data APIの管理する接続数はmax_connectionsよりもある程度少ない数値(今回の構成だとmax_connections180に対して100)になるようなので、VPC Lambda × Auroraより有利になるかはワークロード次第と言えそうです。

このあたりの情報も踏まえた上でVPC Lambdaを使うのか、Aurora ServerlessのData APIを使うのか、適切な判断をして頂ければと思います。 もちろん最初にRDBが必要なのか？！RDBを使っても問題のないユースケースなのか？！という点を良くご検討下さい。

PR満足度98%