Enormous performance regression by PR #482 when prepared_statements is set to true

[JelteF]

Describe the bug
I wanted to try out prepared statement support and measure its performance in pgcat (essentially reproducing the blog). But when running pgbench --select-only on the main branch I was only able to get ~50 TPS.

To Reproduce
Steps to reproduce the behavior:

1. git checkout main
2. Add prepared_statements = true to the minimal config
3. RUST_LOG=info cargo run --release -- pgcat.minimal.toml
4. pgbench --select-only -T 10 -P 1 -p 6433 --protocol prepared

Expected behavior
Get somewhere in the order of 2000-20000 TPS. But instead I get between 20-50TPS. The worst part is that this even happens when using --protocol simple. Only if you enable prepared_statements = true from the config, performance of --protocol simple returns to normal levels.

Screenshots
I narrowed the regression down commit: 4b78af9
With commit: 4b78af9

With commit right before: 73500c0

Desktop (please complete the following information):

• OS: Linux

Additional info
The reason I was testing pgcat its performance was because I wanted to compare PgBouncer its upcoming prepared statement support (pgbouncer/pgbouncer#845) to pgcat and Odyssey. But pgcat its perf was so much lower than expected that something obviously seemed wrong.

[levkk]

45 TPS is very suspect. Something is definitely wrong. I ran a benchmark on my end, and as is with all benchmarks, it had a different result:

lev@Levs-MBP postgresql % PGPASSWORD=sharding_user pgbench -h 127.0.0.1 -p 6432 --protocol prepared -S -t 100000 -U sharding_user sharded_db
pgbench (15.3 (Homebrew))
starting vacuum...end.
transaction type: <builtin: select only>
scaling factor: 1
query mode: prepared
number of clients: 1
number of threads: 1
maximum number of tries: 1
number of transactions per client: 100000
number of transactions actually processed: 100000/100000
number of failed transactions: 0 (0.000%)
latency average = 0.087 ms
initial connection time = 2.885 ms
tps = 11454.727481 (without initial connection time)

Latest main commit. Default config from main. Setup local DBs with psql -f tests/sharding/query_routing_setup.sql. Setup pgbench with PGPASSWORD=sharding_user pgbench -i shard0 -U sharding_user.

OS: Mac OS Ventura
Hardware: M1 Max
Build: cargo run --release
Postgres:

lev=# SELECT version();
                                                             version                                                             
---------------------------------------------------------------------------------------------------------------------------------
 PostgreSQL 15.3 (Homebrew) on aarch64-apple-darwin22.4.0, compiled by Apple clang version 14.0.3 (clang-1403.0.22.14.1), 64-bit
(1 row)

pgbench:

lev@Levs-MBP pgcat % pgbench --version
pgbench (PostgreSQL) 15.3 (Homebrew)

Happy to help debug further. Could you please:

• attach your pgcat config
• share your hardware specs
• run the same benchmark with prepared_statements = false to compare

Thanks!

P.S. Ran your benchmark as well:

PGPASSWORD=sharding_user pgbench --select-only -T 10 -P 1 -p 6432 --protocol prepared -U sharding_user -h 127.0.0.1 sharded_db 
pgbench (15.3 (Homebrew))
starting vacuum...end.
progress: 1.0 s, 10906.8 tps, lat 0.091 ms stddev 0.044, 0 failed
progress: 2.0 s, 11540.0 tps, lat 0.087 ms stddev 0.009, 0 failed
progress: 3.0 s, 11641.0 tps, lat 0.086 ms stddev 0.007, 0 failed
progress: 4.0 s, 11675.0 tps, lat 0.086 ms stddev 0.007, 0 failed
progress: 5.0 s, 11650.8 tps, lat 0.086 ms stddev 0.007, 0 failed
progress: 6.0 s, 11613.3 tps, lat 0.086 ms stddev 0.008, 0 failed
progress: 7.0 s, 11661.0 tps, lat 0.086 ms stddev 0.007, 0 failed
progress: 8.0 s, 11649.1 tps, lat 0.086 ms stddev 0.007, 0 failed
progress: 9.0 s, 11602.9 tps, lat 0.086 ms stddev 0.008, 0 failed

[JelteF]

More precise reproduction steps

I was trying with this slightly modified pgcat.minimal.toml file

[general]
host = "127.0.0.1"
port = 6433
admin_username = "pgcat"
admin_password = "pgcat"
prepared_statements = true

[pools.pgml.users.0]
username = "postgres"
password = "postgres"
pool_size = 10
min_pool_size = 1
pool_mode = "transaction"

[pools.pgml.shards.0]
servers = [
  ["127.0.0.1", 5432, "primary"]
]
database = "postgres"

Command to run pgcat:

RUST_LOG=info cargo run --release -- pgcat.minimal.toml

This command then results in ~45TPS

PGDATABASE=pgml PGUSER=postgres PGPASSWORD=postgres pgbench --select-only -T 10 -P 1 -p 6433 --protocol simple

If I remove the prepared_statements = true line and restart, then it gets TPS of multiple thousands.

Hardware: 16 core VM on Azure, and my own desktop. Ubuntu 20.04 and Ubuntu 22.04 respectively (desktop runs Ubuntu in WSL). CPU on both is some Intel 64bit. My desktop shows this with lscpu.

Details

Architecture:            x86_64
  CPU op-mode(s):        32-bit, 64-bit
  Address sizes:         46 bits physical, 48 bits virtual
  Byte Order:            Little Endian
CPU(s):                  20
  On-line CPU(s) list:   0-19
Vendor ID:               GenuineIntel
  Model name:            Intel(R) Core(TM) i9-10900X CPU @ 3.70GHz
    CPU family:          6
    Model:               85
    Thread(s) per core:  2
    Core(s) per socket:  10
    Socket(s):           1
    Stepping:            7
    BogoMIPS:            7391.99
    Flags:               fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ss ht syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon rep_good nopl xtopology tsc_reliable nonstop_tsc cpuid p
                         ni pclmulqdq vmx ssse3 fma cx16 pdcm pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand hypervisor lahf_lm abm 3dnowprefetch invpcid_single ssbd ibrs ibpb stibp ibrs_enhanced tpr_sha
                         dow vnmi ept vpid ept_ad fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid avx512f avx512dq rdseed adx smap clflushopt clwb avx512cd avx512bw avx512vl xsaveopt xsavec xgetbv1 xsaves avx512_vnni flush_l1d arch_cap
                         abilities
Virtualization features:
  Virtualization:        VT-x
  Hypervisor vendor:     Microsoft
  Virtualization type:   full
Caches (sum of all):
  L1d:                   320 KiB (10 instances)
  L1i:                   320 KiB (10 instances)
  L2:                    10 MiB (10 instances)
  L3:                    19.3 MiB (1 instance)
Vulnerabilities:
  Itlb multihit:         KVM: Mitigation: VMX disabled
  L1tf:                  Not affected
  Mds:                   Not affected
  Meltdown:              Not affected
  Mmio stale data:       Vulnerable: Clear CPU buffers attempted, no microcode; SMT Host state unknown
  Retbleed:              Mitigation; Enhanced IBRS
  Spec store bypass:     Mitigation; Speculative Store Bypass disabled via prctl and seccomp
  Spectre v1:            Mitigation; usercopy/swapgs barriers and __user pointer sanitization
  Spectre v2:            Mitigation; Enhanced IBRS, IBPB conditional, RSB filling, PBRSB-eIBRS SW sequence
  Srbds:                 Not affected
  Tsx async abort:       Mitigation; TSX disabled

[levkk]

Just to confirm one thing, are you pgbench and pgcat on the same machine or are you running pgbench on your machine and pgcat on a VM in Azure?

[JelteF]

Looking at the default config (that one is huge), it seems to be using session pooling for the sharding_user. Changing poolmode to session for my config indeed makes the issue go a away.

[levkk]

Oh hmm, that was my mistake. Let me test with transaction mode.

[levkk]

A little slower, but still not 45 TPS:

 PGPASSWORD=sharding_user pgbench --select-only -T 10 -P 1 -p 6432 --protocol prepared -U sharding_user -h 127.0.0.1 sharded_db
pgbench (15.3 (Homebrew))
starting vacuum...end.
progress: 1.0 s, 8533.8 tps, lat 0.117 ms stddev 0.032, 0 failed
progress: 2.0 s, 8824.1 tps, lat 0.113 ms stddev 0.011, 0 failed
progress: 3.0 s, 8863.9 tps, lat 0.113 ms stddev 0.010, 0 failed
progress: 4.0 s, 8847.1 tps, lat 0.113 ms stddev 0.011, 0 failed
progress: 5.0 s, 8855.0 tps, lat 0.113 ms stddev 0.010, 0 failed
progress: 6.0 s, 8861.0 tps, lat 0.113 ms stddev 0.010, 0 failed
progress: 7.0 s, 8820.9 tps, lat 0.113 ms stddev 0.011, 0 failed
progress: 8.0 s, 8715.8 tps, lat 0.115 ms stddev 0.013, 0 failed
progress: 9.0 s, 8817.4 tps, lat 0.113 ms stddev 0.011, 0 failed
progress: 10.0 s, 8861.9 tps, lat 0.113 ms stddev 0.010, 0 failed
transaction type: <builtin: select only>
scaling factor: 1
query mode: prepared
number of clients: 1
number of threads: 1
maximum number of tries: 1
duration: 10 s
number of transactions actually processed: 88042
number of failed transactions: 0 (0.000%)
latency average = 0.114 ms
latency stddev = 0.014 ms
initial connection time = 2.474 ms
tps = 8802.444793 (without initial connection time)

Double-checked the config this time:

2023-07-29T14:42:28.102582Z  INFO pgcat::config: [pool: sharded_db][user: sharding_user] Pool mode: transaction 

SHOW SERVERS show good prepared cache hit rates:

 server_id  | database_name |     user      |          address_id          | application_name | state | transaction_count | query_count | bytes_sent | bytes_received | age_seconds | prepare_cache_hit | prepare_cache_miss | prepare_cache_size
 0xE4A31CCC | sharded_db    | sharding_user | sharded_db_shard_0_primary   | pgbench          | idle  |             35570 |       35570 |    1917440 |        2525674 |          14 |             35565 |                  1 |                  1

pgcat=> show users;
     name      |  pool_mode  
---------------+-------------
 simple_user   | session
 sharding_user | transaction
 other_user    | transaction
(3 rows)

pgcat=> show pools;
  database  |     user      |  pool_mode  | cl_idle | cl_active | cl_waiting | cl_cancel_req | sv_active | sv_idle | sv_used | sv_tested | sv_login | maxwait | maxwait_us 
------------+---------------+-------------+---------+-----------+------------+---------------+-----------+---------+---------+-----------+----------+---------+------------
 sharded_db | sharding_user | transaction |       0 |         0 |          0 |             0 |         0 |       0 |       0 |         0 |        0 |       0 |          0
 sharded_db | other_user    | transaction |       0 |         0 |          0 |             0 |         0 |       0 |       0 |         0 |        0 |       0 |          0
 simple_db  | simple_user   | session     |       0 |         0 |          0 |             0 |         0 |       6 |       0 |         0 |        0 |       0 |          0
(3 rows)

[JelteF]

If I change the default config to use transaction mode for sharding_user and use your commands. Then I get the exact same issue as with the config I shared. So, it's extremely reproducible for me. I think if you try on an Ubuntu box with an Intel CPU you should be able to reproduce this without problems.

Just double checking, you are on the latest commit of the main branch, right? i.e. 9d1c46a

[JelteF]

Some extra info: CPU of pgcat and postgres is pretty much idle. So I'm guessing it's related to something i/o related. Could be due to some differences between non-blocking i/o between OSX and Linux. I'd be quite surprised if it's ARM vs X86_64 related.

[levkk]

Cool will do. I developed that PR on my Ubuntu (Ryzen 5800X), so I don't think it's ARM vs Intel vs Mac silicon either. Could you enable tracing log level and maybe also a profiler (e.g. strace could be very helpful here)? It should show where it's waiting for something.

I double checked, I'm on latest main version of the code.

[JelteF]

strace slow:

[pid 2251942] 10:32:45.084525 recvfrom(11, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 8192, 0, NULL, NULL) = 66 <0.000130>
[pid 2251942] 10:32:45.084834 sendto(14, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 66, MSG_NOSIGNAL, NULL, 0) = 66 <0.000174>
[pid 2251942] 10:32:45.085185 sendto(11, "H\0\0\0\4", 5, MSG_NOSIGNAL, NULL, 0) = 5 <0.000176>
[pid 2251942] 10:32:45.085545 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=4, u64=4}}], 1024, 1081) = 1 <0.000128>
[pid 2251942] 10:32:45.085843 recvfrom(14, "Q\0\0\0<SELECT abalance FROM pgbench_accounts WHERE aid = 4706;\0", 8192, 0, NULL, NULL) = 61 <0.000129>
[pid 2251942] 10:32:45.086184 sendto(12, "Q\0\0\0<SELECT abalance FROM pgbench_accounts WHERE aid = 4706;\0", 61, MSG_NOSIGNAL, NULL, 0) = 61 <0.000132>
[pid 2251942] 10:32:45.086494 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=2, u64=2}}], 1024, 1080) = 1 <0.045625>
[pid 2251942] 10:32:45.132382 recvfrom(12, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 8192, 0, NULL, NULL) = 66 <0.000147>
[pid 2251942] 10:32:45.132757 sendto(14, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 66, MSG_NOSIGNAL, NULL, 0) = 66 <0.000206>
[pid 2251942] 10:32:45.133160 sendto(12, "H\0\0\0\4", 5, MSG_NOSIGNAL, NULL, 0) = 5 <0.000232>
[pid 2251942] 10:32:45.133662 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=4, u64=4}}], 1024, 1033) = 1 <0.000142>
[pid 2251942] 10:32:45.134005 recvfrom(14, "Q\0\0\0=SELECT abalance FROM pgbench_accounts WHERE aid = 96908;\0", 8192, 0, NULL, NULL) = 62 <0.000150>
[pid 2251942] 10:32:45.134386 sendto(11, "Q\0\0\0=SELECT abalance FROM pgbench_accounts WHERE aid = 96908;\0", 62, MSG_NOSIGNAL, NULL, 0) = 62 <0.000185>
[pid 2251942] 10:32:45.134754 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=1, u64=1}}], 1024, 1031) = 1 <0.000362>
[pid 2251942] 10:32:45.135294 recvfrom(11, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 8192, 0, NULL, NULL) = 66 <0.000141>
[pid 2251942] 10:32:45.135630 sendto(14, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 66, MSG_NOSIGNAL, NULL, 0) = 66 <0.000181>
[pid 2251942] 10:32:45.136012 sendto(11, "H\0\0\0\4", 5, MSG_NOSIGNAL, NULL, 0) = 5 <0.000184>
[pid 2251942] 10:32:45.136385 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=4, u64=4}}], 1024, 1030) = 1 <0.000133>
[pid 2251942] 10:32:45.136693 recvfrom(14, "Q\0\0\0=SELECT abalance FROM pgbench_accounts WHERE aid = 15928;\0", 8192, 0, NULL, NULL) = 62 <0.000135>
[pid 2251942] 10:32:45.137222 sendto(12, "Q\0\0\0=SELECT abalance FROM pgbench_accounts WHERE aid = 15928;\0", 62, MSG_NOSIGNAL, NULL, 0) = 62 <0.000166>
[pid 2251942] 10:32:45.137591 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=2, u64=2}}], 1024, 1029) = 1 <0.044558>
[pid 2251942] 10:32:45.182422 recvfrom(12, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 8192, 0, NULL, NULL) = 66 <0.000150>
[pid 2251942] 10:32:45.182806 sendto(14, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 66, MSG_NOSIGNAL, NULL, 0) = 66 <0.000347>
[pid 2251942] 10:32:45.183385 sendto(12, "H\0\0\0\4", 5, MSG_NOSIGNAL, NULL, 0) = 5 <0.000246>
[pid 2251942] 10:32:45.183908 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=4, u64=4}}], 1024, 982) = 1 <0.000141>
[pid 2251942] 10:32:45.184251 recvfrom(14, "Q\0\0\0=SELECT abalance FROM pgbench_accounts WHERE aid = 87512;\0", 8192, 0, NULL, NULL) = 62 <0.000154>
[pid 2251942] 10:32:45.184642 sendto(11, "Q\0\0\0=SELECT abalance FROM pgbench_accounts WHERE aid = 87512;\0", 62, MSG_NOSIGNAL, NULL, 0) = 62 <0.000190>
[pid 2251942] 10:32:45.185023 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=1, u64=1}}], 1024, 981) = 1 <0.000400>
[pid 2251942] 10:32:45.185605 recvfrom(11, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\16\0\1\0\0\0\0041838C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 8192, 0, NULL, NULL) = 69 <0.000139>
[pid 2251942] 10:32:45.185936 sendto(14, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\16\0\1\0\0\0\0041838C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 69, MSG_NOSIGNAL, NULL, 0) = 69 <0.000187>
[pid 2251942] 10:32:45.186313 sendto(11, "H\0\0\0\4", 5, MSG_NOSIGNAL, NULL, 0) = 5 <0.000190>
[pid 2251942] 10:32:45.186697 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=4, u64=4}}], 1024, 979) = 1 <0.000138>
[pid 2251942] 10:32:45.187016 recvfrom(14, "Q\0\0\0=SELECT abalance FROM pgbench_accounts WHERE aid = 45847;\0", 8192, 0, NULL, NULL) = 62 <0.000139>
[pid 2251942] 10:32:45.187359 sendto(12, "Q\0\0\0=SELECT abalance FROM pgbench_accounts WHERE aid = 45847;\0", 62, MSG_NOSIGNAL, NULL, 0) = 62 <0.000139>
[pid 2251942] 10:32:45.187684 epoll_wait(3, [], 1024, 0) = 0 <0.000136>
[pid 2251942] 10:32:45.187992 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=2, u64=2}}], 1024, 978) = 1 <0.044064>
[pid 2251942] 10:32:45.232320 recvfrom(12, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 8192, 0, NULL, NULL) = 66 <0.000147>

