Database connections not being closed

[ghost]

After upgrading to 6.2.16-1.20170331, we are now getting a significant number of idle sessions on the sympa database. If I don't close them by killing the backends we run out of available connections and that then impacts other services.

The last query executed in most of the sessions would appear to be
SELECT bounce_subscriber AS "bounce", bounce_address_subscriber AS "bounce_address", bounce_score_subscriber AS "bounc
e_score", custom_attribute_subscriber AS "custom_attribute", date_part('epoch',date_subscriber) AS "date", user_subscri
ber AS "email", suspend_end_date_subscriber AS "enddate", comment_subscriber AS "gecos", include_sources_subscriber AS
"id", included_subscriber AS "included", number_messages_subscriber AS "number_messages", reception_subscriber AS "rece
ption", suspend_start_date_subscriber AS "startdate", subscribed_subscriber AS "subscribed", suspend_subscriber AS "sus
pend", topics_subscriber AS "topics", date_part('epoch',update_subscriber) AS "update_date", visibility_subscriber AS "
visibility"+
FROM subscriber_table

[racke]

@Godzone, which SQL database are you using?. Also please post the query as code, so I can copy it from here easily.

[ghost]

Sorry, I cut and pasted from pg_stat_activity.
DB is PostgreSQL 9.5.6 on x86_64-redhat-linux-gnu

[ghost]

SELECT bounce_subscriber AS "bounce", bounce_address_subscriber AS "bounce_address", bounce_score_subscriber AS "bounce_score", custom_attribute_subscriber AS "custom_attribute", date_part('epoch',date_subscriber) AS "date", user_subscriber AS "email", suspend_end_date_subscriber AS "enddate", comment_subscriber AS "gecos", include_sources_subscriber AS "id", included_subscriber AS "included", number_messages_subscriber AS "number_messages", reception_subscriber AS "reception", suspend_start_date_subscriber AS "startdate", subscribed_subscriber AS "subscribed" suspend_subscriber AS "suspend", topics_subscriber AS "topics", date_part('epoch',update_subscriber) AS "update_date", visibility_subscriber AS "visibility" FROM subscriber_table WHERE list_subscriber = 'list-owners' AND robot_subscriber = 'godzone.net.nz' ORDER BY email

[ghost]

This isn't the only query but seems to be the last that most of the sessions executed.

[ghost]

Its late here so will leave this until tomorrow.

[ikedas]

@Godzone, can you try ---

• checking query_start columns repeatedly.
  For example, if values of the column stick to the same times, queries may keep running or waiting. Otherwise, if new time values appear one after another while number of queries do not decrease much, simply many queries are issued.
• checking log.
  If it is possible that queries are kept, please check Sympa log, pick the entries at the times queries started and show them us (encrypted passwords and parsonal e-mails would be masked).

And, I want to know what version of Sympa you have upgraded from.

[ghost]

checking query_start columns repeatedly. For example, if values of the column stick to the same times, queries may keep running or waiting. Otherwise, if new time values appear one after another while number of queries does not decrease much, simply many queries are issued. checking log. If it is possible that queries are kept, plaase check Sympa log, pick the entries at the times queries started and show them us (encrypted passwords and parsonal e-mails would be masked).

Have just started myEaster break so will do a more of the above in a day or two.

And, I want to know what version of Sympa you have upgraded from.

sympa.x86_64 6.2.16-1.20160920.svn12962.RHEL6

…

-- =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Glen Eustace, GodZone Internet Services, a division of AGRE Enterprises Ltd., P.O. Box 8020, Palmerston North, New Zealand 4446 Ph +64 6 357 8168, Mob +64 27 542 4015 “Specialising in providing low-cost professional Internet Services since 1997"

[ikedas]

Stagnant issue. Closed for the present.

[ghost]

