Thread: PGAgent Connection Pool Leaking

PGAgent Connection Pool Leaking

From

Rob Emery

Date:

19 October 2017, 11:51:05

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?

Re: PGAgent Connection Pool Leaking

From

Dave Page

Date:

19 October 2017, 11:55:48

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

Re: PGAgent Connection Pool Leaking

From

Neel Patel

Date:

23 October 2017, 08:26:36

Sure. Dave. I will work on this.

Thanks,

Neel Patel

On Thu, Oct 19, 2017 at 2:25 PM, Dave Page <dpage@pgadmin.org> wrote:

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

Re: PGAgent Connection Pool Leaking

From

Ashesh Vashi

Date:

23 October 2017, 08:38:48

Hi Dave,

Rob has already sent a patch on a separate thread.

I have reviewed it, and sent a updated patch on that thread.

Neel - please take a look at it.

Thanks & Regards,

Ashesh Vashi
EnterpriseDB INDIA: Enterprise PostgreSQL Company

http://www.linkedin.com/in/asheshvashi

On Mon, Oct 23, 2017 at 10:56 AM, Neel Patel <neel.patel@enterprisedb.com> wrote:

Sure. Dave. I will work on this.

Thanks,
Neel Patel

On Thu, Oct 19, 2017 at 2:25 PM, Dave Page <dpage@pgadmin.org> wrote:
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