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

JelteF · 2023-07-29T11:55:59Z

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:

git checkout main
Add prepared_statements = true to the minimal config
RUST_LOG=info cargo run --release -- pgcat.minimal.toml
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.

The text was updated successfully, but these errors were encountered:

levkk · 2023-07-29T13:56:06Z

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 · 2023-07-29T14:35:59Z

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 · 2023-07-29T14:40:38Z

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 · 2023-07-29T14:40:42Z

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 · 2023-07-29T14:41:03Z

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

levkk · 2023-07-29T14:44:15Z

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 · 2023-07-29T15:59:47Z

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 · 2023-07-29T16:05:19Z

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 · 2023-07-29T22:40:50Z

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 · 2023-07-31T09:00:16Z

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 · 2023-08-01T12:18:41Z

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 · 2023-08-01T12:29:46Z

@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 · 2023-08-01T17:55:29Z

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 · 2023-08-01T17:57:39Z

@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 · 2023-08-01T18:08:37Z

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).

JelteF · 2023-08-01T18:11:35Z

trace level logs of the slow thing:

Details

2023-08-01T18:08:57.175430Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.175478Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.175494Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.175506Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.175517Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.175583Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.175602Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.213620Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.213704Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.213718Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.213725Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.213734Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.213821Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.213880Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.213935Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.213949Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.214037Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.214129Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.214194Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.214250Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.214268Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.214276Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.214284Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.214306Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.214361Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 207, query_count: 207, bytes_received: 14712, bytes_sent: 11777, xact_time: 0, query_time: 4870, wait_time: 14618, errors: 0 }, current: AddressStatFields { xact_count: 207, query_count: 207, bytes_received: 14669, bytes_sent: 11741, xact_time: 0, query_time: 4870, wait_time: 14618, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.214446Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.214503Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 207, query_count: 207, bytes_received: 14712, bytes_sent: 11777, xact_time: 0, query_time: 4870, wait_time: 14699, errors: 0 }, current: AddressStatFields { xact_count: 207, query_count: 207, bytes_received: 14669, bytes_sent: 11741, xact_time: 0, query_time: 4870, wait_time: 14699, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.214575Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.214630Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.214643Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.214692Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.214748Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.214766Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.214774Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.223027Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.223099Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.223112Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.223119Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.223172Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.223300Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.223356Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.223369Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.223377Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.223460Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.223547Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.223610Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.223666Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.223685Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.223692Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.223700Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.223717Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.223732Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 208, query_count: 208, bytes_received: 14783, bytes_sent: 11831, xact_time: 0, query_time: 4878, wait_time: 14699, errors: 0 }, current: AddressStatFields { xact_count: 208, query_count: 208, bytes_received: 14740, bytes_sent: 11795, xact_time: 0, query_time: 4878, wait_time: 14699, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.223807Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.223823Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 208, query_count: 208, bytes_received: 14783, bytes_sent: 11831, xact_time: 0, query_time: 4878, wait_time: 14768, errors: 0 }, current: AddressStatFields { xact_count: 208, query_count: 208, bytes_received: 14740, bytes_sent: 11795, xact_time: 0, query_time: 4878, wait_time: 14768, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.223893Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.223949Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.223962Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.223970Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.223977Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.223983Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.223989Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.262940Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.263016Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.263029Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.263085Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.263101Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.263227Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.263284Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.263296Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.263348Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.263474Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.263563Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.263627Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.263682Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.263698Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.263751Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.263810Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.263835Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.263889Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 209, query_count: 209, bytes_received: 14854, bytes_sent: 11885, xact_time: 0, query_time: 4917, wait_time: 14768, errors: 0 }, current: AddressStatFields { xact_count: 209, query_count: 209, bytes_received: 14811, bytes_sent: 11849, xact_time: 0, query_time: 4917, wait_time: 14768, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.263972Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.264030Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 209, query_count: 209, bytes_received: 14854, bytes_sent: 11885, xact_time: 0, query_time: 4917, wait_time: 14847, errors: 0 }, current: AddressStatFields { xact_count: 209, query_count: 209, bytes_received: 14811, bytes_sent: 11849, xact_time: 0, query_time: 4917, wait_time: 14847, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.264105Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.264122Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.264176Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.264232Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.264247Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.264298Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.264313Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.273148Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.273228Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.273241Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.273292Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.273310Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.273446Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.273499Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.273512Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.273520Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.273647Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.273739Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.273804Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.273861Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.273880Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.273935Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.273991Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.274017Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.274073Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 210, query_count: 210, bytes_received: 14925, bytes_sent: 11939, xact_time: 0, query_time: 4926, wait_time: 14847, errors: 0 }, current: AddressStatFields { xact_count: 210, query_count: 210, bytes_received: 14882, bytes_sent: 11903, xact_time: 0, query_time: 4926, wait_time: 14847, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.274155Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.274215Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 210, query_count: 210, bytes_received: 14925, bytes_sent: 11939, xact_time: 0, query_time: 4926, wait_time: 14926, errors: 0 }, current: AddressStatFields { xact_count: 210, query_count: 210, bytes_received: 14882, bytes_sent: 11903, xact_time: 0, query_time: 4926, wait_time: 14926, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.274286Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.274300Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.274307Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.274357Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.274374Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.274425Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.274480Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.313549Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.313635Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.313648Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.313703Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.313762Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.313860Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.313929Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.313946Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.313958Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.314091Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.314187Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.314251Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.314306Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.314324Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.314374Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.314395Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.314423Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.314476Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 211, query_count: 211, bytes_received: 14996, bytes_sent: 11993, xact_time: 0, query_time: 4965, wait_time: 14926, errors: 0 }, current: AddressStatFields { xact_count: 211, query_count: 211, bytes_received: 14953, bytes_sent: 11957, xact_time: 0, query_time: 4965, wait_time: 14926, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.314560Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.314575Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 211, query_count: 211, bytes_received: 14996, bytes_sent: 11993, xact_time: 0, query_time: 4965, wait_time: 15006, errors: 0 }, current: AddressStatFields { xact_count: 211, query_count: 211, bytes_received: 14953, bytes_sent: 11957, xact_time: 0, query_time: 4965, wait_time: 15006, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.314645Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.314701Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.314713Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.314720Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.314769Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.314823Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.314838Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.323350Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.323427Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.323487Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.323542Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.323558Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.323638Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.323659Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.323671Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.323684Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.323807Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.323897Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.323975Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.324042Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.324064Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.324131Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.324154Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.324229Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.324288Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 212, query_count: 212, bytes_received: 15067, bytes_sent: 12047, xact_time: 0, query_time: 4973, wait_time: 15006, errors: 0 }, current: AddressStatFields { xact_count: 212, query_count: 212, bytes_received: 15024, bytes_sent: 12011, xact_time: 0, query_time: 4973, wait_time: 15006, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.324372Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.324429Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 212, query_count: 212, bytes_received: 15067, bytes_sent: 12047, xact_time: 0, query_time: 4973, wait_time: 15086, errors: 0 }, current: AddressStatFields { xact_count: 212, query_count: 212, bytes_received: 15024, bytes_sent: 12011, xact_time: 0, query_time: 4973, wait_time: 15086, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.324500Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.324557Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.324611Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.324669Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.324724Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.324779Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.324833Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.363501Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.363584Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.363648Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.363704Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.363724Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.363820Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.363878Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.363891Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.363900Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.363987Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.364080Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.364145Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.364200Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.364261Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.364274Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.364326Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.364396Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.364430Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 213, query_count: 213, bytes_received: 15138, bytes_sent: 12101, xact_time: 0, query_time: 5011, wait_time: 15086, errors: 0 }, current: AddressStatFields { xact_count: 213, query_count: 213, bytes_received: 15095, bytes_sent: 12065, xact_time: 0, query_time: 5011, wait_time: 15086, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.364547Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.364614Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 213, query_count: 213, bytes_received: 15138, bytes_sent: 12101, xact_time: 0, query_time: 5011, wait_time: 15197, errors: 0 }, current: AddressStatFields { xact_count: 213, query_count: 213, bytes_received: 15095, bytes_sent: 12065, xact_time: 0, query_time: 5011, wait_time: 15197, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.364685Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.364741Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.364753Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.364804Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.364860Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.364951Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.365045Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.373354Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.373433Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.373447Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.373454Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.373463Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.373588Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.373646Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.373659Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.373669Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.373752Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.373838Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.373902Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.373958Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.374017Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.374071Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.374129Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.374153Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.374207Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 214, query_count: 214, bytes_received: 15209, bytes_sent: 12155, xact_time: 0, query_time: 5019, wait_time: 15197, errors: 0 }, current: AddressStatFields { xact_count: 214, query_count: 214, bytes_received: 15166, bytes_sent: 12119, xact_time: 0, query_time: 5019, wait_time: 15197, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.374287Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.374381Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 214, query_count: 214, bytes_received: 15209, bytes_sent: 12155, xact_time: 0, query_time: 5019, wait_time: 15274, errors: 0 }, current: AddressStatFields { xact_count: 214, query_count: 214, bytes_received: 15166, bytes_sent: 12119, xact_time: 0, query_time: 5019, wait_time: 15274, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.374453Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.374546Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.374600Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.374655Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.374711Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.374765Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.374777Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.413267Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.413351Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.413413Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.413469Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.413526Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.413659Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.413716Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.413729Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.413738Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.413870Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.413961Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.414026Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.414082Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.414100Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.414108Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.414115Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.414136Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.414153Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 215, query_count: 215, bytes_received: 15280, bytes_sent: 12209, xact_time: 0, query_time: 5057, wait_time: 15274, errors: 0 }, current: AddressStatFields { xact_count: 215, query_count: 215, bytes_received: 15237, bytes_sent: 12173, xact_time: 0, query_time: 5057, wait_time: 15274, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.414232Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.414294Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 215, query_count: 215, bytes_received: 15280, bytes_sent: 12209, xact_time: 0, query_time: 5057, wait_time: 15346, errors: 0 }, current: AddressStatFields { xact_count: 215, query_count: 215, bytes_received: 15237, bytes_sent: 12173, xact_time: 0, query_time: 5057, wait_time: 15346, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.414366Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.414380Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.414388Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.414437Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.414457Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.414466Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.414478Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.423012Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.423048Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.423053Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.423056Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.423059Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.423103Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.423130Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.423142Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.423148Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.423201Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.423255Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.423267Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.423272Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.423278Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.423307Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.423315Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.423330Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.423341Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 216, query_count: 216, bytes_received: 15351, bytes_sent: 12263, xact_time: 0, query_time: 5065, wait_time: 15346, errors: 0 }, current: AddressStatFields { xact_count: 216, query_count: 216, bytes_received: 15308, bytes_sent: 12227, xact_time: 0, query_time: 5065, wait_time: 15346, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.423369Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.423399Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 216, query_count: 216, bytes_received: 15351, bytes_sent: 12263, xact_time: 0, query_time: 5065, wait_time: 15371, errors: 0 }, current: AddressStatFields { xact_count: 216, query_count: 216, bytes_received: 15308, bytes_sent: 12227, xact_time: 0, query_time: 5065, wait_time: 15371, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.423441Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.423448Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.423454Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.423458Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.423488Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.423494Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.423500Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.463731Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.463833Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.463848Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.463855Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.463864Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.463971Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.464030Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.464042Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.464052Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.464142Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.464235Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.464305Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.464363Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.464382Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.464390Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.464398Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.464419Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.464474Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 217, query_count: 217, bytes_received: 15422, bytes_sent: 12317, xact_time: 0, query_time: 5105, wait_time: 15371, errors: 0 }, current: AddressStatFields { xact_count: 217, query_count: 217, bytes_received: 15379, bytes_sent: 12281, xact_time: 0, query_time: 5105, wait_time: 15371, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.464560Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.464577Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 217, query_count: 217, bytes_received: 15422, bytes_sent: 12317, xact_time: 0, query_time: 5105, wait_time: 15453, errors: 0 }, current: AddressStatFields { xact_count: 217, query_count: 217, bytes_received: 15379, bytes_sent: 12281, xact_time: 0, query_time: 5105, wait_time: 15453, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.464646Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.464660Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.464712Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.464768Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.464782Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.464791Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.464800Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.473139Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.473214Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.473227Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.473234Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.473243Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.473327Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.473576Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.473594Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.473647Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.473785Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.473875Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.473941Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.473996Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.474056Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.474069Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.474122Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.474149Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.474207Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 218, query_count: 218, bytes_received: 15493, bytes_sent: 12371, xact_time: 0, query_time: 5113, wait_time: 15453, errors: 0 }, current: AddressStatFields { xact_count: 218, query_count: 218, bytes_received: 15450, bytes_sent: 12335, xact_time: 0, query_time: 5113, wait_time: 15453, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.474249Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.474304Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 218, query_count: 218, bytes_received: 15493, bytes_sent: 12371, xact_time: 0, query_time: 5113, wait_time: 15493, errors: 0 }, current: AddressStatFields { xact_count: 218, query_count: 218, bytes_received: 15450, bytes_sent: 12335, xact_time: 0, query_time: 5113, wait_time: 15493, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.474376Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.474390Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.474397Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.474404Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.474412Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.474419Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.474426Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.513156Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.513252Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.513265Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.513272Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.513331Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.513475Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.513532Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.513544Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.513553Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.513641Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.513744Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.513810Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.513866Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.513929Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.513984Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.514000Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.514064Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.514083Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 219, query_count: 219, bytes_received: 15564, bytes_sent: 12425, xact_time: 0, query_time: 5151, wait_time: 15493, errors: 0 }, current: AddressStatFields { xact_count: 219, query_count: 219, bytes_received: 15521, bytes_sent: 12389, xact_time: 0, query_time: 5151, wait_time: 15493, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.514169Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.514185Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 219, query_count: 219, bytes_received: 15564, bytes_sent: 12425, xact_time: 0, query_time: 5151, wait_time: 15573, errors: 0 }, current: AddressStatFields { xact_count: 219, query_count: 219, bytes_received: 15521, bytes_sent: 12389, xact_time: 0, query_time: 5151, wait_time: 15573, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.514255Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.514270Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.514321Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.514376Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.514431Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.514486Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.514540Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.523064Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.523138Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.523151Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.523158Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.523212Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.523307Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.523365Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.523378Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.523430Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.523560Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.523648Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.523750Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.523806Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.523823Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.523831Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.523840Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.523859Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.523871Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 220, query_count: 220, bytes_received: 15635, bytes_sent: 12479, xact_time: 0, query_time: 5159, wait_time: 15573, errors: 0 }, current: AddressStatFields { xact_count: 220, query_count: 220, bytes_received: 15592, bytes_sent: 12443, xact_time: 0, query_time: 5159, wait_time: 15573, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.523950Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.523967Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 220, query_count: 220, bytes_received: 15635, bytes_sent: 12479, xact_time: 0, query_time: 5159, wait_time: 15647, errors: 0 }, current: AddressStatFields { xact_count: 220, query_count: 220, bytes_received: 15592, bytes_sent: 12443, xact_time: 0, query_time: 5159, wait_time: 15647, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.524036Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.524092Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.524104Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.524112Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.524163Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.524177Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.524229Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.563557Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.563647Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.563660Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.563667Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.563676Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.563816Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.563874Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.563887Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.563897Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.563987Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.564080Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.564145Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.564203Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.564220Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.564232Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.564239Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.564304Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.564364Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 221, query_count: 221, bytes_received: 15706, bytes_sent: 12533, xact_time: 0, query_time: 5198, wait_time: 15647, errors: 0 }, current: AddressStatFields { xact_count: 221, query_count: 221, bytes_received: 15663, bytes_sent: 12497, xact_time: 0, query_time: 5198, wait_time: 15647, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.564447Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.564462Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 221, query_count: 221, bytes_received: 15706, bytes_sent: 12533, xact_time: 0, query_time: 5198, wait_time: 15727, errors: 0 }, current: AddressStatFields { xact_count: 221, query_count: 221, bytes_received: 15663, bytes_sent: 12497, xact_time: 0, query_time: 5198, wait_time: 15727, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.564532Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.564589Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.564644Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.564657Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.564666Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.564672Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.564679Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.573447Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.573523Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.573537Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.573590Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.573649Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.573744Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.573801Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.573814Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.573866Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.573960Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.574047Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.574068Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.574076Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.574086Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.574092Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.574100Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.574164Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.574187Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 222, query_count: 222, bytes_received: 15777, bytes_sent: 12587, xact_time: 0, query_time: 5207, wait_time: 15727, errors: 0 }, current: AddressStatFields { xact_count: 222, query_count: 222, bytes_received: 15734, bytes_sent: 12551, xact_time: 0, query_time: 5207, wait_time: 15727, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.574267Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.574324Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 222, query_count: 222, bytes_received: 15777, bytes_sent: 12587, xact_time: 0, query_time: 5207, wait_time: 15802, errors: 0 }, current: AddressStatFields { xact_count: 222, query_count: 222, bytes_received: 15734, bytes_sent: 12551, xact_time: 0, query_time: 5207, wait_time: 15802, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.574397Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.574453Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.574467Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.574474Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.574482Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.574489Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.574495Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.613620Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.613713Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.613730Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.613783Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.613799Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.613895Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.613952Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.613965Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.613973Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.614058Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.614146Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.614215Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.614270Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.614333Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.614387Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.614681Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.614765Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.614833Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 223, query_count: 223, bytes_received: 15848, bytes_sent: 12641, xact_time: 0, query_time: 5246, wait_time: 15802, errors: 0 }, current: AddressStatFields { xact_count: 223, query_count: 223, bytes_received: 15805, bytes_sent: 12605, xact_time: 0, query_time: 5246, wait_time: 15802, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.614917Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.614973Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 223, query_count: 223, bytes_received: 15848, bytes_sent: 12641, xact_time: 0, query_time: 5246, wait_time: 15881, errors: 0 }, current: AddressStatFields { xact_count: 223, query_count: 223, bytes_received: 15805, bytes_sent: 12605, xact_time: 0, query_time: 5246, wait_time: 15881, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.615045Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.615102Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.615156Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.615211Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.615266Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.615320Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.615375Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.623004Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.623080Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.623093Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.623100Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.623108Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.623192Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.623249Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.623305Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.623360Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.623487Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.623575Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.623639Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.623695Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.623753Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.623810Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.623824Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.623843Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.623855Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 224, query_count: 224, bytes_received: 15919, bytes_sent: 12695, xact_time: 0, query_time: 5253, wait_time: 15881, errors: 0 }, current: AddressStatFields { xact_count: 224, query_count: 224, bytes_received: 15876, bytes_sent: 12659, xact_time: 0, query_time: 5253, wait_time: 15881, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.623932Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.623989Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 224, query_count: 224, bytes_received: 15919, bytes_sent: 12695, xact_time: 0, query_time: 5253, wait_time: 15951, errors: 0 }, current: AddressStatFields { xact_count: 224, query_count: 224, bytes_received: 15876, bytes_sent: 12659, xact_time: 0, query_time: 5253, wait_time: 15951, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.624020Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.624072Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.624128Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.624141Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.624151Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.624158Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.624209Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.663125Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.663215Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.663228Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.663235Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.663293Z TRACE pgcat::server: Message: Z
2023-08-01T18:08:57.663438Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.663495Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:08:57.663508Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:08:57.663517Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:08:57.663605Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.663701Z DEBUG pgcat::client: Rewrote bind `P_0` to `P_0`
2023-08-01T18:08:57.663767Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:08:57.663823Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.663881Z DEBUG pgcat::client: Anonymous describe
2023-08-01T18:08:57.663894Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.663950Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:08:57.664021Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:08:57.664081Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 225, query_count: 225, bytes_received: 15990, bytes_sent: 12749, xact_time: 0, query_time: 5292, wait_time: 15951, errors: 0 }, current: AddressStatFields { xact_count: 225, query_count: 225, bytes_received: 15947, bytes_sent: 12713, xact_time: 0, query_time: 5292, wait_time: 15951, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:08:57.664165Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:08:57.664183Z DEBUG pgcat::client: Client 127.0.0.1:44298 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 225, query_count: 225, bytes_received: 15990, bytes_sent: 12749, xact_time: 0, query_time: 5292, wait_time: 16032, errors: 0 }, current: AddressStatFields { xact_count: 225, query_count: 225, bytes_received: 15947, bytes_sent: 12713, xact_time: 0, query_time: 5292, wait_time: 16032, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:08:57.664250Z DEBUG pgcat::client: Prepared statement active: Some("P_0")
2023-08-01T18:08:57.664264Z DEBUG pgcat::client: Checking prepared statement is on server
2023-08-01T18:08:57.664273Z DEBUG pgcat::client: Prepared statement `P_0` found in cache
2023-08-01T18:08:57.664323Z DEBUG pgcat::server: Should prepare `P_0`: false
2023-08-01T18:08:57.664379Z TRACE pgcat::client: Message: S
2023-08-01T18:08:57.664433Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:08:57.664446Z DEBUG pgcat::client: Sending S to server
2023-08-01T18:08:57.673026Z TRACE pgcat::server: Message: 2
2023-08-01T18:08:57.673100Z TRACE pgcat::server: Message: T
2023-08-01T18:08:57.673114Z TRACE pgcat::server: Message: D
2023-08-01T18:08:57.673120Z TRACE pgcat::server: Message: C
2023-08-01T18:08:57.673175Z TRACE pgcat::server: Message: Z

JelteF · 2023-08-01T18:24:56Z

with --protocol simple, fast:

Details

2023-08-01T18:21:55.284255Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:21:55.284257Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:21:55.284258Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:21:55.284401Z TRACE pgcat::server: Message: T
2023-08-01T18:21:55.284428Z TRACE pgcat::server: Message: D
2023-08-01T18:21:55.284431Z TRACE pgcat::server: Message: C
2023-08-01T18:21:55.284434Z TRACE pgcat::server: Message: Z
2023-08-01T18:21:55.284477Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:21:55.284495Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:21:55.284499Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:21:55.284504Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:21:55.284532Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:21:55.284556Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:21:55.284575Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:21:55.284593Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 5007, query_count: 5007, bytes_received: 330776, bytes_sent: 310296, xact_time: 0, query_time: 20, wait_time: 107891, errors: 0 }, current: AddressStatFields { xact_count: 5007, query_count: 5007, bytes_received: 330733, bytes_sent: 310260, xact_time: 0, query_time: 20, wait_time: 107891, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time:
0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:21:55.284605Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:21:55.284622Z DEBUG pgcat::client: Client 127.0.0.1:37322 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 5007, query_count: 5007, bytes_received: 330776, bytes_sent: 310296, xact_time: 0, query_time: 20, wait_time: 107902, errors: 0 }, current: AddressStatFields { xact_count: 5007, query_count: 5007, bytes_received: 330733, bytes_sent: 310260, xact_time: 0, query_time: 20, wait_time: 107902, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent:
2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:21:55.284631Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:21:55.284650Z TRACE pgcat::client: Message: Q
2023-08-01T18:21:55.284655Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:21:55.284658Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:21:55.284660Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:21:55.284824Z TRACE pgcat::server: Message: T
2023-08-01T18:21:55.284855Z TRACE pgcat::server: Message: D
2023-08-01T18:21:55.284859Z TRACE pgcat::server: Message: C
2023-08-01T18:21:55.284880Z TRACE pgcat::server: Message: Z
2023-08-01T18:21:55.284930Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:21:55.284948Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:21:55.284952Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:21:55.284957Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:21:55.284983Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:21:55.285008Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:21:55.285028Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:21:55.285033Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 5008, query_count: 5008, bytes_received: 330842, bytes_sent: 310358, xact_time: 0, query_time: 20, wait_time: 107902, errors: 0 }, current: AddressStatFields { xact_count: 5008, query_count: 5008, bytes_received: 330799, bytes_sent: 310322, xact_time: 0, query_time: 20, wait_time: 107902, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time:
0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:21:55.285061Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:21:55.285079Z DEBUG pgcat::client: Client 127.0.0.1:37322 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 5008, query_count: 5008, bytes_received: 330842, bytes_sent: 310358, xact_time: 0, query_time: 20, wait_time: 107929, errors: 0 }, current: AddressStatFields { xact_count: 5008, query_count: 5008, bytes_received: 330799, bytes_sent: 310322, xact_time: 0, query_time: 20, wait_time: 107929, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent:
2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:21:55.285101Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:21:55.285107Z TRACE pgcat::client: Message: Q
2023-08-01T18:21:55.285109Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:21:55.285111Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:21:55.285113Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:21:55.285268Z TRACE pgcat::server: Message: T
2023-08-01T18:21:55.285292Z TRACE pgcat::server: Message: D
2023-08-01T18:21:55.285295Z TRACE pgcat::server: Message: C
2023-08-01T18:21:55.285298Z TRACE pgcat::server: Message: Z
2023-08-01T18:21:55.285329Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:21:55.285347Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:21:55.285351Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:21:55.285356Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:21:55.285381Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:21:55.285406Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:21:55.285424Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:21:55.285442Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 5009, query_count: 5009, bytes_received: 330908, bytes_sent: 310420, xact_time: 0, query_time: 20, wait_time: 107929, errors: 0 }, current: AddressStatFields { xact_count: 5009, query_count: 5009, bytes_received: 330865, bytes_sent: 310384, xact_time: 0, query_time: 20, wait_time: 107929, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time:
0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:21:55.285468Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:21:55.285486Z DEBUG pgcat::client: Client 127.0.0.1:37322 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 5009, query_count: 5009, bytes_received: 330908, bytes_sent: 310420, xact_time: 0, query_time: 20, wait_time: 107953, errors: 0 }, current: AddressStatFields { xact_count: 5009, query_count: 5009, bytes_received: 330865, bytes_sent: 310384, xact_time: 0, query_time: 20, wait_time: 107953, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent:
2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:21:55.285496Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:21:55.285498Z TRACE pgcat::client: Message: Q
2023-08-01T18:21:55.285501Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:21:55.285503Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:21:55.285519Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:21:55.285701Z TRACE pgcat::server: Message: T
2023-08-01T18:21:55.285729Z TRACE pgcat::server: Message: D
2023-08-01T18:21:55.285734Z TRACE pgcat::server: Message: C
2023-08-01T18:21:55.285757Z TRACE pgcat::server: Message: Z
2023-08-01T18:21:55.285809Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:21:55.285830Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:21:55.285853Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:21:55.285863Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:21:55.285893Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:21:55.285916Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:21:55.285933Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:21:55.285938Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 5010, query_count: 5010, bytes_received: 330974, bytes_sent: 310482, xact_time: 0, query_time: 20, wait_time: 107953, errors: 0 }, current: AddressStatFields { xact_count: 5010, query_count: 5010, bytes_received: 330931, bytes_sent: 310446, xact_time: 0, query_time: 20, wait_time: 107953, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time:
0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:21:55.285963Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:21:55.285985Z DEBUG pgcat::client: Client 127.0.0.1:37322 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 5010, query_count: 5010, bytes_received: 330974, bytes_sent: 310482, xact_time: 0, query_time: 20, wait_time: 107976, errors: 0 }, current: AddressStatFields { xact_count: 5010, query_count: 5010, bytes_received: 330931, bytes_sent: 310446, xact_time: 0, query_time: 20, wait_time: 107976, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent:
2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:21:55.286012Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:21:55.286032Z TRACE pgcat::client: Message: Q
2023-08-01T18:21:55.286037Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:21:55.286056Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:21:55.286073Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:21:55.286245Z TRACE pgcat::server: Message: T
2023-08-01T18:21:55.286268Z TRACE pgcat::server: Message: D
2023-08-01T18:21:55.286272Z TRACE pgcat::server: Message: C
2023-08-01T18:21:55.286275Z TRACE pgcat::server: Message: Z
2023-08-01T18:21:55.286305Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:21:55.286323Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:21:55.286327Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:21:55.286346Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:21:55.286359Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:21:55.286382Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:21:55.286387Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:21:55.286406Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 5011, query_count: 5011, bytes_received: 331040, bytes_sent: 310544, xact_time: 0, query_time: 20, wait_time: 107976, errors: 0 }, current: AddressStatFields { xact_count: 5011, query_count: 5011, bytes_received: 330997, bytes_sent: 310508, xact_time: 0, query_time: 20, wait_time: 107976, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time:
0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:21:55.286431Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:21:55.286435Z DEBUG pgcat::client: Client 127.0.0.1:37322 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 5011, query_count: 5011, bytes_received: 331040, bytes_sent: 310544, xact_time: 0, query_time: 20, wait_time: 108000, errors: 0 }, current: AddressStatFields { xact_count: 5011, query_count: 5011, bytes_received: 330997, bytes_sent: 310508, xact_time: 0, query_time: 20, wait_time: 108000, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent:
2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:21:55.286458Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:21:55.286463Z TRACE pgcat::client: Message: Q
2023-08-01T18:21:55.286480Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:21:55.286498Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:21:55.286502Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:21:55.286651Z TRACE pgcat::server: Message: T
2023-08-01T18:21:55.286677Z TRACE pgcat::server: Message: D
2023-08-01T18:21:55.286681Z TRACE pgcat::server: Message: C
2023-08-01T18:21:55.286684Z TRACE pgcat::server: Message: Z
2023-08-01T18:21:55.286727Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:21:55.286746Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:21:55.286750Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:21:55.286756Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:21:55.286782Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:21:55.286806Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:21:55.286823Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:21:55.286842Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 5012, query_count: 5012, bytes_received: 331106, bytes_sent: 310606, xact_time: 0, query_time: 20, wait_time: 108000, errors: 0 }, current: AddressStatFields { xact_count: 5012, query_count: 5012, bytes_received: 331063, bytes_sent: 310570, xact_time: 0, query_time: 20, wait_time: 108000, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time:
0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:21:55.286867Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:21:55.286871Z DEBUG pgcat::client: Client 127.0.0.1:37322 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 5012, query_count: 5012, bytes_received: 331106, bytes_sent: 310606, xact_time: 0, query_time: 20, wait_time: 108024, errors: 0 }, current: AddressStatFields { xact_count: 5012, query_count: 5012, bytes_received: 331063, bytes_sent: 310570, xact_time: 0, query_time: 20, wait_time: 108024, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent:
2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:21:55.286893Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:21:55.286909Z TRACE pgcat::client: Message: Q
2023-08-01T18:21:55.286926Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:21:55.286930Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:21:55.286933Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:21:55.287161Z TRACE pgcat::server: Message: T
2023-08-01T18:21:55.287207Z TRACE pgcat::server: Message: D
2023-08-01T18:21:55.287211Z TRACE pgcat::server: Message: C
2023-08-01T18:21:55.287214Z TRACE pgcat::server: Message: Z
2023-08-01T18:21:55.287277Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:21:55.287296Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:21:55.287300Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:21:55.287306Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:21:55.287322Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:21:55.287350Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:21:55.287371Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:21:55.287378Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 5013, query_count: 5013, bytes_received: 331172, bytes_sent: 310668, xact_time: 0, query_time: 20, wait_time: 108024, errors: 0 }, current: AddressStatFields { xact_count: 5013, query_count: 5013, bytes_received: 331129, bytes_sent: 310632, xact_time: 0, query_time: 20, wait_time: 108024, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time:
0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:21:55.287392Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:21:55.287396Z DEBUG pgcat::client: Client 127.0.0.1:37322 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 5013, query_count: 5013, bytes_received: 331172, bytes_sent: 310668, xact_time: 0, query_time: 20, wait_time: 108037, errors: 0 }, current: AddressStatFields { xact_count: 5013, query_count: 5013, bytes_received: 331129, bytes_sent: 310632, xact_time: 0, query_time: 20, wait_time: 108037, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent:
2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:21:55.287430Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:21:55.287436Z TRACE pgcat::client: Message: Q
2023-08-01T18:21:55.287458Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:21:55.287481Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:21:55.287505Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:21:55.287713Z TRACE pgcat::server: Message: T
2023-08-01T18:21:55.287739Z TRACE pgcat::server: Message: D
2023-08-01T18:21:55.287743Z TRACE pgcat::server: Message: C
2023-08-01T18:21:55.287746Z TRACE pgcat::server: Message: Z
2023-08-01T18:21:55.287776Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:21:55.287781Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:21:55.287784Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:21:55.287792Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:21:55.287850Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:21:55.287882Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:21:55.287901Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:21:55.287909Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 5014, query_count: 5014, bytes_received: 331238, bytes_sent: 310730, xact_time: 0, query_time: 20, wait_time: 108037, errors: 0 }, current: AddressStatFields { xact_count: 5014, query_count: 5014, bytes_received: 331195, bytes_sent: 310694, xact_time: 0, query_time: 20, wait_time: 108037, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time:
0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:21:55.287922Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:21:55.287925Z DEBUG pgcat::client: Client 127.0.0.1:37322 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 5014, query_count: 5014, bytes_received: 331238, bytes_sent: 310730, xact_time: 0, query_time: 20, wait_time: 108049, errors: 0 }, current: AddressStatFields { xact_count: 5014, query_count: 5014, bytes_received: 331195, bytes_sent: 310694, xact_time: 0, query_time: 20, wait_time: 108049, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent:
2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
^C2023-08-01T18:21:55.287933Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:21:55.287983Z TRACE pgcat::client: Message: Q
2023-08-01T18:21:55.287987Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:21:55.287990Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:21:55.287992Z DEBUG pgcat::client: Sending Q to server

with --protocol simple, slow:

Details

2023-08-01T18:23:46.384718Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 131, query_count: 131, bytes_received: 8737, bytes_sent: 9227, xact_time: 0, query_time: 3041, wait_time: 8486, errors: 0 }, current: AddressStatFields { xact_count: 131, query_count: 131, bytes_received: 8694, bytes_sent: 9191, xact_time: 0, query_time: 3041, wait_time: 8486, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.384749Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.384754Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 131, query_count: 131, bytes_received: 8737, bytes_sent: 9227, xact_time: 0, query_time: 3041, wait_time: 8515, errors: 0 }, current: AddressStatFields { xact_count: 131, query_count: 131, bytes_received: 8694, bytes_sent: 9191, xact_time: 0, query_time: 3041, wait_time: 8515, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.384762Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.384765Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.384767Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.384769Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.384771Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.433310Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.433387Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.433396Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.433403Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.433472Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.433512Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.433520Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.433527Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.433591Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.433738Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.433801Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.433820Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.433832Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 132, query_count: 132, bytes_received: 8803, bytes_sent: 9294, xact_time: 0, query_time: 3089, wait_time: 8515, errors: 0 }, current: AddressStatFields { xact_count: 132, query_count: 132, bytes_received: 8760, bytes_sent: 9258, xact_time: 0, query_time: 3089, wait_time: 8515, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.433888Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.433899Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 132, query_count: 132, bytes_received: 8803, bytes_sent: 9294, xact_time: 0, query_time: 3089, wait_time: 8568, errors: 0 }, current: AddressStatFields { xact_count: 132, query_count: 132, bytes_received: 8760, bytes_sent: 9258, xact_time: 0, query_time: 3089, wait_time: 8568, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.433946Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.433954Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.433959Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.433967Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.433972Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.434458Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.434508Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.434516Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.434521Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.434569Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.434607Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.434643Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.434651Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.434703Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.434728Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.434750Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.434783Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.434793Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 133, query_count: 133, bytes_received: 8869, bytes_sent: 9361, xact_time: 0, query_time: 3089, wait_time: 8568, errors: 0 }, current: AddressStatFields { xact_count: 133, query_count: 133, bytes_received: 8826, bytes_sent: 9325, xact_time: 0, query_time: 3089, wait_time: 8568, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.434813Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.434846Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 133, query_count: 133, bytes_received: 8869, bytes_sent: 9361, xact_time: 0, query_time: 3089, wait_time: 8586, errors: 0 }, current: AddressStatFields { xact_count: 133, query_count: 133, bytes_received: 8826, bytes_sent: 9325, xact_time: 0, query_time: 3089, wait_time: 8586, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.434868Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.434878Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.434882Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.434890Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.434899Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.483168Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.483204Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.483208Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.483212Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.483245Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.483265Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.483269Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.483272Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.483305Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.483410Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.483446Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.483450Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.483455Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 134, query_count: 134, bytes_received: 8935, bytes_sent: 9428, xact_time: 0, query_time: 3137, wait_time: 8586, errors: 0 }, current: AddressStatFields { xact_count: 134, query_count: 134, bytes_received: 8892, bytes_sent: 9392, xact_time: 0, query_time: 3137, wait_time: 8586, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.483488Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.483493Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 134, query_count: 134, bytes_received: 8935, bytes_sent: 9428, xact_time: 0, query_time: 3137, wait_time: 8617, errors: 0 }, current: AddressStatFields { xact_count: 134, query_count: 134, bytes_received: 8892, bytes_sent: 9392, xact_time: 0, query_time: 3137, wait_time: 8617, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.483502Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.483505Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.483507Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.483509Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.483515Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.483956Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.483984Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.483988Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.483991Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.484023Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.484043Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.484046Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.484049Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.484078Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.484154Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.484183Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.484187Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.484191Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 135, query_count: 135, bytes_received: 9001, bytes_sent: 9495, xact_time: 0, query_time: 3137, wait_time: 8617, errors: 0 }, current: AddressStatFields { xact_count: 135, query_count: 135, bytes_received: 8958, bytes_sent: 9459, xact_time: 0, query_time: 3137, wait_time: 8617, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.484203Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.484206Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 135, query_count: 135, bytes_received: 9001, bytes_sent: 9495, xact_time: 0, query_time: 3137, wait_time: 8628, errors: 0 }, current: AddressStatFields { xact_count: 135, query_count: 135, bytes_received: 8958, bytes_sent: 9459, xact_time: 0, query_time: 3137, wait_time: 8628, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.484227Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.484231Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.484234Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.484237Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.484239Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.533376Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.533504Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.533517Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.533527Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.533617Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.533683Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.533743Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.533800Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.533906Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.534066Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.534158Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.534263Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.534281Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 136, query_count: 136, bytes_received: 9067, bytes_sent: 9562, xact_time: 0, query_time: 3186, wait_time: 8628, errors: 0 }, current: AddressStatFields { xact_count: 136, query_count: 136, bytes_received: 9024, bytes_sent: 9526, xact_time: 0, query_time: 3186, wait_time: 8628, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.534366Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.534429Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 136, query_count: 136, bytes_received: 9067, bytes_sent: 9562, xact_time: 0, query_time: 3186, wait_time: 8707, errors: 0 }, current: AddressStatFields { xact_count: 136, query_count: 136, bytes_received: 9024, bytes_sent: 9526, xact_time: 0, query_time: 3186, wait_time: 8707, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.534505Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.534567Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.534580Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.534587Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.534636Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.535000Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.535060Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.535072Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.535129Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.535259Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.535314Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.535370Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.535433Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.535519Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.535599Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.535674Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.535736Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.535796Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 137, query_count: 137, bytes_received: 9133, bytes_sent: 9629, xact_time: 0, query_time: 3186, wait_time: 8707, errors: 0 }, current: AddressStatFields { xact_count: 137, query_count: 137, bytes_received: 9090, bytes_sent: 9593, xact_time: 0, query_time: 3186, wait_time: 8707, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.535880Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.535936Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 137, query_count: 137, bytes_received: 9133, bytes_sent: 9629, xact_time: 0, query_time: 3186, wait_time: 8787, errors: 0 }, current: AddressStatFields { xact_count: 137, query_count: 137, bytes_received: 9090, bytes_sent: 9593, xact_time: 0, query_time: 3186, wait_time: 8787, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.535969Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.535978Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.536034Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.536095Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.536151Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.583564Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.583639Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.583649Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.583657Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.583726Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.583772Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.583781Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.583823Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.583927Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.584005Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.584072Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.584113Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.584182Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 138, query_count: 138, bytes_received: 9199, bytes_sent: 9696, xact_time: 0, query_time: 3233, wait_time: 8787, errors: 0 }, current: AddressStatFields { xact_count: 138, query_count: 138, bytes_received: 9156, bytes_sent: 9660, xact_time: 0, query_time: 3233, wait_time: 8787, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.584251Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.584263Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 138, query_count: 138, bytes_received: 9199, bytes_sent: 9696, xact_time: 0, query_time: 3233, wait_time: 8853, errors: 0 }, current: AddressStatFields { xact_count: 138, query_count: 138, bytes_received: 9156, bytes_sent: 9660, xact_time: 0, query_time: 3233, wait_time: 8853, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.584314Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.584326Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.584366Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.584408Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.584449Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.584946Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.584990Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.585000Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.585006Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.585056Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.585097Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.585139Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.585149Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.585206Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.585260Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.585279Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.585317Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.585328Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 139, query_count: 139, bytes_received: 9265, bytes_sent: 9763, xact_time: 0, query_time: 3233, wait_time: 8853, errors: 0 }, current: AddressStatFields { xact_count: 139, query_count: 139, bytes_received: 9222, bytes_sent: 9727, xact_time: 0, query_time: 3233, wait_time: 8853, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.585381Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.585433Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 139, query_count: 139, bytes_received: 9265, bytes_sent: 9763, xact_time: 0, query_time: 3233, wait_time: 8902, errors: 0 }, current: AddressStatFields { xact_count: 139, query_count: 139, bytes_received: 9222, bytes_sent: 9727, xact_time: 0, query_time: 3233, wait_time: 8902, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.585483Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.585524Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.585565Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.585579Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.585584Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.633381Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.633467Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.633526Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.633585Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.633714Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.633772Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.633785Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.633838Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.633932Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.634029Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.634123Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.634179Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.634196Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 140, query_count: 140, bytes_received: 9331, bytes_sent: 9830, xact_time: 0, query_time: 3281, wait_time: 8902, errors: 0 }, current: AddressStatFields { xact_count: 140, query_count: 140, bytes_received: 9288, bytes_sent: 9794, xact_time: 0, query_time: 3281, wait_time: 8902, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.634282Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.634339Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 140, query_count: 140, bytes_received: 9331, bytes_sent: 9830, xact_time: 0, query_time: 3281, wait_time: 8982, errors: 0 }, current: AddressStatFields { xact_count: 140, query_count: 140, bytes_received: 9288, bytes_sent: 9794, xact_time: 0, query_time: 3281, wait_time: 8982, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.634415Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.634470Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.634483Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.634534Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.634588Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.635108Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.635166Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.635179Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.635231Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.635342Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.635398Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.635453Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.635508Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.635587Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.635659Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.635685Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.635735Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.635790Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 141, query_count: 141, bytes_received: 9397, bytes_sent: 9897, xact_time: 0, query_time: 3281, wait_time: 8982, errors: 0 }, current: AddressStatFields { xact_count: 141, query_count: 141, bytes_received: 9354, bytes_sent: 9861, xact_time: 0, query_time: 3281, wait_time: 8982, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.635863Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.635919Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 141, query_count: 141, bytes_received: 9397, bytes_sent: 9897, xact_time: 0, query_time: 3281, wait_time: 9052, errors: 0 }, current: AddressStatFields { xact_count: 141, query_count: 141, bytes_received: 9354, bytes_sent: 9861, xact_time: 0, query_time: 3281, wait_time: 9052, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.635996Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.636011Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.636060Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.636116Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.636134Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.683456Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.683548Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.683561Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.683571Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.683698Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.683720Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.683772Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.683792Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.683888Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.683985Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.684068Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.684124Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.684183Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 142, query_count: 142, bytes_received: 9463, bytes_sent: 9964, xact_time: 0, query_time: 3328, wait_time: 9052, errors: 0 }, current: AddressStatFields { xact_count: 142, query_count: 142, bytes_received: 9420, bytes_sent: 9928, xact_time: 0, query_time: 3328, wait_time: 9052, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.684266Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.684282Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 142, query_count: 142, bytes_received: 9463, bytes_sent: 9964, xact_time: 0, query_time: 3328, wait_time: 9132, errors: 0 }, current: AddressStatFields { xact_count: 142, query_count: 142, bytes_received: 9420, bytes_sent: 9928, xact_time: 0, query_time: 3328, wait_time: 9132, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.684354Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.684409Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.684460Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.684473Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.684480Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.684937Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.684999Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.685011Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.685065Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.685181Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.685238Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.685250Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.685258Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.685374Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.685450Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.685521Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.685576Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.685590Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 143, query_count: 143, bytes_received: 9529, bytes_sent: 10031, xact_time: 0, query_time: 3328, wait_time: 9132, errors: 0 }, current: AddressStatFields { xact_count: 143, query_count: 143, bytes_received: 9486, bytes_sent: 9995, xact_time: 0, query_time: 3328, wait_time: 9132, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors:
0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.685661Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.685719Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 143, query_count: 143, bytes_received: 9529, bytes_sent: 10031, xact_time: 0, query_time: 3328, wait_time: 9197, errors: 0 }, current: AddressStatFields { xact_count: 143, query_count: 143, bytes_received: 9486, bytes_sent: 9995, xact_time: 0, query_time: 3328, wait_time: 9197, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.685752Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.685760Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.685808Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.685865Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.685919Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.733763Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.733862Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.733964Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.734025Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.734135Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.734193Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.734249Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.734306Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.734404Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.734490Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.734572Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.734628Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.734689Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 144, query_count: 144, bytes_received: 9595, bytes_sent: 10098, xact_time: 0, query_time: 3376, wait_time: 9197, errors: 0 }, current: AddressStatFields { xact_count: 144, query_count: 144, bytes_received: 9552, bytes_sent: 10062, xact_time: 0, query_time: 3376, wait_time: 9197, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.734773Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.734834Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 144, query_count: 144, bytes_received: 9595, bytes_sent: 10098, xact_time: 0, query_time: 3376, wait_time: 9278, errors: 0 }, current: AddressStatFields { xact_count: 144, query_count: 144, bytes_received: 9552, bytes_sent: 10062, xact_time: 0, query_time: 3376, wait_time: 9278, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.734905Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.734918Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.734967Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.734985Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.735036Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.735461Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.735536Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.735549Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.735605Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.735739Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.735797Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.735853Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.735909Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.735999Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.736082Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.736160Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.736216Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.736273Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 145, query_count: 145, bytes_received: 9661, bytes_sent: 10165, xact_time: 0, query_time: 3376, wait_time: 9278, errors: 0 }, current: AddressStatFields { xact_count: 145, query_count: 145, bytes_received: 9618, bytes_sent: 10129, xact_time: 0, query_time: 3376, wait_time: 9278, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.736354Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.736369Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 145, query_count: 145, bytes_received: 9661, bytes_sent: 10165, xact_time: 0, query_time: 3376, wait_time: 9356, errors: 0 }, current: AddressStatFields { xact_count: 145, query_count: 145, bytes_received: 9618, bytes_sent: 10129, xact_time: 0, query_time: 3376, wait_time: 9356, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.736438Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.736456Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.736506Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.736524Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.736577Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.783649Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.783737Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.783750Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.783761Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.783892Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.783910Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.783962Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.783980Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.784111Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.784212Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.784296Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.784352Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.784412Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 146, query_count: 146, bytes_received: 9727, bytes_sent: 10232, xact_time: 0, query_time: 3423, wait_time: 9356, errors: 0 }, current: AddressStatFields { xact_count: 146, query_count: 146, bytes_received: 9684, bytes_sent: 10196, xact_time: 0, query_time: 3423, wait_time: 9356, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.784497Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.784512Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 146, query_count: 146, bytes_received: 9727, bytes_sent: 10232, xact_time: 0, query_time: 3423, wait_time: 9437, errors: 0 }, current: AddressStatFields { xact_count: 146, query_count: 146, bytes_received: 9684, bytes_sent: 10196, xact_time: 0, query_time: 3423, wait_time: 9437, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.784584Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.784638Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.784651Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.784659Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.784711Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.785315Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.785479Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.785550Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.785623Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.785773Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.785888Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.785957Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.786026Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.786135Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.786236Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.786333Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.786393Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.786409Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 147, query_count: 147, bytes_received: 9793, bytes_sent: 10299, xact_time: 0, query_time: 3423, wait_time: 9437, errors: 0 }, current: AddressStatFields { xact_count: 147, query_count: 147, bytes_received: 9750, bytes_sent: 10263, xact_time: 0, query_time: 3423, wait_time: 9437, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.786484Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.786540Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 147, query_count: 147, bytes_received: 9793, bytes_sent: 10299, xact_time: 0, query_time: 3423, wait_time: 9506, errors: 0 }, current: AddressStatFields { xact_count: 147, query_count: 147, bytes_received: 9750, bytes_sent: 10263, xact_time: 0, query_time: 3423, wait_time: 9506, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.786611Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.786666Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.786721Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.786733Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.786740Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.833285Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.833374Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.833388Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.833447Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.833591Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.833649Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.833662Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.833830Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.834017Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.834153Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.834303Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.834361Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.834376Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 148, query_count: 148, bytes_received: 9862, bytes_sent: 10366, xact_time: 0, query_time: 3469, wait_time: 9506, errors: 0 }, current: AddressStatFields { xact_count: 148, query_count: 148, bytes_received: 9819, bytes_sent: 10330, xact_time: 0, query_time: 3469, wait_time: 9506, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.834462Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.834479Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 148, query_count: 148, bytes_received: 9862, bytes_sent: 10366, xact_time: 0, query_time: 3469, wait_time: 9586, errors: 0 }, current: AddressStatFields { xact_count: 148, query_count: 148, bytes_received: 9819, bytes_sent: 10330, xact_time: 0, query_time: 3469, wait_time: 9586, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.834549Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.834561Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.834568Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.834619Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.834635Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.835220Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.835292Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.835306Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.835315Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.835445Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.835502Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.835515Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.835524Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.835695Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.835778Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.835855Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.835909Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.835924Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 149, query_count: 149, bytes_received: 9928, bytes_sent: 10433, xact_time: 0, query_time: 3469, wait_time: 9586, errors: 0 }, current: AddressStatFields { xact_count: 149, query_count: 149, bytes_received: 9885, bytes_sent: 10397, xact_time: 0, query_time: 3469, wait_time: 9586, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.836000Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.836058Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 149, query_count: 149, bytes_received: 9928, bytes_sent: 10433, xact_time: 0, query_time: 3469, wait_time: 9656, errors: 0 }, current: AddressStatFields { xact_count: 149, query_count: 149, bytes_received: 9885, bytes_sent: 10397, xact_time: 0, query_time: 3469, wait_time: 9656, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.836133Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.836149Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.836200Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.836255Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.836267Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.883043Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.883107Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.883149Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.883188Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.883250Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.883261Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.883295Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.883305Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.883368Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.883435Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.883500Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.883523Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.883532Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 150, query_count: 150, bytes_received: 9994, bytes_sent: 10500, xact_time: 0, query_time: 3515, wait_time: 9656, errors: 0 }, current: AddressStatFields { xact_count: 150, query_count: 150, bytes_received: 9951, bytes_sent: 10464, xact_time: 0, query_time: 3515, wait_time: 9656, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok
2023-08-01T18:23:46.883572Z DEBUG pgcat::client: Got connection from pool
2023-08-01T18:23:46.883580Z DEBUG pgcat::client: Client 127.0.0.1:41718 talking to server Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres",
pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 150, query_count: 150, bytes_received: 9994, bytes_sent: 10500, xact_time: 0, query_time: 3515, wait_time: 9694, errors: 0 }, current: AddressStatFields { xact_count: 150, query_count: 150, bytes_received: 9951, bytes_sent: 10464, xact_time: 0, query_time: 3515, wait_time: 9694, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } }
2023-08-01T18:23:46.883607Z DEBUG pgcat::client: Prepared statement active: None
2023-08-01T18:23:46.883613Z TRACE pgcat::client: Message: Q
2023-08-01T18:23:46.883616Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.883619Z DEBUG pgcat::client: Sending query to server
2023-08-01T18:23:46.883621Z DEBUG pgcat::client: Sending Q to server
2023-08-01T18:23:46.883858Z TRACE pgcat::server: Message: T
2023-08-01T18:23:46.883887Z TRACE pgcat::server: Message: D
2023-08-01T18:23:46.883892Z TRACE pgcat::server: Message: C
2023-08-01T18:23:46.883896Z TRACE pgcat::server: Message: Z
2023-08-01T18:23:46.883928Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.883954Z DEBUG pgcat::client: Releasing server back into the pool
2023-08-01T18:23:46.883959Z DEBUG pgcat::server: Server in transaction: false
2023-08-01T18:23:46.883963Z DEBUG pgcat::server: Cache maintenance run
2023-08-01T18:23:46.883997Z TRACE pgcat::client: Client idle, waiting for message, transaction mode: true
2023-08-01T18:23:46.884015Z DEBUG pgcat::query_router: Using pool settings, query_parser_enabled: false
2023-08-01T18:23:46.884047Z DEBUG pgcat::query_router: Regular query, not a command
2023-08-01T18:23:46.884052Z DEBUG pgcat::client: Waiting for connection from pool
2023-08-01T18:23:46.884056Z DEBUG pgcat::pool: Address { id: 0, host: "127.0.0.1", port: 5432, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "pgml", mirrors: [], stats: AddressStats { total: AddressStatFields { xact_count: 151, query_count: 151, bytes_received: 10060, bytes_sent: 10567, xact_time: 0, query_time: 3515, wait_time: 9694, errors: 0 }, current: AddressStatFields { xact_count: 151, query_count: 151, bytes_received: 10017, bytes_sent: 10531, xact_time: 0, query_time: 3515, wait_time: 9694, errors: 0 }, averages: AddressStatFields { xact_count: 0, query_count: 0, bytes_received: 2, bytes_sent: 2, xact_time: 0, query_time: 0, wait_time: 0, errors: 0 }, averages_updated: false } } is ok

