Pgx: [q] custom cancellation func

[utrack]

Hi! I was migrating to pgx/v4 while I noticed that pgx.ConnConfig.CustomCancel hook is no more. How do I set up a custom cancel func with v4?
I'd like to disable cancellation signaling completely since it may kill wrong query when using pgBouncer.

[jackc]

CustomCancel was removed in v4 because v4 changed strategies for context cancellation from cancelling the in progress query and attempting to recover to just closing the connection. So there was no need for it. However, this led to the problem that the too long running queries were still running server side. Now we close the connection but also send a cancel request to the server.

I suppose we could add something similar back... But I find it surprising that PgBouncer works that way. I would expect that it would only forward the cancellation request to the PostgreSQL server if the client side connection that received the cancel request had a query in progress. Seems to guarantee an error to do so otherwise.

[utrack]

Aha! Didn't know that the strategy's changed, thanks.
I don't think there are any guards against running cancel on idle connections, but it won't save us from this race anyway: https://hsto.org/webt/us/xf/v_/usxfv_i0ze_axpmjtlir183reiu.png

Here, PIDs mean true PID in Postgres (belongs to a conn between pgBouncer and DB).

While pgx fires cancel and kills connections to pgBouncer, pgB reuses its connections to DB.
Cancel from a client will be mapped to a true PID inside pgB; then a cancel pkt will be sent to Postgres, but this PID might be used by another query by then.

[jackc]

That really surprises me that PgBouncer would forward cancellations in that manner. It seems that it would be impossible to use that functionality safely.

I would have expected PgBouncer to send its own PID and secret key to the client and when PgBouncer receives a cancel request it would map it to the underlying PG connection only if that PgBouncer connection was busy.

Anyway, as far as custom cancellation behavior, we are always going to close the connection, but I don't mind making the send cancellation request on close behavior customizable.

[nvorobev]

@jackc please return support for CustomCancel. Since in pgx4 there is no support for CustomCancel, therefore, pgx4 always sends cancel, and for pgBouncer it leads to filling the max_client_conn limit and, as a result, blocking new connections.

[eshkinkot]

Cancel from a client will be mapped to a true PID inside pgB

Yes, but it mapped by client->cancel_key:
https://github.com/pgbouncer/pgbouncer/blob/4ac6b897da791422362787959ffdf59ccc4835a3/src/objects.c#L1301

and this client->cancel_key is generated for each client, it is not server cancel_key:
https://github.com/pgbouncer/pgbouncer/blob/4ac6b897da791422362787959ffdf59ccc4835a3/src/proto.c#L228

but this PID might be used by another query by then

BTW, you have this race condition in clean postgres too, because, as you said above — cancel query is linked by PID, not by some "query id", so you does not known which query will be running in postgres backend when it will handle the cancellation.

[jackc]

and this client->cancel_key is generated for each client, it is not server cancel_key:

I would expect pgx to only see the client cancel key then -- and pgbouncer be smart enough not to send the cancel to the Postgres server unless that client was busy.

BTW, you have this race condition in clean postgres too, because, as you said above — cancel query is linked by PID, not by some "query id", so you does not known which query will be running in postgres backend when it will handle the cancellation.

This isn't a problem with regular pgx because any cancellation closes the connection. Sending the cancel signal to the server is merely a courtesy to prevent long running queries from continuing to consume server time.

---

Maybe I don't understand the whole situation, but I still find it difficult to comprehend that this PgBouncer behavior is intentional and not a bug somewhere.

I'm not opposed to adding an on cancel function -- though since connections are always closed on cancel the only thing it could really do is decide whether or not to send the cancel signal -- I'd prefer to solve the root problem rather than add an override to work around it.

[jackc]

I just spent several hours digging into this and am unable to reproduce this...

First, I wrote an example program that inspects that explicitly tries to create this problem.

https://github.com/jackc/pgx_issues/blob/8eb2ebfc8b41c96c4a642e4d078c293f69af320c/main.go

When run it creates two connections to a PgBouncer instance and displays the PID reported through the wire protocol and the PID reported by select pg_backend_pid(). This lets me see that PgBouncer is multiplexing them on the same underlying connection.

Then I start a long running query on one PgBouncer connection and cancel it on the other. PgBouncer correctly does not send the cancel to PostgreSQL.

