Re: [PATCH] Query Jumbling for CALL and SET utility statements

On 8/31/22 8:33 AM, Drouvot, Bertrand wrote:
>
> We’ve recently seen performance impacts (LWLock contention) due to the
> lack of jumbling on procedure calls with pg_stat_statements and
> pg_stat_statements.track_utility enabled (think an application with a
> high rate of procedure calls with unique parameters for each call).

I ran some performance tests with the patch that Bertrand wrote to get
numbers. From my perspective, this patch is scoped very minimally and is
low risk; I don’t think it should need an enormous amount of validation.
It does appear to address the issues with both SET and CALL statements
that Nikolay and I respectively encountered. Honestly, this almost seems
like it was just an minor oversight in the original patch that added
support for CALL and procedures.

I used an r5.large EC2 instance running Linux and tested Bertrand’s
patch using the PostgreSQL 14.4 code base, compiled without and with
Bertrand’s patch. The difference is a lot more extreme on big servers
with lots of cores, but the difference is obvious even on a small
instance like this one.

As a side note: while I certainly don't want to build a database
primarily based on benchmarks, it's nice when benchmarks showcase the
database's strength. Without this patch, HammerDB completely falls over
in stored procedure mode, since one of the procedure arguments is a
time-based unique value on every call. Someone else at Amazon running
HammerDB was how I originally became aware of this problem.

-Jeremy

===== Setup:
$ psql -c "create procedure test(x int) as 'begin return; end' language
plpgsql;"
CREATE PROCEDURE
$ echo -e "\set x random(1,100000000) \n call test(:x)" >test-call.pgbench
$ echo -e "\set x random(1,100000000) \n set application_name=':x'"
>test-set.pgbench

===== CALL results without patch:

[postgres(at)ip-172-31-44-176 ~]$ pgbench -n -c 100 -j 100 -T15 -r -f
test-set.pgbench
pgbench (14.4)
transaction type: test-set.pgbench
scaling factor: 1
query mode: simple
number of clients: 100
number of threads: 100
duration: 15 s
number of transactions actually processed: 728748
latency average = 2.051 ms
initial connection time = 91.844 ms
tps = 48755.446492 (without initial connection time)
statement latencies in milliseconds:
0.000 \set x random(1,100000000)
2.046 set application_name=':x'

pg-14.4 rw postgres(at)postgres=# select wait_event, count(*) from
pg_stat_activity group by wait_event; \watch 1
...
Tue 30 Aug 2022 08:26:35 PM UTC (every 1s)

wait_event | count
---------------------+-------
[NULL] | 6
pg_stat_statements | 95
BgWriterMain | 1
ArchiverMain | 1
WalWriterMain | 1
AutoVacuumMain | 1
CheckpointerMain | 1
LogicalLauncherMain | 1
(8 rows)
...

===== CALL results with patch:

[postgres(at)ip-172-31-44-176 ~]$ pgbench -n -c 100 -j 100 -T15 -r -f
test-call.pgbench
pgbench (14.4)
transaction type: test-call.pgbench
scaling factor: 1
query mode: simple
number of clients: 100
number of threads: 100
duration: 15 s
number of transactions actually processed: 1098776
latency average = 1.361 ms
initial connection time = 89.002 ms
tps = 73491.904878 (without initial connection time)
statement latencies in milliseconds:
0.000 \set x random(1,100000000)
1.383 call test(:x)

pg-14.4 rw postgres(at)postgres=# select wait_event, count(*) from
pg_stat_activity group by wait_event; \watch 1
...
Tue 30 Aug 2022 08:42:51 PM UTC (every 1s)

wait_event | count
---------------------+-------
[NULL] | 99
BgWriterHibernate | 1
ArchiverMain | 1
WalWriterMain | 1
AutoVacuumMain | 1
CheckpointerMain | 1
ClientRead | 2
LogicalLauncherMain | 1
(8 rows)
...

===== SET results without patch:

[postgres(at)ip-172-31-44-176 ~]$ pgbench -n -c 100 -j 100 -T15 -r -f
test-set.pgbench
pgbench (14.4)
transaction type: test-set.pgbench
scaling factor: 1
query mode: simple
number of clients: 100
number of threads: 100
duration: 15 s
number of transactions actually processed: 728748
latency average = 2.051 ms
initial connection time = 91.844 ms
tps = 48755.446492 (without initial connection time)
statement latencies in milliseconds:
0.000 \set x random(1,100000000)
2.046 set application_name=':x'

pg-14.4 rw postgres(at)postgres=# select wait_event, count(*) from
pg_stat_activity group by wait_event; \watch 1
...
Tue 30 Aug 2022 08:26:35 PM UTC (every 1s)

wait_event | count
---------------------+-------
[NULL] | 6
pg_stat_statements | 95
BgWriterMain | 1
ArchiverMain | 1
WalWriterMain | 1
AutoVacuumMain | 1
CheckpointerMain | 1
LogicalLauncherMain | 1
(8 rows)
...

===== SET results with patch:

[postgres(at)ip-172-31-44-176 ~]$ pgbench -n -c 100 -j 100 -T15 -r -f
test-set.pgbench
pgbench (14.4)
transaction type: test-set.pgbench
scaling factor: 1
query mode: simple
number of clients: 100
number of threads: 100
duration: 15 s
number of transactions actually processed: 1178844
latency average = 1.268 ms
initial connection time = 89.159 ms
tps = 78850.178814 (without initial connection time)
statement latencies in milliseconds:
0.000 \set x random(1,100000000)
1.270 set application_name=':x'

pg-14.4 rw postgres(at)postgres=# select wait_event, count(*) from
pg_stat_activity group by wait_event; \watch 1
...
Tue 30 Aug 2022 08:44:30 PM UTC (every 1s)

wait_event | count
---------------------+-------
[NULL] | 101
BgWriterHibernate | 1
ArchiverMain | 1
WalWriterMain | 1
AutoVacuumMain | 1
CheckpointerMain | 1
LogicalLauncherMain | 1
(7 rows)
...

--
Jeremy Schneider
Database Engineer
Amazon Web Services