JelteF · 2023-08-01T18:25:38Z

It seems to be between sending something to the server, and waiting for the response. It's waiting A LOT longer there in the slow case.

levkk · 2023-08-02T00:41:15Z

I can finally reproduce this on my Ubuntu machine. The culprit is maintain_cache. If you comment this out, the performance is back to expected levels. Will investigate.

levkk · 2023-08-02T00:48:03Z

Oh wow. This was really a blunder. Fixed in aefcf42. Could you confirm on your end? Thanks!

The cause was the prepared statement maintenance cache loop issuing a Flush to Postgres on each iteration (each transaction). This only happened in transaction mode, which explains why the performance tanked in transaction mode but not in session mode.

JelteF · 2023-08-02T08:59:03Z

Yes pulling the latest main resolved the perf issue for me.

JelteF · 2023-08-02T08:59:27Z

Seem like a patch release is probably in order though.

levkk added a commit that referenced this issue Aug 2, 2023

Fix for #534 and #535

aefcf42

JelteF closed this as completed Aug 2, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

JelteF commented Jul 29, 2023 •

edited

Loading

levkk commented Jul 29, 2023 •

edited

Loading

JelteF commented Jul 29, 2023

levkk commented Jul 29, 2023

JelteF commented Jul 29, 2023

levkk commented Jul 29, 2023