strace fast:

[pid 2252728] 10:33:53.543720 recvfrom(12, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 8192, 0, NULL, NULL) = 66 <0.000075>
[pid 2252728] 10:33:53.544125 sendto(13, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 66, MSG_NOSIGNAL, NULL, 0) = 66 <0.000336>
[pid 2252728] 10:33:53.545515 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=16777219, u64=16777219}}], 1024, 5455) = 1 <0.000137>
[pid 2252728] 10:33:53.545876 recvfrom(13, "Q\0\0\0=SELECT abalance FROM pgbench_accounts WHERE aid = 96856;\0", 8192, 0, NULL, NULL) = 62 <0.000553>
[pid 2252728] 10:33:53.546836 sendto(11, "Q\0\0\0=SELECT abalance FROM pgbench_accounts WHERE aid = 96856;\0", 62, MSG_NOSIGNAL, NULL, 0) = 62 <0.000184>
[pid 2252728] 10:33:53.548093 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=1, u64=1}}], 1024, 5453) = 1 <0.000122>
[pid 2252728] 10:33:53.548537 recvfrom(11, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 8192, 0, NULL, NULL) = 66 <0.000091>
[pid 2252728] 10:33:53.549696 sendto(13, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 66, MSG_NOSIGNAL, NULL, 0) = 66 <0.000253>
[pid 2252728] 10:33:53.550707 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=16777219, u64=16777219}}], 1024, 5450) = 1 <0.003008>
[pid 2252728] 10:33:53.554620 recvfrom(13, "Q\0\0\0=SELECT abalance FROM pgbench_accounts WHERE aid = 19937;\0", 8192, 0, NULL, NULL) = 62 <0.000083>
[pid 2252728] 10:33:53.555096 sendto(12, "Q\0\0\0=SELECT abalance FROM pgbench_accounts WHERE aid = 19937;\0", 62, MSG_NOSIGNAL, NULL, 0) = 62 <0.000109>
[pid 2252728] 10:33:53.555761 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=2, u64=2}}], 1024, 5445) = 1 <0.001635>
[pid 2252728] 10:33:53.557650 recvfrom(12, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 8192, 0, NULL, NULL) = 66 <0.000088>
[pid 2252728] 10:33:53.557934 sendto(13, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 66, MSG_NOSIGNAL, NULL, 0) = 66 <0.000080>
[pid 2252728] 10:33:53.558157 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=16777219, u64=16777219}}], 1024, 5442) = 1 <0.000417>
[pid 2252728] 10:33:53.558746 recvfrom(13, "Q\0\0\0=SELECT abalance FROM pgbench_accounts WHERE aid = 39716;\0", 8192, 0, NULL, NULL) = 62 <0.000103>
[pid 2252728] 10:33:53.559014 sendto(11, "Q\0\0\0=SELECT abalance FROM pgbench_accounts WHERE aid = 39716;\0", 62, MSG_NOSIGNAL, NULL, 0) = 62 <0.000139>
[pid 2252728] 10:33:53.559327 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=1, u64=1}}], 1024, 5441) = 1 <0.000068>
[pid 2252728] 10:33:53.559505 recvfrom(11, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 8192, 0, NULL, NULL) = 66 <0.000066>
[pid 2252728] 10:33:53.559732 sendto(13, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 66, MSG_NOSIGNAL, NULL, 0) = 66 <0.000223>
[pid 2252728] 10:33:53.560336 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=16777219, u64=16777219}}], 1024, 5440) = 1 <0.001126>
[pid 2252728] 10:33:53.562075 recvfrom(13, "Q\0\0\0=SELECT abalance FROM pgbench_accounts WHERE aid = 63428;\0", 8192, 0, NULL, NULL) = 62 <0.000180>
[pid 2252728] 10:33:53.562491 sendto(12, "Q\0\0\0=SELECT abalance FROM pgbench_accounts WHERE aid = 63428;\0", 62, MSG_NOSIGNAL, NULL, 0) = 62 <0.000230>
[pid 2252728] 10:33:53.562950 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=2, u64=2}}], 1024, 5438) = 1 <0.000086>
[pid 2252728] 10:33:53.563153 recvfrom(12, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 8192, 0, NULL, NULL) = 66 <0.000156>
[pid 2252728] 10:33:53.563572 sendto(13, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 66, MSG_NOSIGNAL, NULL, 0) = 66 <0.000139>
[pid 2252728] 10:33:53.563899 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=16777219, u64=16777219}}], 1024, 5437) = 1 <0.000129>
[pid 2252728] 10:33:53.564274 recvfrom(13, "Q\0\0\0<SELECT abalance FROM pgbench_accounts WHERE aid = 8244;\0", 8192, 0, NULL, NULL) = 61 <0.000340>
[pid 2252728] 10:33:53.564775 sendto(11, "Q\0\0\0<SELECT abalance FROM pgbench_accounts WHERE aid = 8244;\0", 61, MSG_NOSIGNAL, NULL, 0) = 61 <0.000099>
[pid 2252728] 10:33:53.565073 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=1, u64=1}}], 1024, 5435) = 1 <0.000091>
[pid 2252728] 10:33:53.565336 recvfrom(11, "T\0\0\0!\0\1abalance\0\0\3\205}\0\3\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0010C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 8192, 0, NULL, NULL) = 66 <0.000111>

So it seems it's waiting much longer on some epoll_wait calls:

[pid 2251942] 10:32:45.086494 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=2, u64=2}}], 1024, 1080) = 1 <0.045625>

