On Wed, 16 Sep 2020 at 17:43, Tom Lane <t...@sss.pgh.pa.us> wrote:
>
> Hmm ... the thread leading up to 0921554 indicates that the performance
> penalty of update_process_title=on is just ridiculously large on Windows.
> Maybe those numbers are not relevant to crash recovery WAL-application,
> but it might be smart to actually measure that not just assume it.
I had a go at measuring this on Windows and couldn't really detect any
slowdown from running update_process_title on vs off. Average over 3
runs with update_process_title = off was 94.38 s, switched on the
average was 93.81 s. (Some noise there)
Adding a bit of logging shows that the process title was set 225
times. Once setting it to an empty string then once for each of the
224 segments replayed.
Also, from a pgbench -s test with update_process_title on and again
with off I see 9343 tps vs 11969 tps. The process title is changed
twice for each query, once to set it to the query and once to set it
to "idle". Doing a bit of maths there is seems that setting the
process title takes about 15 microseconds per call. So it would have
taken about 3.38 milliseconds to set the process title 225 times for
recovery, or if you prefer, 0.003609% additional overhead.
I don't think we'll notice.
David
Details:
Added PANIC to end of recovery so I could repeat this using identical WAL.
pg_ctl stop -D ../data -m smart
pg_ctl start -D ../data -l pg.log -w
psql -c "drop table if exists t1;" postgres > NUL
psql -c "create table t1 (a int primary key, b int not null) with (fillfactor =
85);" postgres > NUL
psql -c "insert into t1 select x,0 from generate_series(1,10000000) x;"
postgres > NUL
psql -c "drop table if exists log_wal;" postgres > NUL
psql -c "create table log_wal (lsn pg_lsn not null);" postgres > NUL
psql -c "insert into log_wal values(pg_current_wal_lsn());" postgres > NUL
pgbench -n -f update.sql -t 3000000 -c 4 -j 4 -M prepared postgres
psql -c "select 'Used ' || pg_size_pretty(pg_wal_lsn_diff(pg_current_wal_lsn(),
lsn)) || ' of WAL' from log_wal limit 1;" postgres
pg_ctl stop -D ../data -m immediate -w
echo Starting Postgres...
pg_ctl start -D ../data -l pg.log
2020-09-17 17:04:49.902 NZST [16496] LOG: redo done at 0/E170FFD8 system
usage: CPU: user: 74.21 s, system: 17.39 s, elapsed: 94.71 s
2020-09-17 17:06:46.685 NZST [4884] LOG: redo done at 0/E170FFD8 system usage:
CPU: user: 74.75 s, system: 16.56 s, elapsed: 94.56 s
2020-09-17 17:10:21.546 NZST [10272] LOG: redo done at 0/E170FFD8 system
usage: CPU: user: 73.62 s, system: 17.25 s, elapsed: 93.89 s
update_process_title = on
2020-09-17 17:12:45.246 NZST [14744] LOG: redo done at 0/E170FFD8 system
usage: CPU: user: 73.62 s, system: 17.07 s, elapsed: 93.88 s
2020-09-17 17:14:30.303 NZST [15692] LOG: redo done at 0/E170FFD8 system
usage: CPU: user: 73.50 s, system: 16.53 s, elapsed: 93.75 s
2020-09-17 17:16:10.040 NZST [3912] LOG: redo done at 0/E170FFD8 system usage:
CPU: user: 73.95 s, system: 16.65 s, elapsed: 93.80 s
L:\Projects\Postgres\install\bin>pgbench -S -T 60 postgres
starting vacuum...end.
transaction type: <builtin: select only>
scaling factor: 1
query mode: simple
number of clients: 1
number of threads: 1
duration: 60 s
number of transactions actually processed: 560380
latency average = 0.107 ms
tps = 9339.576713 (including connections establishing)
tps = 9343.026904 (excluding connections establishing)
update_process_title = off
L:\Projects\Postgres\install\bin>psql -c "select pg_Reload_conf()" postgres
pg_reload_conf
----------------
t
(1 row)
L:\Projects\Postgres\install\bin>pgbench -S -T 60 postgres
starting vacuum...end.
transaction type: <builtin: select only>
scaling factor: 1
query mode: simple
number of clients: 1
number of threads: 1
duration: 60 s
number of transactions actually processed: 717872
latency average = 0.084 ms
tps = 11964.531821 (including connections establishing)
tps = 11969.342880 (excluding connections establishing)
postgres=# select (60 / (560380/717872.0)) - 60 as seconds_spent_setting_title;
NOTICE: new title = SELECT
NOTICE: new title = idle
seconds_spent_setting_title
-----------------------------
16.86270031050358685130
(1 row)
postgres=# select 16.86270031050358685130/560380.0 * 1000000 / 2 as
microseconds_per_set_process_title;
NOTICE: new title = SELECT
NOTICE: new title = idle
microseconds_per_set_process_title
------------------------------------
15.045772788557395741500000
(1 row)
postgres=# select 15.045772788557395741500000*225 / 1000.0 as
milliseconds_spent_setting_process_title_in_recovery;
NOTICE: new title = SELECT
NOTICE: new title = idle
milliseconds_spent_setting_process_title_in_recovery
------------------------------------------------------
3.385298877425414041837500
(1 row)