levkk commented Jul 29, 2023 •

edited

Loading

JelteF commented Jul 29, 2023 •

edited

Loading

JelteF commented Jul 29, 2023

levkk commented Jul 29, 2023 •

edited

Loading

JelteF commented Jul 31, 2023

JelteF commented Aug 1, 2023

JelteF commented Aug 1, 2023

levkk commented Aug 1, 2023

levkk commented Aug 1, 2023

JelteF commented Aug 1, 2023

JelteF commented Aug 1, 2023

JelteF commented Aug 1, 2023

JelteF commented Aug 1, 2023

levkk commented Aug 2, 2023 •

edited

Loading

levkk commented Aug 2, 2023 •

edited

Loading

JelteF commented Aug 2, 2023

JelteF commented Aug 2, 2023

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

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

Comments

JelteF commented Jul 29, 2023 • edited Loading

levkk commented Jul 29, 2023 • edited Loading

JelteF commented Jul 29, 2023

levkk commented Jul 29, 2023

JelteF commented Jul 29, 2023

levkk commented Jul 29, 2023

levkk commented Jul 29, 2023 • edited Loading

JelteF commented Jul 29, 2023 • edited Loading

JelteF commented Jul 29, 2023

levkk commented Jul 29, 2023 • edited Loading

JelteF commented Jul 31, 2023

JelteF commented Aug 1, 2023

JelteF commented Aug 1, 2023

levkk commented Aug 1, 2023

levkk commented Aug 1, 2023

JelteF commented Aug 1, 2023

JelteF commented Aug 1, 2023

JelteF commented Aug 1, 2023

JelteF commented Aug 1, 2023

levkk commented Aug 2, 2023 • edited Loading

levkk commented Aug 2, 2023 • edited Loading

JelteF commented Aug 2, 2023

JelteF commented Aug 2, 2023

JelteF commented Jul 29, 2023 •

edited

Loading

levkk commented Jul 29, 2023 •

edited

Loading

levkk commented Jul 29, 2023 •

edited

Loading

JelteF commented Jul 29, 2023 •

edited

Loading

levkk commented Jul 29, 2023 •

edited

Loading

levkk commented Aug 2, 2023 •

edited

Loading

levkk commented Aug 2, 2023 •

edited

Loading