Home > mailing lists

PGAgent Connection Pool Leaking - Mailing list pgadmin-support

From	Rob Emery
Subject	PGAgent Connection Pool Leaking
Date	October 19, 2017 11:51:05
Msg-id	CAPCETpsVvZhgzSjterbJORXWVtf8brkG3tnS2REy9c=7e26_Kg@mail.gmail.com Whole thread Raw
Responses	Re: PGAgent Connection Pool Leaking
List	pgadmin-support

Tree view

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