Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Plug connection leaks found during profiling #582

Merged
merged 8 commits into from Mar 30, 2021

Conversation

gkokolatos
Copy link
Collaborator

It seems that pgsql_execute_with_params() during its lifetime has been
inconsistently altered. The latest version notes in the comments that the
connection is not persistant to facilitate error handling. However that was not
entirely true and several parts of the code assumed it to not be true. Others
assumed to be true and failed to release the connection once used.

For the sake of clarity, the function will now explicitly close the connection
that has used, regardless of wether it is a new or existing connection. That
simplifies most of the code and plugs the connection leaks.

It also unconvers an inconsistency on the connections used for notification. The
code mixed the connection it was using to listen to events from the monitor and
with others. A new PGconn member has been added in the monitor struct to
distinguish between the two distinct cases.

@DimCitus DimCitus self-requested a review February 5, 2021 10:29
@DimCitus DimCitus added the bug Something isn't working label Feb 5, 2021
@DimCitus
Copy link
Collaborator

DimCitus commented Feb 5, 2021

Hey Goergios,

You're making good points here, and the analysis is solid, but as you saw our goal has shifted and the code has not been maintained well enough to show our current intentions. Sorry about that.

It seems that pgsql_execute_with_params() during its lifetime has been
inconsistently altered. The latest version notes in the comments that the
connection is not persistant to facilitate error handling. However that was not
entirely true and several parts of the code assumed it to not be true. Others
assumed to be true and failed to release the connection once used.

If you run pg_autoctl in DEBUG mode (using -vv for very verbose) you will see connections and disconnections made in the log messages. The idea is that we should refrains from series of connect, disconnect, connect, disconnect, connect, disconnect within the same work unit. That's not the best way to use Postgres, we should be smart enough to re-use a connection and manage the client-side libpq clean-up that is necessary.

For the sake of clarity, the function will now explicitly close the connection
that has used, regardless of wether it is a new or existing connection. That
simplifies most of the code and plugs the connection leaks.

We started from that much simpler implementation yes, and then made it more complex to be able to re-use a previously established connection.

It also unconvers an inconsistency on the connections used for notification. The
code mixed the connection it was using to listen to events from the monitor and
with others. A new PGconn member has been added in the monitor struct to
distinguish between the two distinct cases.

What's wrong with running queries in the same connection when you LISTEN for changes?

@gkokolatos
Copy link
Collaborator Author

gkokolatos commented Feb 5, 2021 via email

@DimCitus DimCitus requested a review from JelteF February 5, 2021 12:09
@DimCitus
Copy link
Collaborator

DimCitus commented Feb 5, 2021

Absolutely. You should not leak memory though. My rough read is that in order to achieve that, a small redesign of the interface will be needed. IMHO, it might make sense to prevent the memleaks while the redesign is taking place which can end up being a while. Again, only an opinion :)

Okay, between your message and a chat with @JelteF I am now convinced that we should 1. plug the leak and 2. find a principled way to be smart about re-using connections when that's better.

Nothing, providing you are not leaking. If you try to plug the leaks with the current interface, you will stop listening to events in parts of the code where it is not desired to stop listening to events. Or that has been my understanding.

Yeah that's a good point too.

DimCitus
DimCitus previously approved these changes Feb 5, 2021
Copy link
Collaborator

@DimCitus DimCitus left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please rebase to current master and let's see about the CI before merging!

@DimCitus DimCitus added this to the Sprint 2021 W4 W5 milestone Feb 5, 2021
@DimCitus DimCitus dismissed their stale review February 5, 2021 14:50

Thinking more about it, I think this breaks some of our retry loops, such as the one in keeper_register_and_init in https://github.com/citusdata/pg_auto_failover/blob/master/src/bin/pg_autoctl/keeper.c#L1231

