Re: snapbuild woes

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.

Erik Rijkers