jack@glados ~/dev/pgx_issues ±master⚡ » DATABASE_URL="host=127.0.0.1 port=6432 database=pgx_test user=pgx_md5 password=secret" go run main.go
2020/04/23 18:49:10 [busyConn]: protocolPID=841021419, sqlPID=63297, secretKey=491727008
2020/04/23 18:49:10 [cancelConn]: protocolPID=1124499268, sqlPID=63297, secretKey=4189145394
2020/04/23 18:49:10 [cancelConn]: waiting for other conn to run query...
2020/04/23 18:49:10 [busyConn] executing: select pg_sleep(10)
2020/04/23 18:49:12 [cancelConn]: sending CancelRequest
2020/04/23 18:49:12 [cancelConn]: CancelRequest err: <nil>
2020/04/23 18:49:21 [busyConn] was not interrupted

But maybe somehow this only happens under high concurrency or when using context cancellation rather than explicitly invoking CancelRequest().

So I wrote another test https://github.com/jackc/pgx_issues/blob/976053da4b9972d6a6e5fed1fc7b7a8562b3e913/main.go

This is a stress test that starts many workers each of which randomly executes queries, some of which are cancelled and some of which are not. It checks that no queries that are unexpectedly cancelled -- and they're not.

jack@glados ~/dev/pgx_issues ±master » DATABASE_URL="host=127.0.0.1 port=6432 database=pgx_test user=pgx_md5 password=secret" CONN_COUNT=30 QUERIES_PER_CONN=1000 go run main.go
2020/04/23 19:34:10 connCount: 30, queriesPerConn: 1000
2020/04/23 19:35:48 No cancel errors detected.

At this point I do not see a bug in PgBouncer or in pgx. I'm going to need a test case that reproduces this problem before investing any more time in this.

[Timosha]

@jackc can you show your pgbouncer.ini configuration file in your test?

[jackc]

Here it is with the comments removed.

[databases]
pgx_test = host=127.0.0.1 dbname=pgx_test

[pgbouncer]
logfile = /usr/local/var/log/pgbouncer.log
pidfile = /usr/local/var/run/pgbouncer.pid
listen_addr = 127.0.0.1
listen_port = 6432
auth_type = trust
auth_file = /usr/local/etc/pgbouncer_userlist.txt
pool_mode = statement
server_reset_query = DISCARD ALL
max_client_conn = 100
default_pool_size = 20

[iosadchiy]

Hi! I tried to look a bit deeper into the issue. I guess you're right, it's not possible to cancel someone's else query:

1. pgbouncer generates a unique cancel_key for each client connection, which is different from server connections' cancel_keys
2. pgbouncer will only cancel a request if the client's connection is still linked to the server one
3. pgconn closes connection immediately after sending the cancellation request, so no more requests will be sent to this connection

But the problem is still there. Here's what I see in pgbouncer when load testing one of our services which uses pgx/v4/pgxpool:

blue lines - cl_active, red dots - cl_waiting (right scale)

The pool is limited to 10 both on service and on DB. Maximum allowed client connections to pgbouncer - 100. As you can see, there are too many cl_waiting connections (almost up to 60, expected 0).

I've put together a test case to demonstrate the issue: https://github.com/iosadchiy/pgx_pgbouncer_issue. It runs 100 workers sending queries that are always canceled, with pool size 10. If you run it, pgbouncer will show these metrics:

database | user | cl_active | cl_waiting | sv_active | sv_idle | sv_used | sv_tested | sv_login | maxwait | maxwait_us | pool_mode
-----------|-----------|-----------|------------|-----------|---------|---------|-----------|----------|---------|------------|-------------
pgbouncer | pgbouncer | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | statement
postgres | postgres | 2 | 97 | 0 | 0 | 0 | 0 | 1 | 0 | 748640 | transaction

As you can see, there are too little cl_active and too many cl_waiting connections (expected 10 and 0 correspondingly).

As far as I understand the problem lies in pgxpool - pgconn interaction:

• pgxpool knows nothing about query cancellation, it can only control the total number of PgConn objects
• when a PgConn object needs to close its connection, it creates a new one to cancel the query running on it
• at the same moment, pgxpool creates a new PgConn object (and a new connection) because it thinks there is some space in the pool

Thus, in the situation when a lot of requests are being canceled by timeout (that is, under heavy load) pgx creates way more connections than maximum pool size allows and fills pgbouncer's pool with cancellation queries. Service's performance degrades dramatically due to the lack of cl_active connections.

