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

2020年 6月 11日 (木) 14:07:05 JST

はじめまして、星合です。

On Wed, 3 Jun 2020 11:54:42 +0000
相澤 徹 <tr-aizawa ＠ netone.co.jp> wrote:

> お世話になります。
> 
> 相澤と申します。
> 
> ■環境
> 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) 似たような事象の発生例等、ご存知でしょうか。

Pgpool-IIの子プロセスが、正常に使用ないし再起動している間は、connection countが
乖離する事象は分からないです。
ただし、クライアントから接続中であるpgpoolの子プロセスがkillコマンドなどにより、
強制終了させられたりした場合、connction countの値が乖離する場合はあると思います。

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

connection_countの値が乖離した場合、現状再起動する以外の対処方法は無いと思います。

乖離した理由がバグなのかどうか確認するため、以下について教えていただければこちらでも調べてみます。
・運用されていた期間のpgpoolのログ中に、ERRORやFATAILのログありますでしょうか？
・その他、運用中にPostgreSQLのフェイルオーバなどのイベントは発生しましたでしょうか？

上記について、発生していれば、それぞれ前後のログを共有していただけると調査がしやすいです。
> 
> 以上、よろしくお願いいたします。
> 
> ---
> Tetsu Aizawa <tr-aizawa ＠ netone.co.jp>
> 
> _______________________________________________
> pgpool-general-jp mailing list
> pgpool-general-jp ＠ sraoss.jp
> http://www.sraoss.jp/mailman/listinfo/pgpool-general-jp


-- 
Takuma Hoshiai <hoshiai ＠ sraoss.co.jp>