@@ -546,6 +546,7 @@ wait_until_primary_is_ready(Keeper *keeper,
KeeperStateData *keeperState = &(keeper->state);
int timeoutMs = PG_AUTOCTL_KEEPER_SLEEP_TIME * 1000;

(void) pgsql_listen(&(monitor->notificationClient), &((char *){ 0 }));
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We need at least a comment that explains why it's okay to send an empty list of channels here, and then I would rather avoid this advanced notation and just use a const char *channels[] = { 0 }; variable.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, that's clearly a hack. I only added it as a quick way to open a connection as there was no proper interface available.
Instead of hacking pgsql_listen(), how about exposing a lower level interface like pgsql_open_connection()?

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah we don't want to expose the lower-level interface. The whole point is that ensuring libpq-level clean-up and “lifetime management” is pretty hard, so we want to have that all sit in the same place and remain kind of opaque to the higher levels.

Also I'm not sure why we now have an explicit call to pgsql_listen that we didn't have before. Maybe that's where the new API could happen?

* Finally make establish a connection for notifications in case it had
* closed before
*/
(void) pgsql_listen(&(keeper->monitor.notificationClient), &((char *){ 0 }));
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same as before, I'm not happy with this notation, let's make it a whole lot more explicit please?

Copy link
Collaborator

@DimCitus DimCitus left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I took time to review the changes and the incompatibility with our manual transaction handling that we do in places. Do you want to update the PR?

Comment on lines 904 to 905
PQfinish(pgsql->connection);
pgsql->connection = NULL;
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In a couple places in the code we are handling transactions to sync local state file creation with transaction commit on the monitor. When the local activity fails, we ROLLBACK the transaction on the monitor. I think we need to track if an explicit transaction is being used in our PGSQL object and provide pgsql_begin, pgsql_commit, and pgsql_rollback functions, and then have the PGfinish call in pgsql_execute_with_params depend on whether an explicit transaction is in flight or not.

@gkokolatos
Copy link
Collaborator Author

gkokolatos commented Mar 15, 2021 via email

@DimCitus
Copy link
Collaborator

Yeah, it seems that the naive, 'use once' approach will not cut it if a transaction has to be open. Let me try some more targeted valgrind runs and see if I can catch the actual offender(s) before attempting a re-write of the API.

In case that's needed, I think most call sites would remain exactly the same as today. Only those where we issue manual BEGIN/ROLLBACK/COMMIT instructions would have to change. That's not too many, I think I can only find one...

@gkokolatos
Copy link
Collaborator Author

gkokolatos commented Mar 19, 2021 via email

@gkokolatos
Copy link
Collaborator Author

gkokolatos commented Mar 24, 2021

@DimCitus Now that was a bit embarrassing. I had previously pushed only the rebase and not the changes.

Please find a fresh push with a new rebase and the requested changes.

Valgrind is still happy and the tests do pass locally. Let us wait for the CI to conclude.

@DimCitus
Copy link
Collaborator

DimCitus commented Mar 24, 2021

@DimCitus Now that was a bit embarrassing. I had previously pushed only the rebase and not the changes.
Please find a fresh push with a new rebase and the requested changes.

Thanks @gkokolatos ! Your approach/API looks better than my own attempt yesterday. I think it'd be good to rename and improve the emptyChannels to char *emptyChannelsList = { NULL }; but that's a minor issue.

Valgrind is still happy and the tests do pass locally. Let us wait for the CI to conclude.

Some of the failures I see seem related to a merge error, typically:

======================================================================
FAIL: test_extension_update.test_001_update_extension
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/opt/python/3.7.6/lib/python3.7/site-packages/nose/case.py", line 198, in runTest
    self.test(*self.arg)
  File "/home/travis/build/citusdata/pg_auto_failover/tests/test_extension_update.py", line 41, in test_001_update_extension
    eq_(results, [("dummy",)])
AssertionError: [('1.5.0.2',)] != [('dummy',)]

----------------------------------------------------------------------
Ran 34 tests in 74.179s

And then you need to run make indent again apparently.

And another one is the Travis infamous one, where your PR is running some processes in DEBUG mode:

The job exceeded the maximum log length, and has been terminated.

@gkokolatos
Copy link
Collaborator Author

gkokolatos commented Mar 24, 2021 via email

@gkokolatos
Copy link
Collaborator Author

gkokolatos commented Mar 24, 2021 via email

Copy link
Collaborator

@DimCitus DimCitus left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I did another round of review, focusing on some details that seem to require more attention.

Comment on lines 550 to 552
char *emptyChannelList[] = { NULL };

(void) pgsql_listen(&(monitor->notificationClient), emptyChannelList);
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

By the way, how does it work now? We are listening to no channel at all, how do we expect to get a notification that some state change happened in our formation and group, or even for our own node?

Comment on lines +852 to +854
pgsql->connectionStatementType = PGSQL_CONNECTION_MULTI_STATEMENT;
connection = pgsql_open_connection(pgsql);
if (connection == NULL)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could we check for "transaction already in progress" errors and report it as a BUG, possibly forcing an exit?

Comment on lines 291 to 292
monitor->notificationClient.connectionStatementType ==
PGSQL_CONNECTION_SINGLE_STATEMENT)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's always false, so that we never close the connection, right?