It has been awhile since I last looked at this but the issue still exists so I thought I had better spend some more time on it. I am currently running sympa-6.2.22-1.20171002.RHEL6.x86_64 on CentOS 7 with postgresql-libs-9.2.23-1.el7_4.x86_64 on the front end against postgresql96-server-9.6.6-1PGDG.rhel7.x86_64 on the backend DB server. I have had a cron job that watches until the number of sympa connections reaches 100 then kills most of them. This has prevented the services dying and our DB server running out of available connections. With statement logging turned on, it seems that the process leakage always opens a connection and performs a single query Feb 17 12:52:08 agree-12 postgres[13527]: [26-1] sympa6/sympa [2001:df0:dc::251:25] LOG: execute dbdpg_p14861_10: SELECT bounce_subscriber AS "bounce", bounce_address_subscriber AS "bounce_address", bounce_score_subscriber AS "bounce_score", custom_attribute_subscriber AS "custom_attribute", date_part('epoch',date_subscriber) AS "date", user_subscriber AS "email", suspend_end_date_subscriber AS "enddate", comment_subscriber AS "gecos", include_sources_subscriber AS "id", included_subscriber AS "included", number_messages_subscriber AS "number_messages", reception_subscriber AS "reception", suspend_start_date_subscriber AS "startdate", subscribed_subscriber AS "subscribed", suspend_subscriber AS "suspend", topics_subscriber AS "topics", date_part('epoch',update_subscriber) AS "update_date", visibility_subscriber AS "visibility" Feb 17 12:52:08 agree-12 postgres[13527]: [26-2] #11 FROM subscriber_table Feb 17 12:52:08 agree-12 postgres[13527]: [26-3] #11 WHERE list_subscriber = 'list-owners' AND robot_subscriber = 'godzone.net.nz' ORDER BY email Feb 17 12:52:08 agree-12 postgres[13527]: [27-1] sympa6/sympa [2001:df0:dc::251:25] LOG: statement: DEALLOCATE dbdpg_p14861_10 In some case, that same connection is later re-used but in others it doesn’t and a new connection gets opened without closing the existing one. SO I am guessing that whatever is returned somehow effects the logic in the calling SYMPA process. 1396 ? Ss 0:00 postgres: sympa sympa6 2001:df0:dc::251:25(51598) idle 2837 ? Ss 0:00 postgres: sympa sympa6 2001:df0:dc::251:25(51672) idle 13201 ? Ss 0:00 postgres: sympa sympa6 2001:df0:dc::251:25(50488) idle 13527 ? Ss 0:00 postgres: sympa sympa6 2001:df0:dc::251:25(50506) idle 14294 ? Ss 0:00 postgres: sympa sympa6 2001:df0:dc::251:25(50550) idle 18939 ? Ss 0:00 postgres: sympa sympa6 2001:df0:dc::251:25(50772) idle 22473 ? Ss 0:00 postgres: sympa sympa6 2001:df0:dc::251:25(50960) idle 22482 ? Ss 0:00 postgres: sympa sympa6 2001:df0:dc::251:25(50962) idle 24264 ? Ss 0:00 postgres: sympa sympa6 2001:df0:dc::251:25(51050) idle 29663 ? Ss 0:00 postgres: sympa sympa6 2001:df0:dc::251:25(51314) idle 32443 ? Ss 0:00 postgres: sympa sympa6 2001:df0:dc::251:25(51538) idle I am not sure how to go about tracking this down or even which of the sympa processes is doing the work, I think it is task_manager but I am only guessing -- =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Glen Eustace, GodZone Internet Services, a division of AGRE Enterprises Ltd., P.O. Box 8020, Palmerston North, New Zealand 4446 Ph +64 6 357 8168, Mob +64 27 542 4015 “Specialising in providing low-cost professional Internet Services since 1997"

[ikedas]

@Godzone, can you find out what function (not SQL statement) Sympa was executing when PostgreSQL executed DEALLOCATE? If possible, please show the log of Sympa around that time.