Re: prevent immature WAL streaming

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