.NET × PostgreSQL：Npgsqlのコネクションプールをログで可視化して理解する

C# で PostgreSQL を扱う際の選択肢の一つに Npgsql があります。
Npgsql にはコネクションプールの仕組みが組み込まれており、これはデフォルトで有効になっています。
接続文字列に含めるパラメータを変更することで、このコネクションプールの挙動を制御することができますが、実際にどのように変化するのか気になりました。
そこで今回は、設定値を変えて Npgsql や PostgreSQL のログ、pg_stat_activity を通じて、挙動を検証してみたいと思います。

環境

以下の環境で動作確認を行っています。

事前準備

各種ログの出力設定やクエリの準備を行います。

Npgsqlのログ設定

NpgsqlをDI（依存性の注入）で利用している場合、ログ出力は自動的に有効になります。Web APIでの登録例は以下の通りです（Npgsql.DependencyInjection が必要です）。

builder.Services.AddNpgsqlDataSource(connectionString);

トレースレベルまでログを出力するために、appsettings.json に5行目の記載を追加します。

{
    "Logging": {
        "LogLevel": {
            "Default": "Information",
            "Npgsql": "Trace"
        }
    },
    （略）
}

PostgreSQLのログ設定

「postgresql.conf」の設定を変更します。あくまで一例ですので必要に応じてカスタマイズします。コネクション接続切断のログは必要ですので有効化します。

log_min_messages = info
log_connections = on
log_disconnections = on

# %m = timestamp with milliseconds
# %p = process ID
# %r = remote host and port
# %c = session ID
# %Q = query ID (0 if none or not computed)
# %e = SQL state
log_line_prefix = '%m [%p] %r %c %Q %e'

pg_stat_activityの確認

どの接続が確立され、どのクエリが実行されているのかをリアルタイムで把握することができます。

select pid,client_port,backend_start,state_change from pg_stat_activity
where application_name = 'sqltest'

動作確認

コネクションプールに関するパラメータの中でも、以下3つの関係性を確認します。

検証するパターンは以下の4通りです。

SQLを1回だけ実行するAPIを作成し、適宜実行間隔を調整しながらコネクションの状態を確認しました。

パターン1

パターン1はデフォルトの状態に近い設定値です。検証しやすくするために、「ConnectionIdleLifetime = 60」に短縮しています。

以下のとおり3回APIを実行しました。1回目と2回目は1分以上、2回目と3回目は1分以内の間隔で実行しています。

コネクションの状態を確認すると、1回目と2回目の間では pid（PostgreSQL のバックエンドプロセス ID）とクライアントポートが変化しています。一方で、2回目と3回目の間ではそれらが同じままでした。
このことから、「ConnectionIdleLifetime = 60」の設定通り、60秒以上リクエストがないとコネクションが切断されることが確認できます。

またPostgreSQLのログを見ても、ちょうど1分経過後に切断され、その後のリクエストで再度新しいコネクションが確立されていることが分かります。

2025-07-19 05:13:58.120 UTC [18368] :  connection received: host=::1 port=64161
2025-07-19 05:13:58.134 UTC [18368]：connection authenticated: identity="postgres"...
2025-07-19 05:13:58.134 UTC [18368] :  connection authorized: user=postgres ...
2025-07-19 05:14:58.215 UTC [18368]:  disconnection: session time: 0:01:00.134 ...
2025-07-19 05:15:25.878 UTC [16168] :  connection received: host=::1 port=64260
2025-07-19 05:15:25.890 UTC [16168] :  connection authenticated: identity="postgres" ...
2025-07-19 05:15:25.890 UTC [16168] :  connection authorized: user=postgres ...
2025-07-19 05:16:25.950 UTC [16168]:  disconnection: session time: 0:01:00.105 ...

Npgsql のログでも、同様の挙動が確認できます。こちらでは、物理的なコネクションの確立や切断、また論理的なコネクションの開始・終了といった詳細なログが出力されます。

API を実行すると、コマンドの完了後にコネクションはいったん閉じられますが、これは物理的な切断ではなく、プールに戻されるだけです。
そして、「ConnectionIdleLifetime = 60」 を過ぎると、そのアイドル状態のコネクションが物理的に切断されます。

この状態で再度 API を実行すると、ログには「Opening connection to …」と表示され、新たにコネクションの確立処理が行われる様子が確認できます。

