[pgpool-general: 7220] Re: Idle connection in database
Tatsuo Ishii
ishii at sraoss.co.jp
Sun Aug 30 15:49:08 JST 2020
Before these tests, have applied the patch?
> Hi Tatsuo,
>
>
> I have to reopen this issue because after a lot of debugging and reading
> documentation on connection_life_time though there is not much of it, this
> parameter doesn't work as it should.
>
> First I want to be correct in my understanding that this parameter
> terminates cached backend connections in the database.So, I test a simple
> scenario as follows:
>
> PGPOOL - 128.199.224.132
>
> *Parameters set for pooling*
> serialize_accept=on
> child_life_time=0
> child_max_connections=0
> client_idle_limit=0
> connection_life_time=10
>
> *I am running a mixed.sql file which contain below statements*
> BEGIN;
> SELECT CURRENT_TIMESTAMP;
> INSERT into t1 values(3);
> INSERT into t1 values(4);
> select pg_sleep(5);
> INSERT into t1 values(5);
> UPDATE t1 set id=4 where id=5;
> END;
>
> After executing some inserts it will sleep for 5 seconds and then execute
> one update and an insert before closing the connection.
>
>
> *1) Status of nodes*
> -bash-4.2$ psql -h 128.199.224.132 -p 9999 -U enterprisedb
> psql.bin (11.6.13)
> Type "help" for help.
>
> edb=# show pool_nodes;
> node_id | hostname | port | status | lb_weight | role |
> select_cnt | load_balance_node | replication_delay | replication_state |
> replication_syn
> c_state | last_status_change
> ---------+-----------------+------+--------+-----------+---------+------------+-------------------+-------------------+-------------------+----------------
> --------+---------------------
> 0 | 128.199.222.92 | 5445 | up | 0.000000 | primary | 0
> | false | 0 | |
> | 2020-08-30 04:58:24
> 1 | 128.199.222.124 | 5445 | up | 1.000000 | standby | 0
> | true | 0 | |
> | 2020-08-30 04:58:24
> (2 rows)
>
> *2) Running the mixed.sql file*
> -bash-4.2$ psql -h 128.199.224.132 -p 9999 -U enterprisedb -f mixed.sql
> BEGIN
> current_timestamp
> ----------------------------------
> 30-AUG-20 10:31:47.396527 +05:30
> (1 row)
>
> INSERT 0 1
> INSERT 0 1
> pg_sleep
> ----------
>
> (1 row)
>
> INSERT 0 1
> UPDATE 1
> COMMIT
> -bash-4.2$
>
> *3) pool_pools output shows pgpool (pid - 31560) created one connection to
> master(pid - 31550) and one to standby (pid - 28954) *
>
> edb=# show pool_pools;
> pool_pid | start_time | pool_id | backend_id | database |
> username | create_time | majorversion | minorversion |
> pool_counter | pool_
> backendpid | pool_connected
> ----------+---------------------+---------+------------+----------+--------------+---------------------+--------------+--------------+--------------+------
> -----------+----------------
> 31560 | 2020-08-30 04:51:54 | 0 | 0 | edb |
> enterprisedb | 2020-08-30 05:01:47 | 3 | 0 | 1
> | 31550
> | 0
> 31560 | 2020-08-30 04:51:54 | 0 | 1 | edb |
> enterprisedb | 2020-08-30 05:01:47 | 3 | 0 | 1
> | 28954
> | 0
>
> *4) Status of process id 31550 on master.After the run, as seen below on
> the database is idle*
>
> -bash-4.2$ ps -ef |grep 224.132
> enterpr+ 31550 9148 0 05:01 ? 00:00:00 postgres: enterprisedb edb
> 128.199.224.132[49656] idle
>
> *5) Status of processid 31560 on pgpool.* *After the run, as seen below
> pgpool has released connection as soon as transaction completes*
> [root at pgpool-p pgpool4.1]# ps -ef |grep 31560
> enterpr+ 31560 31557 0 04:51 ? 00:00:00 pgpool: wait for accept lock
>
>
> *6) After 10 seconds, this cached connection on database should have been
> terminated as per my understanding of connection_life_time parameter but as
> seen below it has not terminated*
> edb=# select * from pg_stat_activity where client_addr ='128.199.224.132';
> -[ RECORD 1 ]----+---------------------------------
> datid | 67127
> datname | edb
> pid | 31550
> usesysid | 10
> usename | enterprisedb
> application_name | psql.bin
> client_addr | 128.199.224.132
> client_hostname |
> client_port | 49656
> backend_start | 30-AUG-20 10:31:47.380345 +05:30
> xact_start |
> query_start | 30-AUG-20 10:31:52.411607 +05:30
> state_change | 30-AUG-20 10:31:52.411714 +05:30
> wait_event_type | Client
> wait_event | ClientRead
> state | idle
> backend_xid |
> backend_xmin |
> query | DISCARD ALL
> backend_type | client backend
>
> Do not mind the timestamp, it is in IST for the above query.
>
> *7) From the pgpool logs, it sets the alarm after 10 sec but doesn't really
> close the connection after 10 seconds*
> Aug 30 05:01:52 Pgpool-p pgpool[*31560*]: [252-2] 2020-08-30 05:01:52: pid
> 31560: DETAIL: setting alarm after 10 seconds
>
> Attaching pgpool logs as well.
>
>
> On Wed, Aug 12, 2020 at 9:02 PM Nikhil Shetty <nikhil.dba04 at gmail.com>
> wrote:
>
>> Hi Tatsuo,
>>
>> Thank you, I will check how this works.
>>
>>
>> On Tue, Aug 11, 2020 at 5:52 PM Tatsuo Ishii <ishii at sraoss.co.jp> wrote:
>>
>>> Hi Nikhil,
>>>
>>> > Hi Tatsuo,
>>> >
>>> > We are checking the patch internally before we go ahead and deploy in
>>> > production.
>>>
>>> Ok.
>>>
>>> > If I want to set only one of either connection_life_time or
>>> > client_idle_limit. What do you recommend? Should I set
>>> > client_idle_limit=120 and connection_life_time=0, do you foresee any
>>> > effects of these settings for connection pooling?
>>>
>>> In general connection_life_time is better because:
>>>
>>> 1. when client_idle_limit expires, pgpool needs to fork a new process,
>>> but connection_life_time does not.
>>>
>>> 2. when client_idle_limit expires, it looses mutiple connection pools
>>> (this only applicatable fro max_pool > 1 case) because the
>>> connection pools the process hold go away.
>>>
>>> However if you have very short and frequent sessions, more alarm
>>> system calls with connection_life_time are required and maybe
>>> client_idle_limit wins in this case.
>>>
>>> > Thank you for your time and support.
>>> >
>>> > Thanks and Regards,
>>> > Nikhil
>>> >
>>> > On Mon, Aug 10, 2020 at 11:58 AM Tatsuo Ishii <ishii at sraoss.co.jp>
>>> wrote:
>>> >
>>> >> Hi Nikhil,
>>> >>
>>> >> I have been investigating if there's any case when
>>> >> connection_life_time is not working. Actually it *is*. If primary node
>>> >> is not node 0, connection_life_time does not work. Attached is the
>>> >> patch to fix that. Please try, if you like.
>>> >>
>>> >> > According to your previous message, corresponding pgpool process was
>>> >> > not there, but PostgreSQL backend process were still running. I
>>> >> > suspect the backend process was waiting for TCP/IP connection was
>>> >> > terminated. But to know what was actually happening, I was waiting
>>> for
>>> >> > your response.
>>> >> >
>>> >> >>> "DISCARD ALL" and state idle. I will have to test again to check
>>> the
>>> >> socket
>>> >> >>> status of pid.I will get back on this
>>> >> >
>>> >> > What was that?
>>> >> >
>>> >> >> Hi Tatsuo,
>>> >> >>
>>> >> >>
>>> >> >> Ant reason why connection_idle_limit doesn't remove backend
>>> connection
>>> >> >> after time limit is crossed
>>> >> >>
>>> >> >> Thanks and Regards,
>>> >> >> Nikhil
>>> >> >>
>>> >> >> On Sun, Aug 2, 2020, 12:48 Nikhil Shetty <nikhil.dba04 at gmail.com>
>>> >> wrote:
>>> >> >>
>>> >> >>> Hi Tatsuo,
>>> >> >>>
>>> >> >>> I want to correct my statement from previous email:
>>> >> >>>
>>> >> >>> From ps status *I could not see *that the process (18190 and 18193)
>>> >> were
>>> >> >>> still present on pgpool but the backend process was still present
>>> with
>>> >> >>> "DISCARD ALL" and state idle. I will have to test again to check
>>> the
>>> >> socket
>>> >> >>> status of pid.I will get back on this
>>> >> >>>
>>> >> >>> On Sun, Aug 2, 2020 at 12:15 PM Nikhil Shetty <
>>> nikhil.dba04 at gmail.com>
>>> >> >>> wrote:
>>> >> >>>
>>> >> >>>> Hi Tatsuo,
>>> >> >>>>
>>> >> >>>> >> Assuming you executed "show pool_pools" long after 2020-08-01
>>> >> >>>> >> 06:21:26, that is very strange because connection_life_time
>>> should
>>> >> >>>> >> have been already expired. I wonder if pgpool tried to
>>> disconnect
>>> >> the
>>> >> >>>> >> connection but failed. To check what actually happend, can you
>>> >> check
>>> >> >>>> >> ps status of pgpool process 18190 and 18193?
>>> >> >>>>
>>> >> >>>> >> Also it would be nice you can examine the socket status of
>>> >> PostgreSQL
>>> >> >>>> >> backend 29321 and 29619, and pgpool socket status of process
>>> 18190
>>> >> and
>>> >> >>>> >> 18193?
>>> >> >>>>
>>> >> >>>> From ps status I could see that the process (18190 and 18193) were
>>> >> still
>>> >> >>>> present on pgpool. I will have to test again to check the socket
>>> >> status of
>>> >> >>>> pid.I will get back on this
>>> >> >>>>
>>> >> >>>> Meanwhile, I did some testing of my own for these two parameters(
>>> >> >>>> client_idle_limit and connection_life_time ) and their behaviour:
>>> >> >>>>
>>> >> >>>>
>>> >> >>>> *Test:*
>>> >> >>>>
>>> >> >>>> Database IP:128.199.222.92(master)
>>> >> >>>> Pgpool IP: 128.199.224.132
>>> >> >>>>
>>> >> >>>> *Scenario1:*
>>> >> >>>>
>>> >> >>>> max_pool=1
>>> >> >>>> num_init_children=100
>>> >> >>>> serialize_accept=on
>>> >> >>>> child_max_connections=0
>>> >> >>>> child_life_time=0
>>> >> >>>> connection_life_time=60
>>> >> >>>> client_idle_limit=0
>>> >> >>>>
>>> >> >>>> *1. Connected to Pgpool and ran a query with \watch 1:*
>>> >> >>>> select count(*) from pgbench_accounts ;
>>> >> >>>> \watch 1
>>> >> >>>> Sat 01 Aug 2020 07:25:54 AM UTC (every 1s)
>>> >> >>>>
>>> >> >>>> count
>>> >> >>>> ---------
>>> >> >>>> 6000000
>>> >> >>>>
>>> >> >>>> *2. Checking session in database, one session is active from
>>> pgpool*
>>> >> >>>> Sat 01 Aug 2020 07:26:14 AM UTC
>>> (every 1s)
>>> >> >>>>
>>> >> >>>> pid | query | usename |
>>> >> >>>> client_addr | count | state
>>> >> >>>>
>>> >> >>>>
>>> >>
>>> ------+-----------------------------------------+--------------+-----------------+-------+--------
>>> >> >>>> 3420 | select count(*) from pgbench_accounts ; | enterprisedb |
>>> >> >>>> 128.199.224.132 | 1 | active
>>> >> >>>> (1 row)
>>> >> >>>>
>>> >> >>>> *3. Stopped the query after sometime using Ctrl-C but session is
>>> still
>>> >> >>>> open*
>>> >> >>>> Sat 01 Aug 2020 07:27:35 AM UTC (every 1s)
>>> >> >>>>
>>> >> >>>> count
>>> >> >>>> ---------
>>> >> >>>> 6000000
>>> >> >>>> (1 row)
>>> >> >>>>
>>> >> >>>> ^Cedb=#
>>> >> >>>> edb=#
>>> >> >>>>
>>> >> >>>> *4. Checking session in database, state is now idle*
>>> >> >>>>
>>> >> >>>> Sat 01 Aug 2020 07:28:14 AM UTC (every
>>> 1s)
>>> >> >>>>
>>> >> >>>> pid | query | usename |
>>> >> >>>> client_addr | count | state
>>> >> >>>>
>>> >> >>>>
>>> >>
>>> ------+-----------------------------------------+--------------+-----------------+-------+-------
>>> >> >>>> 3420 | select count(*) from pgbench_accounts ; | enterprisedb |
>>> >> >>>> 128.199.224.132 | 1 | idle
>>> >> >>>>
>>> >> >>>>
>>> >> >>>> *5. Checking session in database after 2 minutes, I can still see
>>> the
>>> >> >>>> database session idle*
>>> >> >>>>
>>> >> >>>> Sat 01 Aug 2020 07:30:02 AM UTC (every
>>> 1s)
>>> >> >>>>
>>> >> >>>> pid | query | usename |
>>> >> >>>> client_addr | count | state
>>> >> >>>>
>>> >> >>>>
>>> >>
>>> ------+-----------------------------------------+--------------+-----------------+-------+-------
>>> >> >>>> 3420 | select count(*) from pgbench_accounts ; | enterprisedb |
>>> >> >>>> 128.199.224.132 | 1 | idle
>>> >> >>>>
>>> >> >>>> *6. Checking connection on pgpool server. connection is still open
>>> >> from
>>> >> >>>> pgpool to database*
>>> >> >>>>
>>> >> >>>> ps -ef|grep edb
>>> >> >>>> enterpr+ 24170 24162 0 06:51 ? 00:00:00 pgpool:
>>> enterprisedb
>>> >> edb
>>> >> >>>> 128.199.222.92(34402) idle
>>> >> >>>>
>>> >> >>>> *7. After being idle for more than 60 seconds, connections are
>>> still
>>> >> open
>>> >> >>>> from pgpool and on database.Connection is removed from pgpool
>>> server
>>> >> after
>>> >> >>>> I quit from the psql terminal but still present in the database as
>>> >> show
>>> >> >>>> below:*
>>> >> >>>> Sat 01 Aug 2020 07:34:26 AM UTC (every 1s)
>>> >> >>>>
>>> >> >>>> pid | query | usename | client_addr | count |
>>> state
>>> >> >>>>
>>> ------+--------------+--------------+-----------------+-------+-------
>>> >> >>>> 3420 | DISCARD ALL | enterprisedb | 128.199.224.132 | 1 |
>>> idle
>>> >> >>>>
>>> >> >>>>
>>> >> >>>>
>>> >> >>>> *Scenario2:*
>>> >> >>>>
>>> >> >>>> max_pool=1
>>> >> >>>> num_init_children=100
>>> >> >>>> serialize_accept=on
>>> >> >>>> child_max_connections=0
>>> >> >>>> child_life_time=0
>>> >> >>>> connection_life_time=0
>>> >> >>>> client_idle_limit=60
>>> >> >>>>
>>> >> >>>> *1. Connected to Pgpool and ran a query with \watch 1:*
>>> >> >>>> edb=# \! date
>>> >> >>>> Sat Aug 1 07:38:45 UTC 2020
>>> >> >>>> select count(*) from pgbench_accounts ;
>>> >> >>>> \watch 1
>>> >> >>>> edb=# select count(*) from pgbench_accounts ;
>>> >> >>>> count
>>> >> >>>> ---------
>>> >> >>>> 6000000
>>> >> >>>> (1 row)
>>> >> >>>>
>>> >> >>>>
>>> >> >>>> *2. Checking session in database, one session is active from
>>> pgpool*
>>> >> >>>>
>>> >> >>>> Sat 01 Aug 2020 07:39:55 AM UTC
>>> (every 1s)
>>> >> >>>>
>>> >> >>>> pid | query | usename |
>>> >> >>>> client_addr | count | state
>>> >> >>>>
>>> >> >>>>
>>> >>
>>> -------+-----------------------------------------+--------------+-----------------+-------+--------
>>> >> >>>> 13427 | select count(*) from pgbench_accounts ; | enterprisedb |
>>> >> >>>> 128.199.224.132 | 1 | active
>>> >> >>>>
>>> >> >>>>
>>> >> >>>> *3. Stopped the query after sometime using Ctrl-C but session is
>>> still
>>> >> >>>> open*
>>> >> >>>> Sat 01 Aug 2020 07:41:39 AM UTC (every 1s)
>>> >> >>>>
>>> >> >>>> count
>>> >> >>>> ---------
>>> >> >>>> 6000000
>>> >> >>>> ^Cedb=#
>>> >> >>>> edb=#
>>> >> >>>>
>>> >> >>>> *4. Checking session in database, state is now idle*
>>> >> >>>>
>>> >> >>>> Sat 01 Aug 2020 07:42:12 AM UTC
>>> (every 1s)
>>> >> >>>>
>>> >> >>>> pid | query | usename |
>>> >> >>>> client_addr | count | state
>>> >> >>>>
>>> >> >>>>
>>> >>
>>> -------+-----------------------------------------+--------------+-----------------+-------+-------
>>> >> >>>> 13427 | select count(*) from pgbench_accounts ; | enterprisedb |
>>> >> >>>> 128.199.224.132 | 1 | idle
>>> >> >>>> (1 row)
>>> >> >>>>
>>> >> >>>>
>>> >> >>>> *5. Checking session in database after 2 minutes, there is no
>>> session
>>> >> in
>>> >> >>>> the database.*
>>> >> >>>>
>>> >> >>>> Sat 01 Aug 2020 07:42:42 AM UTC (every 1s)
>>> >> >>>>
>>> >> >>>> pid | query | usename | client_addr | count | state
>>> >> >>>> -----+-------+---------+-------------+-------+-------
>>> >> >>>> (0 rows)
>>> >> >>>>
>>> >> >>>>
>>> >> >>>> *6. Checking connection on pgpool server. No connection open in
>>> >> pgpool to
>>> >> >>>> database*
>>> >> >>>> ps -ef|grep edb
>>> >> >>>>
>>> >> >>>>
>>> >> >>>> *Observations:*
>>> >> >>>>
>>> >> >>>> With client_idle_limit of 60 seconds, all connections are closed
>>> after
>>> >> >>>> being idle for more than 1 minute. I can see psql session in
>>> database
>>> >> is
>>> >> >>>> still present as shown below, because
>>> >> >>>> I did not quit from psql terminal yet:
>>> >> >>>>
>>> >> >>>> [root at master ~]# ps -ef |grep 128.199.224.132
>>> >> >>>> enterpr+ 13193 28563 0 07:38 pts/0 00:00:00 /bin/bash
>>> /bin/psql -p
>>> >> >>>> 9999 -h 128.199.224.132
>>> >> >>>> enterpr+ 13198 13193 0 07:38 pts/0 00:00:00 /bin/psql.bin -p
>>> 9999
>>> >> -h
>>> >> >>>> 128.199.224.132
>>> >> >>>>
>>> >> >>>>
>>> >> >>>> From scenario 2( client_idle_limit = 60), we can say that when
>>> >> >>>> client_idle_limit is triggered client is disconnected, no database
>>> >> >>>> connection is in use but the session still remains on server.If i
>>> >> start
>>> >> >>>> running query
>>> >> >>>> on same psql session, it will first reset connection and then run
>>> the
>>> >> >>>> query, this will again create a new connection to the database.
>>> >> >>>>
>>> >> >>>> From scenario 1(connection_life_time = 60), there is no real
>>> benefit I
>>> >> >>>> see. I assumed the connections(DISCARD ALL) present in database
>>> will
>>> >> be
>>> >> >>>> reused but each time I connected to the database, it created a new
>>> >> >>>> connection as seen below:
>>> >> >>>>
>>> >> >>>> pid | query | usename | client_addr | count |
>>> state
>>> >> >>>>
>>> >> -------+--------------+--------------+-----------------+-------+-------
>>> >> >>>> 12895 | | enterprisedb | 128.199.224.132 | 1 |
>>> idle
>>> >> >>>> 3420 | DISCARD ALL | enterprisedb | 128.199.224.132 | 1 |
>>> idle
>>> >> >>>> 12531 | DISCARD ALL | enterprisedb | 128.199.224.132 | 1 |
>>> idle
>>> >> >>>> 12636 | DISCARD ALL | enterprisedb | 128.199.224.132 | 1 |
>>> idle
>>> >> >>>> 12698 | DISCARD ALL | enterprisedb | 128.199.224.132 | 1 |
>>> idle
>>> >> >>>> 12751 | DISCARD ALL | enterprisedb | 128.199.224.132 | 1 |
>>> idle
>>> >> >>>> 12773 | DISCARD ALL | enterprisedb | 128.199.224.132 | 1 |
>>> idle
>>> >> >>>> 12862 | DISCARD ALL | enterprisedb | 128.199.224.132 | 1 |
>>> idle
>>> >> >>>> 12878 | DISCARD ALL | enterprisedb | 128.199.224.132 | 1 |
>>> idle
>>> >> >>>> (9 rows)
>>> >> >>>>
>>> >> >>>>
>>> >> >>>> Thanks and Regards,
>>> >> >>>> Nikhil
>>> >> >>>>
>>> >> >>>>
>>> >> >>>>
>>> >> >>>>
>>> >> >>>>
>>> >> >>>> On Sat, Aug 1, 2020 at 6:45 PM Tatsuo Ishii <ishii at sraoss.co.jp>
>>> >> wrote:
>>> >> >>>>
>>> >> >>>>> > Hi,
>>> >> >>>>> >
>>> >> >>>>> > Yes, we can see the pid
>>> >> >>>>> >
>>> >> >>>>> > show pool_pools;
>>> >> >>>>> > pool_pid | start_time | pool_id | backend_id |
>>> database |
>>> >> >>>>> > username | create_time | majorversion | minorversion
>>> |
>>> >> >>>>> > pool_counter | pool_backendpid | pool_connected
>>> >> >>>>> >
>>> >> >>>>> > 18190 | 2020-08-01 06:14:41 | 0 | 1 | edb
>>> |
>>> >> >>>>> > enterprisedb | 2020-08-01 06:19:52 | 3 | 0
>>> |
>>> >> 1
>>> >> >>>>> > | *29321* | 0
>>> >> >>>>> > 18193 | 2020-08-01 06:14:41 | 0 | 1 | edb
>>> |
>>> >> >>>>> > enterprisedb | 2020-08-01 06:21:26 | 3 | 0
>>> |
>>> >> 1
>>> >> >>>>> > | *29619 *| 0
>>> >> >>>>> >
>>> >> >>>>> >
>>> >> >>>>> > select pid,query,usename,state from pg_stat_activity where
>>> >> >>>>> > client_addr='128.199.224.132' group by usename,query,pid;
>>> >> >>>>> > pid | query | usename | state
>>> >> >>>>> > -------+--------------+--------------+-------
>>> >> >>>>> > *29321 *| DISCARD ALL | enterprisedb | idle
>>> >> >>>>> > *29619* | DISCARD ALL | enterprisedb | idle
>>> >> >>>>>
>>> >> >>>>> Assuming you executed "show pool_pools" long after 2020-08-01
>>> >> >>>>> 06:21:26, that is very strange because connection_life_time
>>> should
>>> >> >>>>> have been already expired. I wonder if pgpool tried to
>>> disconnect the
>>> >> >>>>> connection but failed. To check what actually happend, can you
>>> check
>>> >> >>>>> ps status of pgpool process 18190 and 18193?
>>> >> >>>>>
>>> >> >>>>> Also it would be nice you can examine the socket status of
>>> PostgreSQL
>>> >> >>>>> backend 29321 and 29619, and pgpool socket status of process
>>> 18190
>>> >> and
>>> >> >>>>> 18193?
>>> >> >>>>>
>>> >> >>>>> Best regards,
>>> >> >>>>> --
>>> >> >>>>> Tatsuo Ishii
>>> >> >>>>> SRA OSS, Inc. Japan
>>> >> >>>>> English: http://www.sraoss.co.jp/index_en.php
>>> >> >>>>> Japanese:http://www.sraoss.co.jp
>>> >> >>>>>
>>> >> >>>>
>>> >> > _______________________________________________
>>> >> > pgpool-general mailing list
>>> >> > pgpool-general at pgpool.net
>>> >> > http://www.pgpool.net/mailman/listinfo/pgpool-general
>>> >>
>>>
>>
More information about the pgpool-general
mailing list