Horton

Re: prevent immature WAL streaming

Andres Freund <andres@anarazel.de>

View thread View on postgr.es
From: Andres Freund <andres@anarazel.de>
To: Alvaro Herrera <alvherre@alvh.no-ip.org>
Cc: Tom Lane <tgl@sss.pgh.pa.us>, Andrew Dunstan <andrew@dunslane.net>, "Bossart, Nathan" <bossartn@amazon.com>, Kyotaro Horiguchi <horikyota.ntt@gmail.com>, "masao.fujii@oss.nttdata.com" <masao.fujii@oss.nttdata.com>, "pgsql-hackers@lists.postgresql.org" <pgsql-hackers@lists.postgresql.org>, "mengjuan.cmj@alibaba-inc.com" <mengjuan.cmj@alibaba-inc.com>, "Jakub.Wartak@tomtom.com" <Jakub.Wartak@tomtom.com>, Ryo Matsumura <matsumura.ryo@fujitsu.com>
Date: 2021-10-13T18:31:29Z
Lists: pgsql-hackers 
Hi,

On 2021-10-13 11:03:39 -0700, Andres Freund wrote:
> It seems that 026_overwrite_contrecord.pl test often fails under valgrind. I
> first thought that related failures on skink were due to me migrating the
> animal to a new host (and then running out of space due to a mistake in ccache
> config). But it happened again after I fixed those, and I just reproduced the
> issue locally.
> 
> It's a bit odd that we didn't start to see these failures immediately, but
> only in the last few days. I'd blame skink being migrated to a new home,
> except that I can see the issue locally.
> 
> FWIW, the way skink runs all postgres instances through valgrind is by
> replacing the postgres binary. Here's my local version of that:
> 
> andres@awork3:~/build/postgres/dev-assert/vpath$ cat tmp_install/home/andres/build/postgres/dev-assert/install/bin/postgres
> #!/bin/bash
> 
> exec /usr/bin/valgrind \
>     --quiet \
>     --error-exitcode=128 \
>     --suppressions=/home/andres/src/postgresql/src/tools/valgrind.supp \
>     --trace-children=yes --track-origins=yes --read-var-info=no \
>     --leak-check=no \
>     --run-libc-freeres=no \
>     --vgdb=no \
>     --error-markers=VALGRINDERROR-BEGIN,VALGRINDERROR-END \
>     /home/andres/build/postgres/dev-assert/vpath/tmp_install/home/andres/build/postgres/dev-assert/install/bin/postgres.orig \
>     "$@"
> 
> make -C src/test/recovery/ check PROVE_FLAGS='-v' PROVE_TESTS='t/026_overwrite_contrecord.pl' NO_TEMP_INSTALL=1
> ...
> 
> not ok 1 - 000000010000000000000002 differs from 000000010000000000000002
> 
> #   Failed test '000000010000000000000002 differs from 000000010000000000000002'

I added LSNs to the error message:
not ok 1 - 000000010000000000000002 (0/2002350) differs from 000000010000000000000002 (0/2099600)

It appears that the problem is that inbetween the determination of
rows_walsize the insert LSN moved to the next segment separately from the
insertion, presumably due to autovacuum/analayze or such.
<retries, with log_autovacuum_min_duration_statement=0, log_min_duration_statement=0>


2021-10-13 11:23:25.659 PDT [1491455] 026_overwrite_contrecord.pl LOG:  statement: insert into filler select * from generate_series(1, 1000)
2021-10-13 11:23:26.467 PDT [1491455] 026_overwrite_contrecord.pl LOG:  duration: 861.112 ms
2021-10-13 11:23:27.055 PDT [1491458] 026_overwrite_contrecord.pl LOG:  statement: select pg_current_wal_insert_lsn() - '0/0'
2021-10-13 11:23:27.357 PDT [1491458] 026_overwrite_contrecord.pl LOG:  duration: 347.888 ms
2021-10-13 11:23:27.980 PDT [1491461] 026_overwrite_contrecord.pl LOG:  statement: WITH setting AS (
	  SELECT setting::int AS wal_segsize
	    FROM pg_settings WHERE name = 'wal_segment_size'
	)
	INSERT INTO filler
	SELECT g FROM setting,
	  generate_series(1, 1000 * (wal_segsize - ((pg_current_wal_insert_lsn() - '0/0') % wal_segsize)) / 64232) g
2021-10-13 11:24:25.173 PDT [1491550] LOG:  automatic analyze of table "postgres.public.filler"
	avg read rate: 3.185 MB/s, avg write rate: 0.039 MB/s
	buffer usage: 96 hits, 731 misses, 9 dirtied
	system usage: CPU: user: 1.79 s, system: 0.00 s, elapsed: 1.81 s
2021-10-13 11:24:26.255 PDT [1491461] 026_overwrite_contrecord.pl LOG:  duration: 58360.811 ms
2021-10-13 11:24:26.857 PDT [1491557] 026_overwrite_contrecord.pl LOG:  statement: SELECT pg_current_wal_insert_lsn()
2021-10-13 11:24:27.120 PDT [1491557] 026_overwrite_contrecord.pl LOG:  duration: 300.562 ms


Hm. I guess we can disable autovac. But that's not a great solution, there
might be WAL files due to catalog access etc too.

Seems like it might be worth doing the "filling" of the segment with a loop in
a DO block instead, where the end condition is to be within some distance to
the end of the segment? With plenty headroom?


Another thing: filling a segment by inserting lots of very tiny rows is pretty
expensive. Can't we use something a bit wider? Perhaps even emit_message?

Greetings,

Andres Freund

Commits

  1. Fix determination of broken LSN in OVERWRITTEN_CONTRECORD

  2. Fix instability in 026_overwrite_contrecord.pl test.

  3. Fix typo

  4. Change recently added test code for stability

  5. Remove unstable, unnecessary test; fix typo

  6. Repair two portability oversights of new test

  7. Fix WAL replay in presence of an incomplete record

  8. Document XLOG_INCLUDE_XID a little better

  9. Revert "Avoid creating archive status ".ready" files too early"

  10. Avoid creating archive status ".ready" files too early

  11. Fix scenario where streaming standby gets stuck at a continuation record.

  12. Teach xlogreader to follow timeline switches

  13. Forbid using pg_xlogfile_name() and pg_xlogfile_name_offset() during