One possible solution could be just not to use query cancellation when working with pgbouncer. That is, to get CustomCancel back. It works pretty well for us with pgx v3.

Another solution could be to allow pgxpool to control the query cancellation process and to know the total number of connections including cancellation requests.

As of now, we're kind of blocked by this problem in the long run - we cannot migrate to pgx/v4 until there is a good workaround.

Hope this was useful. Let me know what you think!

[jackc]

I was able to duplicate the problem using your example.

But I don't think the cancel query that occurs when closing the connection is the problem. I experimented with removing it. It still exhibited catastrophic behavior very rapidly.

I think the root problem is that closing a connection is handled asynchronously. As far as pgxpool is concerned the connection is immediately closed, but it actually the connection lives for a little while. But there is now room in the pool so it establishes another connection. I think removing the query cancellation could even make it worse. The "closing" connections could live for much longer if they didn't actually close until their last query finished.

It's a bit of a tricky situation. When a query is cancelled the function must return immediately. It can't wait for the connection to close cleanly. That is why it is done in the background. But that causes an unfortunate side effect for the pool.

---

Okay. I think I have a solution. There were a few changes necessary.

1. In pgconn I added CleanupDone(). It returns a channel that is closed when the asynchronous close / cleanup is complete.
2. pgxpool now waits for CleanupDone in its connection destructor.
3. puddle now does not remove a resource from the pool until its destructor has completed.

With these changes cl_active + cl_waiting was never greater than 10.

[iosadchiy]

Works like a charm, at least for performance tests. Thank you!

[iosadchiy]

It turns out that while the issue is fixed for pgx/v4 + pgxpool, it still can be reproduced for pgx/v4 + database/sql.

Check out the test case: https://github.com/iosadchiy/pgx_pgbouncer_issue/tree/database-sql

If you let it run for 15-30 seconds, you will get something like this:

$ echo "show pools;" | psql -h localhost -p 6432 -U postgres pgbouncer

 database  |   user    | cl_active | cl_waiting | sv_active | sv_idle | sv_used | sv_tested | sv_login | maxwait | maxwait_us |  pool_mode
-----------+-----------+-----------+------------+-----------+---------+---------+-----------+----------+---------+------------+-------------
 pgbouncer | pgbouncer |         1 |          0 |         0 |       0 |       0 |         0 |        0 |       0 |          0 | statement
 postgres  | postgres  |         0 |        100 |         0 |       0 |       0 |         0 |        1 |       0 |     541061 | transaction
(2 rows)

Pool size is limited at 10, but there are 100 connections.

Simply closing the connection synchronously resolves the issue:

diff --git a/vendor/github.com/jackc/pgconn/pgconn.go b/vendor/github.com/jackc/pgconn/pgconn.go
index ff81206..304fbdf 100644
--- a/vendor/github.com/jackc/pgconn/pgconn.go
+++ b/vendor/github.com/jackc/pgconn/pgconn.go
@@ -564,7 +564,7 @@ func (pgConn *PgConn) asyncClose() {
        }
        pgConn.status = connStatusClosed

-       go func() {
+       func() {
                defer close(pgConn.cleanupDone)
                defer pgConn.conn.Close()

It works both with pgxpool and database/sql.

I'm not sure what the reasons are behind closing asynchronously. Could you please clarify or point to an explanation?

Do we really need to close the connection asynchronously? It seems that in case of pgxpool it is already being closed synchronously due to the waiting for CleanupDone(). And it works fine so far.
Maybe we can just drop it?

[jackc]

Do we really need to close the connection asynchronously?

Well, I guess it depends on how we define "need". IMO, there are two requirements for context cancellation.

1. Context cancellations should take effect immediately. It's not acceptable for the context passed to a Query to be canceled and the method to not immediately return.
2. We must signal the server that the query has been canceled. Otherwise an expensive query could consume resources on the server indefinitely.

These objectives are opposed to each other in that the second objective requires network activity which could take an arbitrary amount of time.

That is why the query cancellation and connection closing is asynchronous.

It seems that in case of pgxpool it is already being closed synchronously due to the waiting for CleanupDone().

The underlying resource pool implementation, puddle, calls the destructor which calls CleanupDone asynchronously. This lets the canceled code return immediately, but the pool doesn't remove the connection until cleanup is done.

The only obvious way to not close asynchronously would be to violate one of the two requirements above. There might be some workaround possible in stdlib, but I'm not sure what it would be.