Comment on lines 810 to 812
/* Finally establish a connection for notifications if none present */
(void) pgsql_listen(&(keeper->monitor.notificationClient), emptyChannelList);

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I believe we don't need that here, the monitor_wait_for_state_change in the beginning of the main loop reconnects if needed. We have a now spurious "Lost connection" warning that we should probably get rid of in monitor_wait_for_state_change that said, I believe it's now expected to have to establish a connection every once in a while from that point.

@gkokolatos
Copy link
Collaborator Author

gkokolatos commented Mar 24, 2021 via email

@gkokolatos
Copy link
Collaborator Author

gkokolatos commented Mar 24, 2021 via email

@DimCitus
Copy link
Collaborator

I think this PR needs to be rebased/merged on-top on current master's branch again. Recent changes in the release numbers (expected files for the monitor extension should mention extension version 1.5 now) and the Pyroute2 integration in the test framework are the main changes.

Georgios Kokolatos added 6 commits March 30, 2021 09:32
It seems that pgsql_execute_with_params() during its lifetime has been
inconsistently altered. The latest version notes in the comments that the
connection is not persistant to facilitate error handling. However that was not
entirely true and several parts of the code assumed it to not be true. Others
assumed to be true and failed to release the connection once used.

For the sake of clarity, the function will now explicitly close the connection
that has used, regardless of wether it is a new or existing connection. That
simplifies most of the code and plugs the connection leaks.

It also unconvers an inconsistency on the connections used for notification. The
code mixed the connection it was using to listen to events from the monitor and
with others. A new PGconn member has been added in the monitor struct to
distinguish between the two distinct cases.
 * Remove confusing pgsql_listen calls in favour of a new user friendly call
 * Use the same tight conn loop around monitor_wait_for_state_change everywhere
 * Correctly close the connections after it.
@gkokolatos
Copy link
Collaborator Author

gkokolatos commented Mar 30, 2021 via email

@DimCitus
Copy link
Collaborator

DimCitus commented Mar 30, 2021

Thanks! I'm not sure why we still have the following error:

======================================================================
FAIL: test_extension_update.test_001_update_extension
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/opt/python/3.7.6/lib/python3.7/site-packages/nose/case.py", line 198, in runTest
    self.test(*self.arg)
  File "/home/travis/build/citusdata/pg_auto_failover/tests/test_extension_update.py", line 41, in test_001_update_extension
    eq_(results, [("dummy",)])
AssertionError: [('1.5',)] != [('dummy',)]

----------------------------------------------------------------------

Can you reproduce it locally and get more logs maybe? Will have a look later, is it possible that the changes in this PR are somehow preventing the automated ALTER EXTENSION UPDATE mechanics at startup of the pg_autoctl of the monitor?

To repro, with a docker environment available, simply do:

make TEST=test_extension_update run-test

@gkokolatos
Copy link
Collaborator Author

gkokolatos commented Mar 30, 2021 via email

Addresses CI failure of test_extension_update case.
@gkokolatos
Copy link
Collaborator Author

The latest commit seems to address the test_extension_update.test_001_update_extension failure.

There seems to be one more failure as per https://travis-ci.com/github/citusdata/pg_auto_failover/jobs/494941418
which is to be indent related. Apologies for the chatter.

@DimCitus
Copy link
Collaborator

It seems Travis is confused, can you push a meaningless commit to trigger another build?

@DimCitus DimCitus merged commit 8351581 into hapostgres:master Mar 30, 2021
@DimCitus
Copy link
Collaborator

Merged! Thanks for your contribution!

@gkokolatos
Copy link
Collaborator Author

gkokolatos commented Mar 31, 2021 via email

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants