Test with pgbench and debug issues

[mostafa]

PgBench log

PGPASSWORD=postgres pgbench -i -h localhost -p 15432 -U postgres -d postgres
dropping old tables...
creating tables...
generating data (client-side)...
100000 of 100000 tuples (100%) done (elapsed 0.02 s, remaining 0.00 s) # PgBench got stuck here
# Tried to cancel the request:
^CCancel request sent
# After killing GatewayD:
server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
pgbench: error: PQendcopy failed

PostgreSQL log

# After killing pgbench using Ctrl+C
2023-09-29 01:01:02.840 CEST [65972] [unknown]@[unknown] LOG:  PID 65987 in cancel request did not match any process
# After killing GatewayD using Ctrl+C
2023-09-29 01:01:08.627 CEST [65987] postgres@postgres LOG:  incomplete message from client
2023-09-29 01:01:08.627 CEST [65987] postgres@postgres CONTEXT:  COPY pgbench_accounts, line 593
2023-09-29 01:01:08.627 CEST [65987] postgres@postgres STATEMENT:  copy pgbench_accounts from stdin with (freeze on)
2023-09-29 01:01:08.627 CEST [65987] postgres@postgres ERROR:  unexpected EOF on client connection with an open transaction
2023-09-29 01:01:08.627 CEST [65987] postgres@postgres CONTEXT:  COPY pgbench_accounts, line 593
2023-09-29 01:01:08.627 CEST [65987] postgres@postgres STATEMENT:  copy pgbench_accounts from stdin with (freeze on)
2023-09-29 01:01:08.632 CEST [65987] postgres@postgres FATAL:  terminating connection because protocol synchronization was lost
2023-09-29 01:01:08.632 CEST [65987] postgres@postgres LOG:  could not send data to client: Broken pipe

GatewayD log

# The moment that pgbench got stuck
2023-09-29T01:00:55+02:00 DBG Received data from client length=8192 local=0.0.0.0:15432 remote=127.0.0.1:37310
2023-09-29T01:00:55+02:00 DBG Sent data to database function=proxy.passthrough length=8192 local=127.0.0.1:58532 remote=127.0.0.1:5432
# After killing pgbench using Ctrl+C
2023-09-29T01:01:02+02:00 DBG GatewayD is opening a connection from=127.0.0.1:37320
2023-09-29T01:01:02+02:00 DBG Client has been assigned client=f4fcea0 function=proxy.connect server=127.0.0.1:37320
2023-09-29T01:01:02+02:00 DBG Available client connections count=48 function=proxy.connect
2023-09-29T01:01:02+02:00 DBG Busy client connections count=2 function=proxy.connect
2023-09-29T01:01:02+02:00 DBG Received data from client length=16 local=0.0.0.0:15432 remote=127.0.0.1:37320
2023-09-29T01:01:02+02:00 DBG Sent data to database function=proxy.passthrough length=16 local=127.0.0.1:58380 remote=127.0.0.1:5432
2023-09-29T01:01:02+02:00 DBG Received data from database function=proxy.passthrough length=0 local=127.0.0.1:58380 remote=127.0.0.1:5432
2023-09-29T01:01:02+02:00 DBG Client disconnected function=proxy.passthrough local=127.0.0.1:58380 remote=127.0.0.1:5432
2023-09-29T01:01:02+02:00 DBG No data to send to client function=proxy.passthrough local=127.0.0.1:42760 remote=127.0.0.1:5432
2023-09-29T01:01:02+02:00 DBG GatewayD is closing a connection from=127.0.0.1:37320
2023-09-29T01:01:02+02:00 DBG Available client connections count=49 function=proxy.disconnect
2023-09-29T01:01:02+02:00 DBG Busy client connections count=1 function=proxy.disconnect
^C2023-09-29T01:01:08+02:00 INF Notifying the plugins that the server is shutting down
2023-09-29T01:01:08+02:00 INF Stopping GatewayD
2023-09-29T01:01:08+02:00 INF Stopped health check scheduler
2023-09-29T01:01:08+02:00 INF Stopped metrics merger
2023-09-29T01:01:08+02:00 INF Stopped metrics server
2023-09-29T01:01:08+02:00 INF Stopping server name=default
2023-09-29T01:01:08+02:00 DBG All available connections have been closed
2023-09-29T01:01:08+02:00 DBG All busy connections have been closed
2023-09-29T01:01:08+02:00 DBG GatewayD is shutting down...
2023-09-29T01:01:08+02:00 DBG All available connections have been closed
2023-09-29T01:01:08+02:00 DBG All busy connections have been closed
2023-09-29T01:01:08+02:00 DBG Received data from database function=proxy.passthrough length=0 local= remote=
2023-09-29T01:01:08+02:00 DBG No data to send to client function=proxy.passthrough local= remote=
2023-09-29T01:01:08+02:00 DBG GatewayD is closing a connection from=127.0.0.1:37310
2023-09-29T01:01:09+02:00 INF Stopped all servers
2023-09-29T01:01:09+02:00 INF Stopped plugin registry

Related

• Handle bi-directional communication between server and client #32
• Fix bug in handling connection close #219
• Fix receive issue of the client connection #245

[mostafa]

The above issues are resolved and this is the results of testing GatewayD with pgbench. Based on the following results, the average latency was increased by 41.91 ms, which is consistent with my benchmarks with psql (#344). The initial connection time was increased by 02.29 ms, which is a great achievement, compared to something like Supavisor's benchmarks, considering that GatewayD only support 1:1 connection mapping for now. The transactions per second was decreased by 29.53% (112.63294 tps), which is somewhat proportional to the increase of average latency.

These tests were run on my development machine, which is a small laptop with 2 cores and 4 threads, so I don't expect much of it. I will run bigger tests on more powerful machines on AWS using k6 (#145, #188). k6 (and xk6-sql) tests are more reliable and various metrics are emitted, which can be further scraped and visualized by Prometheus and Grafana.

It is important to note that running pgbench in initialization mode (-i) exhausts GatewayD connections and hangs with no results, as was initially tested in this ticket (in the original description).

GatewayD

GATEWAYD_POOLS_DEFAULT_SIZE=50 ./gatewayd run            
2023-10-26T23:33:31+02:00 INF Starting plugin health check scheduler healthCheckPeriod=5s
2023-10-26T23:33:31+02:00 INF Metrics are exposed address=http://localhost:9090/metrics
2023-10-26T23:33:31+02:00 INF There are clients available in the pool count=50 name=default
2023-10-26T23:33:31+02:00 INF Started the client health check scheduler healthCheckPeriod=1m0s startDelay=2023-10-26T23:34:31+02:00
2023-10-26T23:33:31+02:00 INF GatewayD is listening address=0.0.0.0:15432
2023-10-26T23:33:31+02:00 INF Started the HTTP API address=localhost:18080
2023-10-26T23:33:31+02:00 INF Started the gRPC API address=localhost:19090 network=tcp
2023-10-26T23:33:31+02:00 INF GatewayD is running pid=80321
2023-10-26T23:33:36+02:00 ERR No more available connections
2023-10-26T23:33:36+02:00 ERR Failed to connect to the client error="pool is exhausted"

PgBench <=> PostgreSQL

PGPASSWORD=postgres pgbench -M extended --transactions 1 --jobs 1 --client 50 -h localhost -p 5432 -U postgres postgres
pgbench (15.4 (Debian 15.4-3))
starting vacuum...end.
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 1
query mode: extended
number of clients: 50
number of threads: 1
maximum number of tries: 1
number of transactions per client: 1
number of transactions actually processed: 50/50
number of failed transactions: 0 (0.000%)
latency average = 131.112 ms
initial connection time = 664.919 ms
tps = 381.353347 (without initial connection time)

PgBench <=> GatewayD <=> PostgreSQL

PGPASSWORD=postgres pgbench -M extended --transactions 1 --jobs 1 --client 50 -h localhost -p 15432 -U postgres postgres
pgbench (15.4 (Debian 15.4-3))
starting vacuum...end.
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 1
query mode: extended
number of clients: 50
number of threads: 1
maximum number of tries: 1
number of transactions per client: 1
number of transactions actually processed: 50/50
number of failed transactions: 0 (0.000%)
latency average = 186.067 ms
initial connection time = 680.196 ms
tps = 268.720407 (without initial connection time)