[JelteF]

Could you enable tracing log level ...?

How do you get pgcat to output tracing logs? I tried a few things and grepped trough the codebase, but couldn't find a solution that worked.

[JelteF]

@knizhnik mentioned to me:

Looks like TCP_NODELAY is missed somewhere

Indeed sounds like a possible cause.

Also to be clear. I was able to get good performance with the initial adition of prepared statement support (PR #474), but not with the addition of handling the Close message (PR #482).

[levkk]

Could you enable tracing log level ...?

How do you get pgcat to output tracing logs? I tried a few things and grepped trough the codebase, but couldn't find a solution that worked.

cargo run -- --log-level TRACE

For more options:

cargo run -- --help

[levkk]

@knizhnik mentioned to me:

Looks like TCP_NODELAY is missed somewhere

Indeed sounds like a possible cause.

Also to be clear. I was able to get good performance with the initial adition of prepared statement support (PR #474), but not with the addition of handling the Close message (PR #482).

Cache addition is the most suspect, although I don't know why it would work fine on my end and not on yours. Could you share your stats?

SHOW SERVERS

I'm looking mostly for prepared_cache_hit, and prepare_cache_miss, also prepared_cache_size.

Thanks!

[JelteF]

When running with --protocol prepared I get these kind of results (hits slowly encreasing):

 server_id  │ database_name │   user   │      address_id      │ application_name │ state  │ transaction_count │ query_count │ bytes_sent │ bytes_received │ age_seconds │ prepare_cache_hit │ prepare_cache_miss │ prepare_cache_size
────────────┼───────────────┼──────────┼──────────────────────┼──────────────────┼────────┼───────────────────┼─────────────┼────────────┼────────────────┼─────────────┼───────────────────┼────────────────────┼────────────────────
 0x0D97F26B │ pgml          │ postgres │ pgml_shard_0_primary │ pgbench          │ active │               311 │         311 │      19427 │          20981 │          39 │               108 │                  1 │                  1
 0xCBA72142 │ pgml          │ postgres │ pgml_shard_0_primary │ pgbench          │ idle   │               311 │         311 │      20260 │          21132 │          39 │               108 │                  0 │                  1

When running with --protocol simple all are zeros of course (but that still has the super low performance).