Re: snapbuild woes

On 09/05/17 19:54, Erik Rijkers wrote:
> On 2017-05-09 11:50, Petr Jelinek wrote:
>
>> I rebased the above mentioned patch to apply to the patches Andres sent,
>> if you could try to add it on top of what you have and check if it still
>> fails, that would be helpful.
>
> It still fails.
>
> With these patches
>
> - 0001-WIP-Fix-off-by-one-around-GetLastImportantRecPtr.patch+
> - 00002-WIP-Possibly-more-robust-snapbuild-approach.patch +
> - fix-statistics-reporting-in-logical-replication-work.patch +
> - Skip-unnecessary-snapshot-builds.patch
>
> built again on top of 44c528810a1 ( so I had to add the
> 'fix-statistics-rep*' patch because without it I immediately got that
> Assertion failure again ).
>
> As always most runs succeed (especially on this large 192GB 16-core
> server).
>
> But attached is an output file of a number of runs of my
> pgbench_derail2.sh test.
>
> Overal result:
>
> -- out_20170509_1635.txt
> 3 -- pgbench -c 64 -j 8 -T 900 -P 180 -n -- scale 25
> 2 -- All is well.
> 1 -- Not good, but breaking out of wait (21 times no change)
>
> I broke it off after iteration 4, so 5 never ran, and
> iteration 1 failed due to a mistake in the harness (somethind stupid I
> did) - not interesting.
>
> iteration 2 succeeds. (eventually has 'replica ok')
>
> iteration 3 succeeds. (eventually has 'replica ok')
>
> iteration 4 fails.
> Just after 'alter subscription sub1 enable' I caught (as is usual)
> pg_stat_replication.state as 'catchup'. So far so good.
> After the 15-minute pgbench run pg_stat_replication has only 2
> 'startup' lines (and none 'catchup' or 'streaming'):
>
> port | pg_stat_replication | pid | wal | replay_loc | diff |
> ?column? | state | app | sync_state
> 6972 | pg_stat_replication | 108349 | 19/8FBCC248 | | |
> | startup | derail2 | async
> 6972 | pg_stat_replication | 108351 | 19/8FBCC248 | | |
> | startup | derail2 | async
>
> (that's from:
> select $port1 as port,'pg_stat_replication' as pg_stat_replication, pid
> , pg_current_wal_location() wal, replay_location replay_loc,
> pg_current_wal_location() - replay_location as diff
> , pg_current_wal_location() <= replay_location
> , state, application_name as app, sync_state
> from pg_stat_replication
> )
>
> This remains in this state for as long as my test-programs lets it
> (i.e., 20 x 30s, or something like that, and then the loop is exited);
> in the ouput file it says: 'Not good, but breaking out of wait'
>
> Below is the accompanying ps (with the 2 'deranged senders' as Jeff
> Janes would surely call them):
>
>
> UID PID PPID C STIME TTY STAT TIME CMD
> rijkers 107147 1 0 17:11 pts/35 S+ 0:00
> /var/data1/pg_stuff/pg_installations/pgsql.logical_replication2/bin/postgres
> -D /var/data1/pg_stuff/pg_installations
> rijkers 107149 107147 0 17:11 ? Ss 0:00 \_ postgres:
> logger process
> rijkers 107299 107147 0 17:11 ? Ss 0:01 \_ postgres:
> checkpointer process
> rijkers 107300 107147 0 17:11 ? Ss 0:00 \_ postgres:
> writer process
> rijkers 107301 107147 0 17:11 ? Ss 0:00 \_ postgres: wal
> writer process
> rijkers 107302 107147 0 17:11 ? Ss 0:00 \_ postgres:
> autovacuum launcher process
> rijkers 107303 107147 0 17:11 ? Ss 0:00 \_ postgres: stats
> collector process
> rijkers 107304 107147 0 17:11 ? Ss 0:00 \_ postgres:
> bgworker: logical replication launcher
> rijkers 108348 107147 0 17:12 ? Ss 0:01 \_ postgres:
> bgworker: logical replication worker for subscription 70310 sync 70293
> rijkers 108350 107147 0 17:12 ? Ss 0:00 \_ postgres:
> bgworker: logical replication worker for subscription 70310 sync 70298
> rijkers 107145 1 0 17:11 pts/35 S+ 0:02
> /var/data1/pg_stuff/pg_installations/pgsql.logical_replication/bin/postgres
> -D /var/data1/pg_stuff/pg_installations
> rijkers 107151 107145 0 17:11 ? Ss 0:00 \_ postgres:
> logger process
> rijkers 107160 107145 0 17:11 ? Ss 0:08 \_ postgres:
> checkpointer process
> rijkers 107161 107145 0 17:11 ? Ss 0:07 \_ postgres:
> writer process
> rijkers 107162 107145 0 17:11 ? Ss 0:02 \_ postgres: wal
> writer process
> rijkers 107163 107145 0 17:11 ? Ss 0:00 \_ postgres:
> autovacuum launcher process
> rijkers 107164 107145 0 17:11 ? Ss 0:02 \_ postgres: stats
> collector process
> rijkers 107165 107145 0 17:11 ? Ss 0:00 \_ postgres:
> bgworker: logical replication launcher
> rijkers 108349 107145 0 17:12 ? Ss 0:27 \_ postgres: wal
> sender process rijkers [local] idle
> rijkers 108351 107145 0 17:12 ? Ss 0:26 \_ postgres: wal
> sender process rijkers [local] idle
>
> I have had no time to add (or view) any CPUinfo.
>
>

Ah okay, so this is same issue that's reported by both Masahiko Sawada
[1] and Jeff Janes [2].

[1]
https://www.postgresql.org/message-id/CAD21AoBYpyqTSw%2B%3DES%2BxXtRGMPKh%3DpKiqjNxZKnNUae0pSt9bg%40mail.gmail.com
[2]
https://www.postgresql.org/message-id/flat/CAMkU%3D1xUJKs%3D2etq2K7bmbY51Q7g853HLxJ7qEB2Snog9oRvDw%40mail.gmail.com

--
Petr Jelinek http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services