Opening connection to localhost:5432/postgres...
Opening physical connection to localhost:5432/postgres...
Attempting to connect to [::1]:5432
Socket connected to localhost:5432
Opened physical connection to localhost:5432/postgres (in 270ms)
Opened connection to localhost:5432/postgres
Command execution completed (duration=105ms): select ...
Closing connection to localhost:5432/postgres...
Closed connection to localhost:5432/postgres
・・・1分後・・・
Closing physical connection to localhost:5432/postgres...
Closed physical connection to localhost:5432/postgres
・・・API実行・・・
Opening connection to localhost:5432/postgres...
（略）

パターン2

パターン2では最低プールサイズを1に変更します。。パターン1と同様に何度かAPIを実行しました。

コネクションの状態を確認しても、すべて同じバックエンドプロセスに同じポートで接続されています。

PostgreSQLのログでも、アプリを終了させてコネクションを強制的に切断するまで一度も切断されていないことが分かります。

2025-07-19 04:55:43.289 UTC [11548] :  connection received: host=::1 port=63095
2025-07-19 04:55:43.353 UTC [11548] :  connection authenticated: identity="postgres" …
2025-07-19 04:55:43.353 UTC [11548] :  connection authorized: user=postgres …
・・・アプリ終了・・・
2025-07-19 04:59:12.883 UTC [11548] :  disconnection: session time: 0:03:29.643 …

パターン1と2より、ConnectionIdleLifetime に設定した時間が経過すると、アイドル状態のコネクションは切断されますが、MinPoolSizeを設定している場合はその値の数だけ維持されることが分かります。

パターン3

パターン3ではConnectionLifetime MinPoolSize の関係性を確認します。まずはコネクションのライフタイムを1分にします。そして同様に数回APIを実行します。

コネクションの状態を見ると、60秒以上経過している場合はpidやポートが変わっているため、別のコネクションが使用されていると思われます。

PostgreSQLのログを見ると具体的な動きが確認できます。APIが実行される際に一度切断してから新しいコネクションを張っています。

2025-07-19 04:34:52.155 UTC [4444]  :  connection received: host=::1 port=62052
2025-07-19 04:34:52.204 UTC [4444]  :  connection authenticated: identity="postgres" ...
2025-07-19 04:34:52.204 UTC [4444]  :  connection authorized: user=postgres 
2025-07-19 04:37:30.498 UTC [4444]  :  disconnection: session time: 0:02:38.371 
2025-07-19 04:37:30.582 UTC [6068] :  connection received: host=::1 port=62171
2025-07-19 04:37:30.594 UTC [6068] :  connection authenticated: identity="postgres" ...
2025-07-19 04:37:30.594 UTC [6068] :  connection authorized: user=postgres 
2025-07-19 04:38:36.203 UTC [6068] :  disconnection: session time: 0:01:05.646 
2025-07-19 04:38:36.288 UTC [8780] :  connection received: host=::1 port=62250
2025-07-19 04:38:36.299 UTC [8780] :  connection authenticated: identity="postgres" ...
2025-07-19 04:38:36.299 UTC [8780] :  connection authorized: user=postgres 

Npgsqlのログでも、同様のログが確認できます。

Connection has exceeded its maximum lifetime ('00:01:00') and will be closed

パターン4

最後はコネクションを5つ張った状態で60秒以上経過後、1回APIを実行するとどうなるのかを確認します。

まずは、Jmeterなどで負荷をかけてコネクションを5つ張ります。

60秒経過後APIを1回だけ実行した結果が以下になります。新しいコネクションが1つだけになりました。

Npgsqlのログでも、API実行時に5つの既存コネクションがすべて切断されている様子を確認できます。

パターン3の結果から、実施前はコネクションが1つだけ作り直されると思っていましたが、ライフタイムが終了したコネクションはすべて切断されました。また、「MinPoolSize = 5」でも、新規に作成されるコネクションは5つになるわけではなく、必要最低限の数だけ作成されていました。

まとめ

Npgsql にはデフォルトで有効なコネクションプール機能が備わっており、接続文字列のパラメータを調整することで、プールの挙動を細かく制御できます。
本記事では主に ConnectionLifetime、ConnectionIdleLifetime、MinPoolSize の3つに注目し、それぞれの設定によってコネクションの維持や再接続のタイミングがどう変わるのかを PostgreSQL のログや pg_stat_activity、Npgsql のトレースログを使って可視化しました。

実際にログを追ってみることで、アイドル状態の切断タイミングや、物理的な接続の再確立など、普段は見えにくい動作の裏側を確認することができます。
パフォーマンスやリソース効率を意識したコネクション管理が求められる場面では、これらのパラメータを理解し、適切に設定することが重要です。