[pgpool-general-jp: 1630] connection_count がずれてpgpoolに接続できなくなる

[相澤 徹]

お世話になります。

相澤と申します。

■環境
OS: RHEL7.5
Pgpool: 4.1.0
Postgresql: 9.6.16

■設定
pgpool.conf
---
reserved_connections = 0
num_init_children = 195
child_life_time = 300
child_max_connections = 0
connection_life_time = 0
client_idle_limit = 0
max_pool = 2
connection_cache = on


postgresql.conf
---
max_connections = 400
superuser_reserved_connections = 10

■発生事象
pgpoolの運用を開始してしばらく(2か月程度)して、"Sorry, too many clients already" のメッセージが出力され、
クライアントがDBに時々接続できなくなる事象が発生しました。

【抜粋】
May 26 02:30:01 mydb01 pgpool[29169]: [585626-1] 2020-05-26 02:30:01: pid 29169: ERROR:  Sorry, too many clients already
May 26 02:30:01 mydb01 pgpool[32689]: [585886-1] 2020-05-26 02:30:01: pid 32689: ERROR:  Sorry, too many clients already
May 26 03:01:03 mydb01 pgpool[3813]: [586131-1] 2020-05-26 03:01:03: pid 3813: ERROR:  Sorry, too many clients already
May 26 03:01:03 mydb01 pgpool[1634]: [585988-1] 2020-05-26 03:01:03: pid 1634: ERROR:  Sorry, too many clients already

同タイミングでpsコマンドでプロセスを確認すると、

$ ps ax | grep pgpool | grep 'wait for'
 1019 ?        S      0:00 pgpool: wait for connection request
 1030 ?        S      0:00 pgpool: wait for connection request
 1214 ?        S      0:00 pgpool: wait for connection request
 ...
 ...

 $ ps ax | grep pgpool | grep 'wait for' | wc -l
121

となっていて、wait for connection request となっている子プロセスはまだ余っている状態でした。


状況的には、出力ログの内容から下記ソースコード335行目部分のconnection countのチェックにひっかかっているのではないかと推測しました。

https://github.com/pgpool/pgpool2/blob/master/src/protocol/child.c#L335


そこで、 pgpool.conf で、 log_min_messages = debug5 に設定を変更して、pgpoolのreload を行ったところ、

"Sorry, too many clients already" が出力される同じタイミングで以下のログが出力されました。

May 29 00:44:43 mydb01 pgpool[15600]: [703473-1] 2020-05-29 00:44:43: pid 15600: ERROR:  Sorry, too many clients already

# journalctl -u pgpool -f | grep --line-buffered  'connection_count'
 5月 29 00:44:45 mydb01 pgpool[15600]: [703474-1] 2020-05-29 00:44:45: pid 15600: DEBUG:  connection_count_up: number of connected children: 196
 5月 29 00:44:45 mydb01 pgpool[15600]: [703475-1] 2020-05-29 00:44:45: pid 15600: DEBUG:  connection_count_down: number of connected children: 195


上記のログより、pgpool内部で保持するconnection count と、実際の接続数に乖離が発生していたものと判断し、
pgpoolをrestartしたところ、上記事象は解消されました。

■質問

1) pgpool内部で保持するconnection count と、実際の接続数に乖離が発生していたと考えますが、
そのような乖離が発生する条件としてどのようなことが考えられますでしょうか。

2) 似たような事象の発生例等、ご存知でしょうか。

3) 対処方法
しばらくの間、pgpoolのプロセスを定期的に再起動（月一回程度）して対処しようと思いますが、
より良い対処方法があればご教示ください。（pgpoolの再起動を避けられるのであれば避けたい）




以上、よろしくお願いいたします。

---
Tetsu Aizawa <tr-aizawa ＠ netone.co.jp>