Re: PGAgent Connection Pool Leaking

Neel, can you assist with this please?

On Thu, Oct 19, 2017 at 9:51 AM, Rob Emery <re-pgsql@codeweavers.net> wrote:

Hiya,

We run postgresql-9.5 (9.5.5-1.pgdg80+1) on debian jessie (using the postgres apt repo) with replication between two servers. We have pgagent running on both the master and the slave using:
/usr/bin/pgagent -f host=pgserver dbname=postgres user=username password=password -l 2 -s /home/robertemery/test/pgagent.log

where pgserver is a CNAME that we use to direct traffic to the current master.

We are finding that over-time, the pgagent user ends up with hundreds of connections into the postgresql cluster from both pgagents. If we kill and restart the pgagent process, it returns to 1.

When we run a job the number of connections goes from 1 -> 3 then back to 1 again; however this morning (for example) one of the servers has ended up with 2 connections for the pgagent user:

SELECT * FROM pg_stat_activity WHERE usename  LIKE '%pgagent%'; looks like :

12379;"postgres";14853;22872466;"pgagent_login_role";"";"192.168.1.1";"";58223;"2017-10-18 08:20:29.481096+01";"";"2017-10-19 09:16:25.656794+01";"2017-10-19 09:16:25.657219+01";f;"idle";;;"SELECT J.jobid   FROM pgagent.pga_job J  WHERE jobenabled    AND jobagentid IS NULL    AND jobnextrun <= now()    AND (jobhostagent = '' OR jobhostagent = 'pgsqla02') ORDER BY jobnextrun"
12379;"postgres";10184;22872466;"pgagent_login_role";"";"192.168.1.2";"";34501;"2017-10-18 15:20:53.282212+01";"";"2017-10-19 09:16:29.061761+01";"2017-10-19 09:16:29.062225+01";f;"idle";;;"SELECT J.jobid   FROM pgagent.pga_job J  WHERE jobenabled    AND jobagentid IS NULL    AND jobnextrun <= now()    AND (jobhostagent = '' OR jobhostagent = 'pgsqla01') ORDER BY jobnextrun"
12379;"postgres";13060;22872466;"pgagent_login_role";"";"192.168.1.2";"";34518;"2017-10-19 07:20:02.680711+01";"";"2017-10-19 07:20:02.70995+01";"2017-10-19 07:20:02.723907+01";f;"idle";;;"UPDATE pgagent.pga_job SET jobagentid=10184, joblastrun=now()  WHERE jobagentid IS NULL AND jobid=2"

It looks like the UPDATE statement is the new connection that's leaking.

Looking at the pgagent log for 07:20 (we have a job that runs at 07:10, 07:20, 07:30, 07:40) I can see:

Thu Oct 19 07:19:57 2017 : DEBUG: Clearing inactive connections
Thu Oct 19 07:19:57 2017 : DEBUG: Connection stats: total - 1, free - 0, deleted - 0
Thu Oct 19 07:19:57 2017 : DEBUG: Checking for jobs to run
Thu Oct 19 07:19:57 2017 : DEBUG: Sleeping...
Thu Oct 19 07:20:02 2017 : DEBUG: Clearing inactive connections
Thu Oct 19 07:20:02 2017 : DEBUG: Connection stats: total - 1, free - 0, deleted - 0
Thu Oct 19 07:20:02 2017 : DEBUG: Checking for jobs to run
Thu Oct 19 07:20:02 2017 : DEBUG: Creating job thread for job 2
Thu Oct 19 07:20:02 2017 : DEBUG: Creating DB connection: user=pgagent_login_role host=pgserver password=password dbname=postgres
Thu Oct 19 07:20:02 2017 : DEBUG: Allocating new connection to database postgres
Thu Oct 19 07:20:02 2017 : DEBUG: Starting job: 2
Thu Oct 19 07:20:02 2017 : DEBUG: Destroying job thread for job 2
Thu Oct 19 07:20:02 2017 : DEBUG: Sleeping...
Thu Oct 19 07:20:07 2017 : DEBUG: Clearing inactive connections
Thu Oct 19 07:20:07 2017 : DEBUG: Connection stats: total - 2, free - 0, deleted - 0
Thu Oct 19 07:20:07 2017 : DEBUG: Checking for jobs to run
Thu Oct 19 07:20:07 2017 : DEBUG: Sleeping...

which looks like it allocates a connection but never gives it up again. From this point on DEBUG: Connection stats: total - 2, free - 0, deleted - 0 always shows 2.

Looking at the run at 07:10 it looks different:

Thu Oct 19 07:09:55 2017 : DEBUG: Clearing inactive connections
Thu Oct 19 07:09:55 2017 : DEBUG: Connection stats: total - 1, free - 0, deleted - 0
Thu Oct 19 07:09:55 2017 : DEBUG: Checking for jobs to run
Thu Oct 19 07:09:55 2017 : DEBUG: Sleeping...
Thu Oct 19 07:10:00 2017 : DEBUG: Clearing inactive connections
Thu Oct 19 07:10:00 2017 : DEBUG: Connection stats: total - 1, free - 0, deleted - 0
Thu Oct 19 07:10:00 2017 : DEBUG: Checking for jobs to run
Thu Oct 19 07:10:00 2017 : DEBUG: Creating job thread for job 2
Thu Oct 19 07:10:01 2017 : DEBUG: Creating DB connection: user=pgagent_login_role host=pgserver password=password dbname=postgres
Thu Oct 19 07:10:01 2017 : DEBUG: Allocating new connection to database postgres
Thu Oct 19 07:10:01 2017 : DEBUG: Starting job: 2
Thu Oct 19 07:10:01 2017 : DEBUG: Sleeping...
Thu Oct 19 07:10:01 2017 : DEBUG: Creating DB connection: user=pgagent_login_role host=pgserver password=password dbname=postgres dbname=ourdatabasename
Thu Oct 19 07:10:01 2017 : DEBUG: Allocating new connection to database ourdatabasename
Thu Oct 19 07:10:01 2017 : DEBUG: Executing SQL step 3 (part of job 2)
Thu Oct 19 07:10:01 2017 : DEBUG: Returning connection to database ourdatabasename
Thu Oct 19 07:10:01 2017 : DEBUG: Returning connection to database postgres
Thu Oct 19 07:10:01 2017 : DEBUG: Completed job: 2
Thu Oct 19 07:10:01 2017 : DEBUG: Destroying job thread for job 2
Thu Oct 19 07:10:06 2017 : DEBUG: Checking for jobs to run
Thu Oct 19 07:10:06 2017 : DEBUG: Sleeping...

I'm at a bit of a loss to debug this further now, it looks like a bug in the connection pooling to me?

Many Thanks,

Rob

--

Robert Emery

Codeweavers 

October

 Newsletter  l  Auto Trader extends partnership with Codeweavers 

What are Codeweavers doing to gear up for GDPR?

Phone: 0800 021 0888   Email: contactus@codeweavers.net
Codeweavers Ltd | Barn 4 | Dunston Business Village | Dunston | ST18 9AB
Registered in England and Wales No. 04092394 | VAT registration no. 974 9705 63 

     

--

Dave Page
Blog: http://pgsnake.blogspot.com
Twitter: @pgsnake

EnterpriseDB UK: http://www.enterprisedb.com
The Enterprise PostgreSQL Company