Re: PGAgent Connection Pool Leaking

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.enterprisedb.com>

*http://www.linkedin.com/in/asheshvashi*
<http://www.linkedin.com/in/asheshvashi>

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

> Sure. Dave. I will work on this.
>
> Thanks,
> Neel Patel
>
> On Thu, Oct 19, 2017 at 2:25 PM, Dave Page <dpage(at)pgadmin(dot)org> wrote:
>
>> Neel, can you assist with this please?
>>
>> On Thu, Oct 19, 2017 at 9:51 AM, Rob Emery <re-pgsql(at)codeweavers(dot)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
>>>
>>>
>>> <https://codeweavers.net>
>>>
>>>
>>> <http://us15.campaign-archive1.com/?u=fcb361cfa194cf70551bc5169&id=f556b0bf09>
>>> Codeweavers
>>> October
>>> Newsletter
>>> <http://us15.campaign-archive1.com/?u=fcb361cfa194cf70551bc5169&id=f556b0bf09>
>>> *l *Auto Trader extends partnership with Codeweavers
>>> <https://codeweavers.net/company-blog/auto-trader-extends-partnership-with-codeweavers-to-power-finance-on-auto-trader-websites>
>>>
>>>
>>> <https://codeweavers.net/automotive-vision-conference-agenda>
>>>
>>> *What are Codeweavers doing to gear up for GDPR?
>>> <https://codeweavers.net/company-blog/what-are-codeweavers-doing-to-gear-up-for-gdpr>*
>>>
>>>
>>>
>>> *Phone:* 0800 021 0888 * Email: *contactus(at)codeweavers(dot)net
>>> *Codeweavers Ltd* | Barn 4 | Dunston Business Village | Dunston | ST18
>>> 9AB
>>> Registered in England and Wales No. 04092394 | VAT registration no. 974
>>> 9705 63
>>>
>>> <https://www.linkedin.com/company/codeweavers-limited>
>>> <https://vimeo.com/codeweaversltd> [image:
>>> https://plus.google.com/b/105942302039373248738/+CodeweaversNet]
>>> <https://plus.google.com/b/105942302039373248738/+CodeweaversNet> [image:
>>> https://twitter.com/CodeweaversTeam]
>>> <https://twitter.com/CodeweaversTeam>
>>>
>>
>>
>>
>> --
>> Dave Page
>> Blog: http://pgsnake.blogspot.com
>> Twitter: @pgsnake
>>
>> EnterpriseDB UK: http://www.enterprisedb.com
>> The Enterprise PostgreSQL Company
>>
>
>