Re: Logical replication existing data copy

Hi,

as the logical replication patch is progressing closer to integration it
seems to be good time to revisit what to do about preexisting data.

This patch implements data synchronization for the logical replication.
It works both for initial setup of subscription as well as for tables
added later to replication when the subscription is already active.

There is new catalog pg_subscription_rel which track
synchronization/replication state of each table that is subscribed via
publications.

From the user perspective it adds some additional options/clauses to
CREATE/ALTER SUBSCRIPTION namely:
- CREATE SUBSCRIPTION ... [ WITH (COPY DATA | NOCOPY DATA) ] where user
can specify if initial data should be copied or not, with the default COPY.
- ALTER SUBSCRIPTION ... REFRESH PUBLICATION [ WITH (COPY DATA | NOCOPY
DATA) ] which updates the local info about tables in the subscribed
publication again with option to either copy or not copy data.
- Also this WITH (COPY DATA | NOCOPY DATA) ] was added to ALTER
SUBSCRIPTION ... SET PUBLICATION which automatically triggers the
REFRESH PUBLICATION as well.

So existing table data can be copied once subscription is created, but
also new tables can be added and their data copied. This is where the
REFRESH PUBLICATION comes into play. Adding table to publication does
not make it automatically replicated by the subscription as the
subscription does not have tracking info for that table. So to add new
table user must call ALTER SUBSCRIPTION ... REFRESH PUBLICATION on
subscriber otherwise the data won't be replicated.

The copy proccess runs in parallel with normal replication and is
visible in the pg_stat_subscription view. There is also new GUC
max_subscription_sync_workers which specifies how many tables can be
synchronized in parallel.

Implementation-wise this adds modified apply process called sync
(tablesync.c) which at the beginning creates temporary slot, copies data
from it, then synces to the correct LSN with the main apply and exits
(this is actually quite complex but it's explained in the tablesync.c
header).

Standard COPY TO/FROM is used. This is done by enhancing COPY FROM to
accept data from callback function which the tablesync implements.

On the publisher side, the walsender is enhanced to accept standard SQL
(simple query protocol only) so that COPY can be run. This also helps
getting info about table using plain SELECT. The way the SQL works is
that the parser was changed to accept strings that are not valid
replication protocol commands and if such string comes it's sent to
exec_simple_query instead of walsender.

The attached patch applies on top of logical replication patch-set v14.
I will add this as separate entry to the CF.

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

On 12/19/16 4:30 AM, Petr Jelinek wrote:
> So existing table data can be copied once subscription is created, but
> also new tables can be added and their data copied. This is where the
> REFRESH PUBLICATION comes into play. Adding table to publication does
> not make it automatically replicated by the subscription as the
> subscription does not have tracking info for that table. So to add new
> table user must call ALTER SUBSCRIPTION ... REFRESH PUBLICATION on
> subscriber otherwise the data won't be replicated.

Couldn't the subscriber automatically add tracking info when apply
stream data arrives for a relation it has not seen before?

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 20 Dec. 2016 1:27 am, "Peter Eisentraut" <
peter(dot)eisentraut(at)2ndquadrant(dot)com> wrote:

On 12/19/16 4:30 AM, Petr Jelinek wrote:
> So existing table data can be copied once subscription is created, but
> also new tables can be added and their data copied. This is where the
> REFRESH PUBLICATION comes into play. Adding table to publication does
> not make it automatically replicated by the subscription as the
> subscription does not have tracking info for that table. So to add new
> table user must call ALTER SUBSCRIPTION ... REFRESH PUBLICATION on
> subscriber otherwise the data won't be replicated.

Couldn't the subscriber automatically add tracking info when apply
stream data arrives for a relation it has not seen before?

If no table has been created by the user and we start trying to apply a
data stream apply will break.

Since manual action is needed to create the destination I don't see a
problem with requiring manual enabling too, personally.

Let the fully transparent way wait until we can do DDL replication in v11+

On 19/12/16 18:25, Peter Eisentraut wrote:
> On 12/19/16 4:30 AM, Petr Jelinek wrote:
>> So existing table data can be copied once subscription is created, but
>> also new tables can be added and their data copied. This is where the
>> REFRESH PUBLICATION comes into play. Adding table to publication does
>> not make it automatically replicated by the subscription as the
>> subscription does not have tracking info for that table. So to add new
>> table user must call ALTER SUBSCRIPTION ... REFRESH PUBLICATION on
>> subscriber otherwise the data won't be replicated.
>
> Couldn't the subscriber automatically add tracking info when apply
> stream data arrives for a relation it has not seen before?
>

Sure, but it has many caveats:
- what if the table does not exist
- what it if exists and already has data
- what if the table is rarely written to

We can't control any of that until we have DDL replication/automatic
structure dumping. Once we have those, we can add options to control
default behavior per subscriber, but with current feature set, anything
that does not require user action will behave non-deterministically
which is usually confusing.

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

On 12/19/16 4:30 AM, Petr Jelinek wrote:
> This patch implements data synchronization for the logical replication.
> It works both for initial setup of subscription as well as for tables
> added later to replication when the subscription is already active.

First detailed read-through. General structure makes sense.

Comments on some details:

No catalogs.sgml documentation for pg_subscription_rel. When that is
added, I would emphasize that entries are only added when relations
are first encountered, not immediately when a table is added to a
publication. So it is unlike pg_publication_rel in that respect.

Rename max_subscription_sync_workers ->
max_sync_workers_per_subscription (similar to
max_parallel_workers_per_gather and others)

About the changes to COPY: It took me a while to get clarity on the
direction of things. Is the read_cb reading the table, or the data?
You are copying data produced by a function into a table, so
produce_cb or data_source_cb could be clearer.

SetSubscriptionRelState(): This is doing an "upsert", so I don't think
a RowExclusiveLock is enough, or it needs to be able to retry on
concurrent changes. I suppose there shouldn't be more than one
concurrent change per sub/rel pair, but that would need to be
explained there.

SetSubscriptionRelState(): The memset(values, 0, sizeof(values)) is
kind of in an odd place. Possibly not actually needed.

GetSubscriptionRelState(): Prefer error messages that identify the
objects by name. (Also subid should be %u.)

GetSubscriptionRelationsFilter(): The state and filter arguments are
kind of weird. And there are only two callers, so all this complexity
is not even used. Perhaps, if state == SUBREL_STATE_UNKNOWN, then
return everything, else return exactly the state specified. The case
of everything-but-the-state-specified does not appear to be needed.

GetSubscriptionRelationsFilter(): RowExclusiveLock is probably too
much

This patch adds the fourth definition of oid_cmp() (also known as
oidComparator()) and the 12th definition of atooid(). Let's collect
those in a central place. I'm sending a separate patch for that. (No
need to change here until that is resolved, of course.)

AlterSubscription_refresh(): Put the if (wrconn == NULL) case first
and error out, and then put the rest of the code into the main
function block, saving one level of indentation.

AlterSubscription_refresh(): remote_table_oids isn't really the
remote OIDs of the tables but the local OIDs of the remote tables.
Consider clearer variable naming in that function.

interesting_relation(): very generic name, maybe
should_apply_changes_for_rel(). Also the comment mentions a "parallel
worker" -- maybe better a "separate worker process running in
parallel", since a parallel worker is something different.

LogicalRepApplyLoop() changed to non-static, but not used anywhere
else.

process_syncing_tables_*(): Function names and associated comments are
not very clear (process what?, handle what?).

In process_syncing_tables_apply(), it says that
logicalrep_worker_count() counts the apply worker as well, but what
happens if the apply worker has temporarily disappeared? Since
logicalrep_worker_count() is only used in this one place, maybe have
it count just the sync workers and rename it slightly.

Changed some LOG messages to DEBUG, not clear what the purpose there is.

check_max_subscription_sync_workers(): Same problem as discussed
previously, checking a GUC setting against another GUC setting like
this doesn't work. Just skip it and check at run time.

wait_for_sync_status_change(): Comment is wrong/misleading: It doesn't
wait until it matches any specific state, it just waits for any state
change.

LogicalRepSyncTableStart(): The code that assembles the slot name
needs to be aware of NAMEDATALEN. (Maybe at least throw in a static
assert that NAMEDATALEN>=64.)

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 11/01/17 17:10, Peter Eisentraut wrote:
> On 12/19/16 4:30 AM, Petr Jelinek wrote:
>> This patch implements data synchronization for the logical replication.
>> It works both for initial setup of subscription as well as for tables
>> added later to replication when the subscription is already active.
>
> First detailed read-through. General structure makes sense.

Thanks!

>
> Comments on some details:
>
> No catalogs.sgml documentation for pg_subscription_rel. When that is
> added, I would emphasize that entries are only added when relations
> are first encountered, not immediately when a table is added to a
> publication. So it is unlike pg_publication_rel in that respect.
>

It's not even first encountered, but I did explain.

> Rename max_subscription_sync_workers ->
> max_sync_workers_per_subscription (similar to
> max_parallel_workers_per_gather and others)
>

Makes sense.

> About the changes to COPY: It took me a while to get clarity on the
> direction of things. Is the read_cb reading the table, or the data?
> You are copying data produced by a function into a table, so
> produce_cb or data_source_cb could be clearer.
>

The data_source_cb sounds good to me.

> SetSubscriptionRelState(): This is doing an "upsert", so I don't think
> a RowExclusiveLock is enough, or it needs to be able to retry on
> concurrent changes. I suppose there shouldn't be more than one
> concurrent change per sub/rel pair, but that would need to be
> explained there.
>

Well technically there can be some concurrency via the ALTER
SUBSCRIPTION ... REFRESH so I increased lock level (and same for Remove).

> SetSubscriptionRelState(): The memset(values, 0, sizeof(values)) is
> kind of in an odd place. Possibly not actually needed.
>

It might not be needed but we traditionally do it anyway. I moved it a bit.

> GetSubscriptionRelState(): Prefer error messages that identify the
> objects by name. (Also subid should be %u.)
>

Well this is cache lookup failure though, who's to know that the objects
actually exist in that case.

> GetSubscriptionRelationsFilter(): The state and filter arguments are
> kind of weird. And there are only two callers, so all this complexity
> is not even used. Perhaps, if state == SUBREL_STATE_UNKNOWN, then
> return everything, else return exactly the state specified. The case
> of everything-but-the-state-specified does not appear to be needed.
>

I see this was bit confusing so I split the function into two. Actually
the 2 usecases used are everything and everything except SUBREL_STATE_READY.

> GetSubscriptionRelationsFilter(): RowExclusiveLock is probably too
> much
>

Yes, same with GetSubscriptionRelState().

> AlterSubscription_refresh(): remote_table_oids isn't really the
> remote OIDs of the tables but the local OIDs of the remote tables.
> Consider clearer variable naming in that function.
>

Done.

> interesting_relation(): very generic name, maybe
> should_apply_changes_for_rel(). Also the comment mentions a "parallel
> worker" -- maybe better a "separate worker process running in
> parallel", since a parallel worker is something different.
>

Done.

>
> process_syncing_tables_*(): Function names and associated comments are
> not very clear (process what?, handle what?).
>

Ok added some more explanation, hopefully it's better now.

> In process_syncing_tables_apply(), it says that
> logicalrep_worker_count() counts the apply worker as well, but what
> happens if the apply worker has temporarily disappeared? Since

Then the function is never going to be called for that subscription as
it's only called from the apply.

> logicalrep_worker_count() is only used in this one place, maybe have
> it count just the sync workers and rename it slightly.
>

Makes sense anyway though.

> Changed some LOG messages to DEBUG, not clear what the purpose there is.

In fact I changed some DEBUG messages to LOG in the main patch set, git
rebase just does not handle that very well. Fixed.

> check_max_subscription_sync_workers(): Same problem as discussed
> previously, checking a GUC setting against another GUC setting like
> this doesn't work. Just skip it and check at run time.
>

Yeah, we always check at run time.

> wait_for_sync_status_change(): Comment is wrong/misleading: It doesn't
> wait until it matches any specific state, it just waits for any state
> change.
>

Fixed.

> LogicalRepSyncTableStart(): The code that assembles the slot name
> needs to be aware of NAMEDATALEN. (Maybe at least throw in a static
> assert that NAMEDATALEN>=64.)
>

I switched to snprintf seems cleaner (also removes the need to know
about proper memory context of a private variable from
LogicalRepSyncTableStart()).

I also added option called SKIP CONNECT to CREATE SUBSCRIPTION (yes that
WIP name, I welcome suggestions). That skips the initial connection
attempt which is now needed always since we need to copy the table list.

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

On 2017-01-18 14:46, Petr Jelinek wrote:

> 0001-Logical-replication-support-for-initial-data-copy-v2.patch

Applies and builds fine on top of the previous 5 patches.

Two problems:

1. alter_subscription.sgml has an unpaired <command>-tag, which breaks
the doc-build:
This is the offending patch-line:
+ <command>CREATE SUBSCRIPTION</command> with <command>COPY
DATA<command>

2. Running the below (a version of the earlier pgbench_derail.sh) I have
found that
create subscription sub1 .. with (disabled); and then alter
subscription sub1 enable;
cannot be run immediately, consecutively. The error is avoided when the
two
commands are separated (for instance, below in separate psql- calls).

I don't understand why this is but it is reliably so.

The error(s):
2017-01-18 17:26:56.126 CET 24410 LOG: starting logical replication
worker for subscription "sub1"
2017-01-18 17:26:56.132 CET 26291 LOG: logical replication apply for
subscription sub1 started
2017-01-18 17:26:56.139 CET 26291 LOG: starting logical replication
worker for subscription "sub1"
2017-01-18 17:26:56.145 CET 26295 LOG: logical replication sync for
subscription sub1, table pgbench_accounts started
2017-01-18 17:26:56.534 CET 26295 ERROR: duplicate key value violates
unique constraint "pgbench_accounts_pkey"
2017-01-18 17:26:56.534 CET 26295 DETAIL: Key (aid)=(1) already exists.
2017-01-18 17:26:56.534 CET 26295 CONTEXT: COPY pgbench_accounts, line
1
2017-01-18 17:26:56.536 CET 21006 LOG: worker process: logical
replication worker 41015 sync 40991 (PID 26295) exited with exit code 1
2017-01-18 17:26:56.536 CET 26291 LOG: starting logical replication
worker for subscription "sub1"
2017-01-18 17:26:56.542 CET 26297 LOG: logical replication sync for
subscription sub1, table pgbench_branches started
2017-01-18 17:26:57.015 CET 26297 ERROR: duplicate key value violates
unique constraint "pgbench_branches_pkey"
2017-01-18 17:26:57.015 CET 26297 DETAIL: Key (bid)=(1) already exists.
2017-01-18 17:26:57.015 CET 26297 CONTEXT: COPY pgbench_branches, line
1
2017-01-18 17:26:57.017 CET 21006 LOG: worker process: logical
replication worker 41015 sync 40994 (PID 26297) exited with exit code 1
2017-01-18 17:26:57.017 CET 26291 LOG: starting logical replication
worker for subscription "sub1"
2017-01-18 17:26:57.023 CET 26299 LOG: logical replication sync for
subscription sub1, table pgbench_history started
2017-01-18 17:26:57.487 CET 26299 LOG: logical replication
synchronization worker finished processing
2017-01-18 17:26:57.488 CET 26291 LOG: starting logical replication
worker for subscription "sub1"
2017-01-18 17:26:57.491 CET 26301 LOG: logical replication sync for
subscription sub1, table pgbench_tellers started
2017-01-18 17:26:57.948 CET 26301 ERROR: duplicate key value violates
unique constraint "pgbench_tellers_pkey"
2017-01-18 17:26:57.948 CET 26301 DETAIL: Key (tid)=(1) already exists.
2017-01-18 17:26:57.948 CET 26301 CONTEXT: COPY pgbench_tellers, line 1
etc, etc.

#!/bin/sh

# assumes both instances are running, initially without publication or
subscription

unset PGSERVICEFILE PGSERVICE PGPORT PGDATA PGHOST
env | grep PG

PGDATABASE=testdb

# clear logs
echo >
/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/logfile.logical_replication
echo >
/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/logfile.logical_replication2

port1=6972
port2=6973

function cb()
{
# display the 4 pgbench tables' accumulated content as md5s
# a,b,t,h stand for: pgbench_accounts, -branches, -tellers, -history
for port in $port1 $port2
do
md5_a=$(echo "select * from pgbench_accounts order by aid"|psql
-qtAXp$port|md5sum|cut -b 1-9)
md5_b=$(echo "select * from pgbench_branches order by bid"|psql
-qtAXp$port|md5sum|cut -b 1-9)
md5_t=$(echo "select * from pgbench_tellers order by tid"|psql
-qtAXp$port|md5sum|cut -b 1-9)
md5_h=$(echo "select * from pgbench_history order by hid"|psql
-qtAXp$port|md5sum|cut -b 1-9)
cnt_a=$(echo "select count(*) from pgbench_accounts"|psql -qtAXp
$port)
cnt_b=$(echo "select count(*) from pgbench_branches"|psql -qtAXp
$port)
cnt_t=$(echo "select count(*) from pgbench_tellers" |psql -qtAXp
$port)
cnt_h=$(echo "select count(*) from pgbench_history" |psql -qtAXp
$port)
printf "$port a,b,t,h: %6d %6d %6d %6d" $cnt_a $cnt_b $cnt_t
$cnt_h
echo -n " $md5_a $md5_b $md5_t $md5_h"
if [[ $port -eq $port1 ]]; then echo " master"
elif [[ $port -eq $port2 ]]; then echo " replica"
else echo " ERROR"
fi
done
}

echo "
drop table if exists pgbench_accounts;
drop table if exists pgbench_branches;
drop table if exists pgbench_tellers;
drop table if exists pgbench_history;" | psql -X -p $port1 \
&& echo "
drop table if exists pgbench_accounts;
drop table if exists pgbench_branches;
drop table if exists pgbench_tellers;
drop table if exists pgbench_history;" | psql -X -p $port2 \
&& pgbench -p $port1 -qis 1 \
&& echo "
alter table pgbench_history add column hid serial primary key;
-- alter table pgbench_history replica identity full;
" | psql -1p $port1 \
&& pg_dump -F c -p $port1 \
-t pgbench_accounts \
-t pgbench_branches \
-t pgbench_tellers \
-t pgbench_history \
| pg_restore -p $port2 -d testdb

echo "$(cb)"

sleep 2

echo "$(cb)"

echo "create publication pub1 for all tables;" | psql -p $port1 -aqtAX

# this demostrates the bug:
echo "create subscription sub1 connection 'port=${port1}' publication
pub1 with (disabled);
alter subscription sub1 enable; " | psql -p $port2 -aqtAX
# like this (create and alter together in a single psql-call) fails;
# with the commands separated (to send them separately to psql suffices)
there is no problem.

#------------------------------------

#exit
#echo "$(cb)"
#echo "-- pgbench -c 1 -T 10 -P 5 -n (short run, first)"
# pgbench -c 1 -T 10 -P 5 -n

On 18/01/17 17:35, Erik Rijkers wrote:
> On 2017-01-18 14:46, Petr Jelinek wrote:
>
>> 0001-Logical-replication-support-for-initial-data-copy-v2.patch
>
> Applies and builds fine on top of the previous 5 patches.
>
> Two problems:
>
> 1. alter_subscription.sgml has an unpaired <command>-tag, which breaks
> the doc-build:
> This is the offending patch-line:
> + <command>CREATE SUBSCRIPTION</command> with <command>COPY
> DATA<command>
>

Hmm, I wonder how did that compile on my machine as it's indeed syntax
error.

>
> 2. Running the below (a version of the earlier pgbench_derail.sh) I have
> found that
> create subscription sub1 .. with (disabled); and then alter
> subscription sub1 enable;
> cannot be run immediately, consecutively. The error is avoided when the
> two
> commands are separated (for instance, below in separate psql- calls).
>
> I don't understand why this is but it is reliably so.
>

AFAICS you should always get error from that test after you enable the
subscription, no matter if you enable immediately or later. The default
behavior is to copy the data and your test already copies them via
pg_dump/pg_restore.

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

On 2017-01-18 20:45, Petr Jelinek wrote:
>
> AFAICS you should always get error from that test after you enable the

Ah tes, you were right, of course; I had assumed the earlier mentioned
CREATE SUBSCRIPTION ... [ WITH (COPY DATA | NOCOPY DATA) ]
but that syntax wasn't implemented, I now understand.

Taking that into account, my older tests work OK again (using the
7-patches below).

Other small issue: using this patch-set:

> 0001-Add-PUBLICATION-catalogs-and-DDL-v18.patch
> 0002-Add-SUBSCRIPTION-catalog-and-DDL-v18.patch
> 0003-Define-logical-replication-protocol-and-output-plugi-v18.patch
> 0004-Add-logical-replication-workers-v18fixed.patch
> 0005-Add-separate-synchronous-commit-control-for-logical--v18.patch
> 0001-Logical-replication-support-for-initial-data-copy-v2.patch
> 0006-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION.patch

( This is now the patch-set to test, is that correct? )

make check complains:

***
/home/aardvark/pg_stuff/pg_sandbox/pgsql.logical_replication/src/test/regress/expected/subscription.out 2017-01-19
09:26:41.354703032 +0100
---
/home/aardvark/pg_stuff/pg_sandbox/pgsql.logical_replication/src/test/regress/results/subscription.out 2017-01-19
09:29:56.104685043 +0100
***************
*** 53,62 ****
COMMIT;
ALTER SUBSCRIPTION testsub RENAME TO testsub_foo;
\dRs
! List of subscriptions
! Name | Owner | Enabled | Publication
!
-------------+---------------------------+---------+--------------------
! testsub_foo | regress_subscription_user | f |
{testpub,testpub1}
(1 row)

DROP SUBSCRIPTION testsub_foo NODROP SLOT;
--- 53,62 ----
COMMIT;
ALTER SUBSCRIPTION testsub RENAME TO testsub_foo;
\dRs
! List of subscriptions
! Name | Owner | Enabled | Publication
! -------------+---------------------------+---------+-------------
! testsub_foo | regress_subscription_user | f | {testpub}
(1 row)

DROP SUBSCRIPTION testsub_foo NODROP SLOT;

======================================================================

Thanks,

Erik Rijkers

On 19/01/17 09:39, Erik Rijkers wrote:
> On 2017-01-18 20:45, Petr Jelinek wrote:
>>
>> AFAICS you should always get error from that test after you enable the
>
> Ah tes, you were right, of course; I had assumed the earlier mentioned
> CREATE SUBSCRIPTION ... [ WITH (COPY DATA | NOCOPY DATA) ]
> but that syntax wasn't implemented, I now understand.
>
> Taking that into account, my older tests work OK again (using the
> 7-patches below).
>

Good to hear.

>
> Other small issue: using this patch-set:
>
>> 0001-Add-PUBLICATION-catalogs-and-DDL-v18.patch
>> 0002-Add-SUBSCRIPTION-catalog-and-DDL-v18.patch
>> 0003-Define-logical-replication-protocol-and-output-plugi-v18.patch
>> 0004-Add-logical-replication-workers-v18fixed.patch
>> 0005-Add-separate-synchronous-commit-control-for-logical--v18.patch
>> 0001-Logical-replication-support-for-initial-data-copy-v2.patch
>> 0006-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION.patch
>
> ( This is now the patch-set to test, is that correct? )
>

The rename should be before this one, but I guess with v2 that didn't
work well yet as it didn't know about rename.

> make check complains:
>
> ***
> /home/aardvark/pg_stuff/pg_sandbox/pgsql.logical_replication/src/test/regress/expected/subscription.out
> 2017-01-19 09:26:41.354703032 +0100
> ---
> /home/aardvark/pg_stuff/pg_sandbox/pgsql.logical_replication/src/test/regress/results/subscription.out
> 2017-01-19 09:29:56.104685043 +0100
> ***************
> *** 53,62 ****
> COMMIT;
> ALTER SUBSCRIPTION testsub RENAME TO testsub_foo;
> \dRs
> ! List of subscriptions
> ! Name | Owner | Enabled | Publication
> ! -------------+---------------------------+---------+--------------------
> ! testsub_foo | regress_subscription_user | f | {testpub,testpub1}
> (1 row)
>
> DROP SUBSCRIPTION testsub_foo NODROP SLOT;
> --- 53,62 ----
> COMMIT;
> ALTER SUBSCRIPTION testsub RENAME TO testsub_foo;
> \dRs
> ! List of subscriptions
> ! Name | Owner | Enabled | Publication
> ! -------------+---------------------------+---------+-------------
> ! testsub_foo | regress_subscription_user | f | {testpub}
> (1 row)
>
> DROP SUBSCRIPTION testsub_foo NODROP SLOT;
>
> ======================================================================
>

Meh, I really messed up the rebase this time.

Okay, here is v3 with some small fixes and rebased on top of rename.
Also it's rebased without the
0005-Add-separate-synchronous-commit-control-for-logical--v18.patch as I
don't expect that one to go further for now.

Thanks for testing!

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

On Fri, Jan 20, 2017 at 3:03 AM, Petr Jelinek
<petr(dot)jelinek(at)2ndquadrant(dot)com> wrote:
> Okay, here is v3 with some small fixes and rebased on top of rename.
> Also it's rebased without the
> 0005-Add-separate-synchronous-commit-control-for-logical--v18.patch as I
> don't expect that one to go further for now.
>
> Thanks for testing!

This patch needs a rebase, moved to next CF with "waiting on author".
--
Michael

Hi,

here is updated patch.

Note that it's rebased on top of logical replication improvements
patches [1] (which still apply fine to my surprise).

It will probably need another rebase once patches from Masahiko Sawada
and Fujii Masao get in.

[1]
https://www.postgresql.org/message-id/42655eb4-6b2e-b35b-c184-509efd6eba10%402ndquadrant.com

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

On 08/02/17 23:24, Petr Jelinek wrote:
> Hi,
>
> here is updated patch.
>
> Note that it's rebased on top of logical replication improvements
> patches [1] (which still apply fine to my surprise).
>
> It will probably need another rebase once patches from Masahiko Sawada
> and Fujii Masao get in.
>
> [1]
> https://www.postgresql.org/message-id/42655eb4-6b2e-b35b-c184-509efd6eba10%402ndquadrant.com
>

And now with the actual patch attached :)

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

On 2017-02-08 23:25, Petr Jelinek wrote:

> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver-v2.patch
> 0002-Always-initialize-stringinfo-buffers-in-walsender-v2.patch
> 0003-Fix-after-trigger-execution-in-logical-replication-v2.patch
> 0004-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION-v2.patch
> 0001-Logical-replication-support-for-initial-data-copy-v4.patch

test 'object_address' fails, see atachment.

That's all I found in a quick first trial.

thanks,

Erik Rijkers

On 2017-02-08 23:25, Petr Jelinek wrote:

> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver-v2.patch
> 0002-Always-initialize-stringinfo-buffers-in-walsender-v2.patch
> 0003-Fix-after-trigger-execution-in-logical-replication-v2.patch
> 0004-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION-v2.patch
> 0001-Logical-replication-support-for-initial-data-copy-v4.patch

Apart from the failing one make check test (test 'object_address') which
I reported earlier, I find it is easy to 'confuse' the replication.

I attach a script that intends to test the default COPY DATA. There
are two instances, initially without any replication. The script inits
pgbench on the master, adds a serial column to pgbench_history, and
dump-restores the 4 pgbench-tables to the future replica. It then
empties the 4 pgbench-tables on the 'replica'. The idea is that when
logrep is initiated, data will be replicated from master, with the end
result being that there are 4 identical tables on master and replica.

This often works but it also fails far too often (in my hands). I test
whether the tables are identical by comparing an md5 from an ordered
resultset, from both replica and master. I estimate that 1 in 5 tries
fail; 'fail' being a somewhat different table on replica (compared to
mater), most often pgbench_accounts (typically there are 10-30 differing
rows). No errors or warnings in either logfile. I'm not sure but I
think testing on faster machines seem to be doing somewhat better
('better' being less replication error).

Another, probably unrelated, problem occurs (but much more rarely) when
executing 'DROP SUBSCRIPTION sub1' on the replica (see the beginning of
the script). Sometimes that command hangs, and refuses to accept
shutdown of the server. I don't know how to recover from this -- I just
have to kill the replica server (master server still obeys normal
shutdown) and restart the instances.

The script accepts 2 parameters, scale and clients (used in pgbench -s
resp. -c)

I don't think I've managed to successfully run the script with more than
1 client yet.

Can you have a look whether this is reproducible elsewhere?

thanks,

Erik Rijkers

On 2017-02-09 02:25, Erik Rijkers wrote:
> On 2017-02-08 23:25, Petr Jelinek wrote:
>
>> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver-v2.patch
>> 0002-Always-initialize-stringinfo-buffers-in-walsender-v2.patch
>> 0003-Fix-after-trigger-execution-in-logical-replication-v2.patch
>> 0004-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION-v2.patch
>> 0001-Logical-replication-support-for-initial-data-copy-v4.patch
>

fixes in create_subscription.sgml

On 2017-02-11 11:16, Erik Rijkers wrote:
> On 2017-02-08 23:25, Petr Jelinek wrote:
>
>> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver-v2.patch
>> 0002-Always-initialize-stringinfo-buffers-in-walsender-v2.patch
>> 0003-Fix-after-trigger-execution-in-logical-replication-v2.patch
>> 0004-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION-v2.patch
>> 0001-Logical-replication-support-for-initial-data-copy-v4.patch
>
> This often works but it also fails far too often (in my hands). I
> test whether the tables are identical by comparing an md5 from an
> ordered resultset, from both replica and master. I estimate that 1 in
> 5 tries fail; 'fail' being a somewhat different table on replica
> (compared to mater), most often pgbench_accounts (typically there are
> 10-30 differing rows). No errors or warnings in either logfile. I'm
> not sure but I think testing on faster machines seem to be doing
> somewhat better ('better' being less replication error).
>

I have noticed that when I insert a few seconds wait-state after the
create subscription (or actually: the 'enable'ing of the subscription)
the problem does not occur. Apparently, (I assume) the initial snapshot
occurs somewhere when the subsequent pgbench-run has already started, so
that the logical replication also starts somewhere 'into' that
pgbench-run. Does that make sense?

I don't know what to make of it. Now that I think that I understand
what happens I hesitate to call it a bug. But I'd say it's still a
useability problem that the subscription is only 'valid' after some
time, even if it's only a few seconds.

(the other problem I mentioned (drop subscription hangs) still happens
every now and then)

On 13/02/17 14:51, Erik Rijkers wrote:
> On 2017-02-11 11:16, Erik Rijkers wrote:
>> On 2017-02-08 23:25, Petr Jelinek wrote:
>>
>>> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver-v2.patch
>>> 0002-Always-initialize-stringinfo-buffers-in-walsender-v2.patch
>>> 0003-Fix-after-trigger-execution-in-logical-replication-v2.patch
>>> 0004-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION-v2.patch
>>> 0001-Logical-replication-support-for-initial-data-copy-v4.patch
>>
>> This often works but it also fails far too often (in my hands). I
>> test whether the tables are identical by comparing an md5 from an
>> ordered resultset, from both replica and master. I estimate that 1 in
>> 5 tries fail; 'fail' being a somewhat different table on replica
>> (compared to mater), most often pgbench_accounts (typically there are
>> 10-30 differing rows). No errors or warnings in either logfile. I'm
>> not sure but I think testing on faster machines seem to be doing
>> somewhat better ('better' being less replication error).
>>
>
> I have noticed that when I insert a few seconds wait-state after the
> create subscription (or actually: the 'enable'ing of the subscription)
> the problem does not occur. Apparently, (I assume) the initial snapshot
> occurs somewhere when the subsequent pgbench-run has already started, so
> that the logical replication also starts somewhere 'into' that
> pgbench-run. Does that make sense?
>
> I don't know what to make of it. Now that I think that I understand
> what happens I hesitate to call it a bug. But I'd say it's still a
> useability problem that the subscription is only 'valid' after some
> time, even if it's only a few seconds.
>

It is a bug, we are going to great lengths to create data snapshot that
corresponds to specific LSN so that we are able to decode exactly the
changes that happened since the data snapshot was taken. And the
tablecopy.c does quite a lot to synchronize table handover to main apply
process so that there is correct continuation of data stream as well. So
the end result is that concurrent changes are supposed to be okay and
eventually replication should catch up and the contents should be the same.

That being said, I am so far having problems reproducing this on my test
machine(s) so no idea what causes it yet.

Could you periodically dump contents of the pg_subscription_rel on
subscriber (ideally when dumping the md5 of the data) and attach that as
well?

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

On 2017-02-16 00:43, Petr Jelinek wrote:
> On 13/02/17 14:51, Erik Rijkers wrote:
>> On 2017-02-11 11:16, Erik Rijkers wrote:
>>> On 2017-02-08 23:25, Petr Jelinek wrote:
>>>
>>>> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver-v2.patch
>>>> 0002-Always-initialize-stringinfo-buffers-in-walsender-v2.patch
>>>> 0003-Fix-after-trigger-execution-in-logical-replication-v2.patch
>>>> 0004-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION-v2.patch
>>>> 0001-Logical-replication-support-for-initial-data-copy-v4.patch
>>>
>>> This often works but it also fails far too often (in my hands). I
>
> Could you periodically dump contents of the pg_subscription_rel on
> subscriber (ideally when dumping the md5 of the data) and attach that
> as
> well?

I attach a bash script (and its output) that polls the 4 pgbench table's
md5s and the pg_subscription_rel table, each second, while I run the
pgbench_derail2.sh (for that see my earlier mail).

pgbench_derail2.sh writes a 'header' into the same output stream (search
for '^===' ).

The .out file reflects a session where I started pgbench_derail2.sh
twice (it removes the publication and subscription at startup). So
there are 2 headers in the attached cb_20170216_10_04_47.out. The first
run ended in a succesful replication (=all 4 pgbench tables
md5-identical). The second run does not end correctly: it has (one of)
the typical faulty end-states: pgbench_accounts, the copy, has a few
less rows than the master table.

Other typical endstates are:
same number of rows but content not identical (for some, typically < 20
rows).
mostly pgbench_accounts and pgbench_history are affected.

(I see now that I made some mistakes in generating the timestamps in the
.out file but I suppose it doesn't matter too much)

I hope it helps; let me know if I can do any other test(s).

On 2017-02-16 00:43, Petr Jelinek wrote:
> On 13/02/17 14:51, Erik Rijkers wrote:
>> On 2017-02-11 11:16, Erik Rijkers wrote:
>>> On 2017-02-08 23:25, Petr Jelinek wrote:
>>>
>>>> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver-v2.patch
>>>> 0002-Always-initialize-stringinfo-buffers-in-walsender-v2.patch
>>>> 0003-Fix-after-trigger-execution-in-logical-replication-v2.patch
>>>> 0004-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION-v2.patch
>>>> 0001-Logical-replication-support-for-initial-data-copy-v4.patch
>>>
>>> This often works but it also fails far too often (in my hands). I
>
> That being said, I am so far having problems reproducing this on my
> test
> machine(s) so no idea what causes it yet.
>

A few extra bits:

- I have repeated this now on three different machines (debian 7, 8,
centos6; one a pretty big server); there is always failure within a few
tries of that test program (i.e. pgbench_derail2.sh, with the above 5
patches).

- I have also tried to go back to an older version of logrep: running
with 2 instances with only the first four patches (i.e., leaving out the
support-for-existing-data patch). With only those 4, the logical
replication is solid. (a quick 25x repetition of a (very similar) test
program is 100% successful). So the problem is likely somehow in that
last 5th patch.

- A 25x repetition of a test on a master + replica 5-patch server yields
13 ok, 12 NOK.

- Is the 'make check' FAILED test 'object_addess' unrelated? (Can you
at least reproduce that failed test?)

Maybe add this to the 10 Open Items list?
https://wiki.postgresql.org/wiki/PostgreSQL_10_Open_Items

It may garner a bit more attention.

thanks,

Erik Rijkers

>
> Maybe add this to the 10 Open Items list?
> https://wiki.postgresql.org/wiki/PostgreSQL_10_Open_Items
>
> It may garner a bit more attention.
>

Ah sorry, it's there already.

On 2017-02-11 11:16, Erik Rijkers wrote:
> On 2017-02-08 23:25, Petr Jelinek wrote:
>
>> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver-v2.patch
>> 0002-Always-initialize-stringinfo-buffers-in-walsender-v2.patch
>> 0003-Fix-after-trigger-execution-in-logical-replication-v2.patch
>> 0004-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION-v2.patch
>> 0001-Logical-replication-support-for-initial-data-copy-v4.patch
>

Let me add the script ('instances.sh') that I use to startup the two
logical replication instances for testing.

Together with the earlier posted 'pgbench_derail2.sh' it makes out the
fails test.

pg_config of the master is:

$ pg_config
BINDIR =
/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/bin
DOCDIR =
/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/share/doc
HTMLDIR =
/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/share/doc
INCLUDEDIR =
/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/include
PKGINCLUDEDIR =
/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/include
INCLUDEDIR-SERVER =
/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/include/server
LIBDIR =
/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/lib
PKGLIBDIR =
/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/lib
LOCALEDIR =
/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/share/locale
MANDIR =
/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/share/man
SHAREDIR =
/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/share
SYSCONFDIR =
/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/etc
PGXS =
/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/lib/pgxs/src/makefiles/pgxs.mk
CONFIGURE =
'--prefix=/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication'
'--bindir=/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/bin'
'--libdir=/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/lib'
'--with-pgport=6972' '--enable-depend' '--enable-cassert'
'--enable-debug' '--with-openssl' '--with-perl' '--with-libxml'
'--with-libxslt' '--with-zlib' '--enable-tap-tests'
'--with-extra-version=_logical_replication_20170218_1221_e3a58c8835a2'
CC = gcc
CPPFLAGS = -DFRONTEND -D_GNU_SOURCE -I/usr/include/libxml2
CFLAGS = -Wall -Wmissing-prototypes -Wpointer-arith
-Wdeclaration-after-statement -Wendif-labels -Wmissing-format-attribute
-Wformat-security -fno-strict-aliasing -fwrapv
-fexcess-precision=standard -g -O2
CFLAGS_SL = -fpic
LDFLAGS = -L../../src/common -Wl,--as-needed
-Wl,-rpath,'/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/lib',--enable-new-dtags
LDFLAGS_EX =
LDFLAGS_SL =
LIBS = -lpgcommon -lpgport -lxslt -lxml2 -lssl -lcrypto -lz -lreadline
-lrt -lcrypt -ldl -lm
VERSION = PostgreSQL
10devel_logical_replication_20170218_1221_e3a58c8835a2

I hope it helps someone to reproduce the errors I get. (If you don't,
I'd like to hear that too)

thanks,

Erik Rijkers

On 18/02/17 14:24, Erik Rijkers wrote:
>>
>> Maybe add this to the 10 Open Items list?
>> https://wiki.postgresql.org/wiki/PostgreSQL_10_Open_Items
>>
>> It may garner a bit more attention.
>>
>
> Ah sorry, it's there already.

Hmm that's interesting given that it's not even committed yet :)

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

On 18/02/17 14:17, Erik Rijkers wrote:
> On 2017-02-16 00:43, Petr Jelinek wrote:
>> On 13/02/17 14:51, Erik Rijkers wrote:
>>> On 2017-02-11 11:16, Erik Rijkers wrote:
>>>> On 2017-02-08 23:25, Petr Jelinek wrote:
>>>>
>>>>> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver-v2.patch
>>>>> 0002-Always-initialize-stringinfo-buffers-in-walsender-v2.patch
>>>>> 0003-Fix-after-trigger-execution-in-logical-replication-v2.patch
>>>>> 0004-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION-v2.patch
>>>>> 0001-Logical-replication-support-for-initial-data-copy-v4.patch
>>>>
>>>> This often works but it also fails far too often (in my hands). I
>>
>> That being said, I am so far having problems reproducing this on my test
>> machine(s) so no idea what causes it yet.
>>
>
> A few extra bits:
>
> - I have repeated this now on three different machines (debian 7, 8,
> centos6; one a pretty big server); there is always failure within a few
> tries of that test program (i.e. pgbench_derail2.sh, with the above 5
> patches).
>
> - I have also tried to go back to an older version of logrep: running
> with 2 instances with only the first four patches (i.e., leaving out the
> support-for-existing-data patch). With only those 4, the logical
> replication is solid. (a quick 25x repetition of a (very similar) test
> program is 100% successful). So the problem is likely somehow in that
> last 5th patch.
>
> - A 25x repetition of a test on a master + replica 5-patch server yields
> 13 ok, 12 NOK.
>
> - Is the 'make check' FAILED test 'object_addess' unrelated? (Can you
> at least reproduce that failed test?)
>

Yes, it has nothing to do with that, that just needs to be updated to
use SKIP CONNECT instead of NOCREATE SLOT in this patch since NOCREATE
SLOT is no longer enough to skip the connection attempt. And I have that
fixed locally, but that does not deserve new patch version given the
main issue you reported.

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

> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver-v2.patch
> 0002-Always-initialize-stringinfo-buffers-in-walsender-v2.patch
> 0003-Fix-after-trigger-execution-in-logical-replication-v2.patch
> 0004-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION-v2.patch
> 0001-Logical-replication-support-for-initial-data-copy-v4.patch

Improve readability of comment blocks
in src/backend/replication/logical/origin.c

thanks,

Erik Rijkers

On 2017-02-19 17:21, Erik Rijkers wrote:
>> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver-v2.patch
>> 0002-Always-initialize-stringinfo-buffers-in-walsender-v2.patch
>> 0003-Fix-after-trigger-execution-in-logical-replication-v2.patch
>> 0004-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION-v2.patch
>> 0001-Logical-replication-support-for-initial-data-copy-v4.patch
>
> Improve readability of comment blocks
> in src/backend/replication/logical/origin.c
>

now attached

>
> thanks,
>
> Erik Rijkers

>>> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver-v2.patch
>>> 0002-Always-initialize-stringinfo-buffers-in-walsender-v2.patch
>>> 0003-Fix-after-trigger-execution-in-logical-replication-v2.patch
>>> 0004-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION-v2.patch
>>> 0001-Logical-replication-support-for-initial-data-copy-v4.patch

Improve comment blocks in
src/backend/replication/logical/snapbuild.c

On 2017-02-19 23:24, Erik Rijkers wrote:
>>>> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver-v2.patch
>>>> 0002-Always-initialize-stringinfo-buffers-in-walsender-v2.patch
>>>> 0003-Fix-after-trigger-execution-in-logical-replication-v2.patch
>>>> 0004-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION-v2.patch
>>>> 0001-Logical-replication-support-for-initial-data-copy-v4.patch
>
> Improve comment blocks in
> src/backend/replication/logical/snapbuild.c
>

[deep sigh...] attached...

Hi,

so I managed to reproduce this. The main issue is the bug in snapbuild.c
as mentioned in nearby thread. But there are couple of fixes in this
patch to make it work correctly (and also to fix the regression test
failure). So here is updated version of the patch that should work
correctly (in combination with other fixes).

I also decided to change SKIP CONNECT to NOCONNECT for consistency with
other options/commands.

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

On 2017-02-22 13:03, Petr Jelinek wrote:

> 0001-Skip-unnecessary-snapshot-builds.patch
> 0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch
> 0003-Fix-xl_running_xacts-usage-in-snapshot-builder.patch
> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver.patch
> 0002-Fix-after-trigger-execution-in-logical-replication.patch
> 0003-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION.patch
> 0001-Logical-replication-support-for-initial-data-copy-v5.patch

It works well now, or at least my particular test case seems now solved.

thanks,

Erik Rijkers

On 2017-02-22 14:48, Erik Rijkers wrote:
> On 2017-02-22 13:03, Petr Jelinek wrote:
>
>> 0001-Skip-unnecessary-snapshot-builds.patch
>> 0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch
>> 0003-Fix-xl_running_xacts-usage-in-snapshot-builder.patch
>> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver.patch
>> 0002-Fix-after-trigger-execution-in-logical-replication.patch
>> 0003-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION.patch
>> 0001-Logical-replication-support-for-initial-data-copy-v5.patch
>
> It works well now, or at least my particular test case seems now
> solved.

Cried victory too early, I'm afraid.

The logical replication is now certainly much more stable but there are
still errors, just less often.

The rare 'hang'-error that I mentioned a few emails back I have not yet
encountered; I am beginning to trust that that is indeed solved.

But there is still sometimes incorrect replication. The symptoms are
the ones I mentioned earlier:
- incorrect number of rows in one of (mostly) pgbench_accounts or
pgbench_history.
the numers are always off by a very small number, say less than 20,
often even only 1 row.
- incorrect content in one of pgbench_accounts or pgbench_history
(detected via md5). Also mostly the two tables named above.

I see sometimes primary key violations on the replica. That should not
be possible if I have understood the intent of logical replication
correctly.
( ERROR: duplicate key value violates unique constraint
"pgbench_tellers_pkey" )
mostly *_tellers, also seen *_branches

Understandably, the errors become more frequent with higher client
counts: a 25x repeat with 1 client yielded only 1 failed run whereas a
25x repeat with 16 clients gave 16 failures.

I attach once more the current incarnation of my test-bash pgbench
runner, pgbench_derail2.sh.
Easiest to run it yourself, I guess.

I also attach the output (of pgbench_derail2.sh) of those two 25x
repeats:
d2_scale__1_client__1_25x.txt
d2_scale__1_client_16_25x.txt

I worry a bit about the correctness of that test program
(pgbench_derail2.sh). I especially wonder if it should look around
better at startup (e.g., at stuff left over from previous iterations).
If you see any incorrect/dumb things there, or a better way to monitor
(aka pre-flight checks), please let me know.

But the current state si certainly a big step forward -- I guess it's
just your bad luck that I had the afternoon off ;)

thanks,

Erik Rijkers

On 2017-02-22 18:13, Erik Rijkers wrote:
> On 2017-02-22 14:48, Erik Rijkers wrote:
>> On 2017-02-22 13:03, Petr Jelinek wrote:
>>
>>> 0001-Skip-unnecessary-snapshot-builds.patch
>>> 0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch
>>> 0003-Fix-xl_running_xacts-usage-in-snapshot-builder.patch
>>> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver.patch
>>> 0002-Fix-after-trigger-execution-in-logical-replication.patch
>>> 0003-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION.patch
>>> 0001-Logical-replication-support-for-initial-data-copy-v5.patch
>>
>> It works well now, or at least my particular test case seems now
>> solved.
>
> Cried victory too early, I'm afraid.
>

I got into a 'hung' state while repeating pgbench_derail2.sh.

Below is some state. I notice that master pg_stat_replication.syaye is
'startup'.
Maybe I should only start the test after that state has changed. Any of
the
other possible values (catchup, streaming) wuold be OK, I would think.

$ ( dbactivity.sh ; echo "; table pg_subscription; table
pg_subscription_rel;" ) | psql -qXp 6973
now | pid | app
| state | wt_evt | wt_evt_type | query_start
| duration | query
---------------------+-------+---------------------------------------------+--------+------------------------+-------------+---------------------+----------+----------------------------------
2017-02-23 00:37:57 | 31352 | logical replication worker 47435
| active | relation | Lock |
| |
2017-02-23 00:37:57 | 397 | psql
| active | BgWorkerShutdown | IPC | 2017-02-23 00:22:14
| 00:15:42 | drop subscription if exists sub1
2017-02-23 00:37:57 | 31369 | logical replication worker 47435 sync
47423 | | LogicalSyncStateChange | IPC |
| |
2017-02-23 00:37:57 | 398 | logical replication worker 47435 sync
47418 | | transactionid | Lock |
| |
(4 rows)

subdbid | subname | subowner | subenabled | subconninfo | subslotname |
subpublications
---------+---------+----------+------------+-------------+-------------+-----------------
16384 | sub1 | 10 | t | port=6972 | sub1 |
{pub1}
(1 row)

srsubid | srrelid | srsubstate | srsublsn
---------+---------+------------+------------
47435 | 47423 | w | 2/CB078260
47435 | 47412 | r |
47435 | 47415 | r |
47435 | 47418 | c | 2/CB06E158
(4 rows)

Replica (port 6973):

[bulldog aardvark] [local]:6973 (Thu) 00:52:47 [pid:5401] [testdb] #
table pg_stat_subscription ;
subid | subname | pid | relid | received_lsn |
last_msg_send_time | last_msg_receipt_time |
latest_end_lsn | latest_end_time
-------+---------+-------+-------+--------------+-------------------------------+-------------------------------+----------------+-------------------------------
47435 | sub1 | 31369 | 47423 | | 2017-02-23
00:20:45.758072+01 | 2017-02-23 00:20:45.758072+01 | |
2017-02-23 00:20:45.758072+01
47435 | sub1 | 398 | 47418 | | 2017-02-23
00:22:14.896471+01 | 2017-02-23 00:22:14.896471+01 | |
2017-02-23 00:22:14.896471+01
47435 | sub1 | 31352 | | 2/CB06E158 |
| 2017-02-23 00:20:47.034664+01 | | 2017-02-23
00:20:45.679245+01
(3 rows)

Master (port 6972):

[bulldog aardvark] [local]:6972 (Thu) 00:48:27 [pid:5307] [testdb] # \x
on \\ table pg_stat_replication ;
Expanded display is on.
-[ RECORD 1 ]----+------------------------------
pid | 399
usesysid | 10
usename | aardvark
application_name | sub1_47435_sync_47418
client_addr |
client_hostname |
client_port | -1
backend_start | 2017-02-23 00:22:14.902701+01
backend_xmin |
state | startup
sent_location |
write_location |
flush_location |
replay_location |
sync_priority | 0
sync_state | async
-[ RECORD 2 ]----+------------------------------
pid | 31371
usesysid | 10
usename | aardvark
application_name | sub1_47435_sync_47423
client_addr |
client_hostname |
client_port | -1
backend_start | 2017-02-23 00:20:45.762852+01
backend_xmin |
state | startup
sent_location |
write_location |
flush_location |
replay_location |
sync_priority | 0
sync_state | async

( above 'dbactivity.sh' is:

select
rpad(now()::text,19) as now
, pid as pid
, application_name as app
, state as state
, wait_event as wt_evt
, wait_event_type as wt_evt_type
, date_trunc('second', query_start::timestamp) as query_start
, substring((now() - query_start)::text, 1, position('.' in (now() -
query_start)::text)-1) as duration
, query
from pg_stat_activity
where query !~ 'pg_stat_activity' ;

)

On 23/02/17 01:02, Erik Rijkers wrote:
> On 2017-02-22 18:13, Erik Rijkers wrote:
>> On 2017-02-22 14:48, Erik Rijkers wrote:
>>> On 2017-02-22 13:03, Petr Jelinek wrote:
>>>
>>>> 0001-Skip-unnecessary-snapshot-builds.patch
>>>> 0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch
>>>> 0003-Fix-xl_running_xacts-usage-in-snapshot-builder.patch
>>>> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver.patch
>>>> 0002-Fix-after-trigger-execution-in-logical-replication.patch
>>>> 0003-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION.patch
>>>> 0001-Logical-replication-support-for-initial-data-copy-v5.patch
>>>
>>> It works well now, or at least my particular test case seems now solved.
>>
>> Cried victory too early, I'm afraid.
>>
>
> I got into a 'hung' state while repeating pgbench_derail2.sh.
>
> Below is some state. I notice that master pg_stat_replication.syaye is
> 'startup'.
> Maybe I should only start the test after that state has changed. Any of the
> other possible values (catchup, streaming) wuold be OK, I would think.
>

I think that's known issue (see comment in tablesync.c about hanging
forever). I think I may have fixed it locally.

I will submit patch once I fixed the other snapshot issue (I managed to
reproduce it as well, although very rarely so it's rather hard to test).

Thanks for all this testing btw, I really appreciate it.

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

On 23/02/17 01:41, Petr Jelinek wrote:
> On 23/02/17 01:02, Erik Rijkers wrote:
>> On 2017-02-22 18:13, Erik Rijkers wrote:
>>> On 2017-02-22 14:48, Erik Rijkers wrote:
>>>> On 2017-02-22 13:03, Petr Jelinek wrote:
>>>>
>>>>> 0001-Skip-unnecessary-snapshot-builds.patch
>>>>> 0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch
>>>>> 0003-Fix-xl_running_xacts-usage-in-snapshot-builder.patch
>>>>> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver.patch
>>>>> 0002-Fix-after-trigger-execution-in-logical-replication.patch
>>>>> 0003-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION.patch
>>>>> 0001-Logical-replication-support-for-initial-data-copy-v5.patch
>>>>
>>>> It works well now, or at least my particular test case seems now solved.
>>>
>>> Cried victory too early, I'm afraid.
>>>
>>
>> I got into a 'hung' state while repeating pgbench_derail2.sh.
>>
>> Below is some state. I notice that master pg_stat_replication.syaye is
>> 'startup'.
>> Maybe I should only start the test after that state has changed. Any of the
>> other possible values (catchup, streaming) wuold be OK, I would think.
>>
>
> I think that's known issue (see comment in tablesync.c about hanging
> forever). I think I may have fixed it locally.
>
> I will submit patch once I fixed the other snapshot issue (I managed to
> reproduce it as well, although very rarely so it's rather hard to test).
>

Hi,

Here it is. But check also the snapbuild related thread for updated
patches related to that (the issue you had with this not copying all
rows is yet another pre-existing Postgres bug).

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

On 2017-02-24 22:58, Petr Jelinek wrote:
> On 23/02/17 01:41, Petr Jelinek wrote:
>> On 23/02/17 01:02, Erik Rijkers wrote:
>>> On 2017-02-22 18:13, Erik Rijkers wrote:
>>>> On 2017-02-22 14:48, Erik Rijkers wrote:
>>>>> On 2017-02-22 13:03, Petr Jelinek wrote:
>>>>>
>>>>>> 0001-Skip-unnecessary-snapshot-builds.patch
>>>>>> 0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch
>>>>>> 0003-Fix-xl_running_xacts-usage-in-snapshot-builder.patch
>>>>>> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver.patch
>>>>>> 0002-Fix-after-trigger-execution-in-logical-replication.patch
>>>>>> 0003-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION.patch
>>>>>> 0001-Logical-replication-support-for-initial-data-copy-v5.patch
>>>>>
>>>>> It works well now, or at least my particular test case seems now
>>>>> solved.
>>>>
>>>> Cried victory too early, I'm afraid.
>>>>
>>>
>>> I got into a 'hung' state while repeating pgbench_derail2.sh.
>>>
>>> Below is some state. I notice that master pg_stat_replication.syaye
>>> is
>>> 'startup'.
>>> Maybe I should only start the test after that state has changed. Any
>>> of the
>>> other possible values (catchup, streaming) wuold be OK, I would
>>> think.
>>>
>>
>> I think that's known issue (see comment in tablesync.c about hanging
>> forever). I think I may have fixed it locally.
>>
>> I will submit patch once I fixed the other snapshot issue (I managed
>> to
>> reproduce it as well, although very rarely so it's rather hard to
>> test).
>>
>
> Hi,
>
> Here it is. But check also the snapbuild related thread for updated
> patches related to that (the issue you had with this not copying all
> rows is yet another pre-existing Postgres bug).
>

The four earlier snapbuild patches apply cleanly, but
then I get errors while applying
0001-Logical-replication-support-for-initial-data-copy-v6.patch:

patching file src/test/regress/expected/sanity_check.out
(Stripping trailing CRs from patch.)
patching file src/test/regress/expected/subscription.out
Hunk #2 FAILED at 25.
1 out of 2 hunks FAILED -- saving rejects to file
src/test/regress/expected/subscription.out.rej
(Stripping trailing CRs from patch.)
patching file src/test/regress/sql/object_address.sql
(Stripping trailing CRs from patch.)
patching file src/test/regress/sql/subscription.sql
(Stripping trailing CRs from patch.)
patching file src/test/subscription/t/001_rep_changes.pl
Hunk #9 succeeded at 175 with fuzz 2.
Hunk #10 succeeded at 193 (offset -9 lines).
(Stripping trailing CRs from patch.)
patching file src/test/subscription/t/002_types.pl
(Stripping trailing CRs from patch.)
can't find file to patch at input line 4296
Perhaps you used the wrong -p or --strip option?
The text leading up to this was:
--------------------------
|diff --git a/src/test/subscription/t/003_constraints.pl
b/src/test/subscription/t/003_constraints.pl
|index 17d4565..9543b91 100644
|--- a/src/test/subscription/t/003_constraints.pl
|+++ b/src/test/subscription/t/003_constraints.pl
--------------------------
File to patch:

Can you have a look?

thanks,

Erik Rijkers

On 25/02/17 00:05, Erik Rijkers wrote:
> On 2017-02-24 22:58, Petr Jelinek wrote:
>> On 23/02/17 01:41, Petr Jelinek wrote:
>>> On 23/02/17 01:02, Erik Rijkers wrote:
>>>> On 2017-02-22 18:13, Erik Rijkers wrote:
>>>>> On 2017-02-22 14:48, Erik Rijkers wrote:
>>>>>> On 2017-02-22 13:03, Petr Jelinek wrote:
>>>>>>
>>>>>>> 0001-Skip-unnecessary-snapshot-builds.patch
>>>>>>> 0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch
>>>>>>> 0003-Fix-xl_running_xacts-usage-in-snapshot-builder.patch
>>>>>>> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver.patch
>>>>>>> 0002-Fix-after-trigger-execution-in-logical-replication.patch
>>>>>>> 0003-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION.patch
>>>>>>> 0001-Logical-replication-support-for-initial-data-copy-v5.patch
>>>>>>
>>>>>> It works well now, or at least my particular test case seems now
>>>>>> solved.
>>>>>
>>>>> Cried victory too early, I'm afraid.
>>>>>
>>>>
>>>> I got into a 'hung' state while repeating pgbench_derail2.sh.
>>>>
>>>> Below is some state. I notice that master pg_stat_replication.syaye is
>>>> 'startup'.
>>>> Maybe I should only start the test after that state has changed. Any
>>>> of the
>>>> other possible values (catchup, streaming) wuold be OK, I would think.
>>>>
>>>
>>> I think that's known issue (see comment in tablesync.c about hanging
>>> forever). I think I may have fixed it locally.
>>>
>>> I will submit patch once I fixed the other snapshot issue (I managed to
>>> reproduce it as well, although very rarely so it's rather hard to test).
>>>
>>
>> Hi,
>>
>> Here it is. But check also the snapbuild related thread for updated
>> patches related to that (the issue you had with this not copying all
>> rows is yet another pre-existing Postgres bug).
>>
>
>
> The four earlier snapbuild patches apply cleanly, but
> then I get errors while applying
> 0001-Logical-replication-support-for-initial-data-copy-v6.patch:
>
>
> patching file src/test/regress/expected/sanity_check.out
> (Stripping trailing CRs from patch.)
> patching file src/test/regress/expected/subscription.out
> Hunk #2 FAILED at 25.
> 1 out of 2 hunks FAILED -- saving rejects to file
> src/test/regress/expected/subscription.out.rej
> (Stripping trailing CRs from patch.)
> patching file src/test/regress/sql/object_address.sql
> (Stripping trailing CRs from patch.)
> patching file src/test/regress/sql/subscription.sql
> (Stripping trailing CRs from patch.)
> patching file src/test/subscription/t/001_rep_changes.pl
> Hunk #9 succeeded at 175 with fuzz 2.
> Hunk #10 succeeded at 193 (offset -9 lines).
> (Stripping trailing CRs from patch.)
> patching file src/test/subscription/t/002_types.pl
> (Stripping trailing CRs from patch.)
> can't find file to patch at input line 4296
> Perhaps you used the wrong -p or --strip option?
> The text leading up to this was:
> --------------------------
> |diff --git a/src/test/subscription/t/003_constraints.pl
> b/src/test/subscription/t/003_constraints.pl
> |index 17d4565..9543b91 100644
> |--- a/src/test/subscription/t/003_constraints.pl
> |+++ b/src/test/subscription/t/003_constraints.pl
> --------------------------
> File to patch:
>
>
> Can you have a look?
>

Hi,

I think you are missing the other fixes (this specific error says that
you didn't apply
0002-Fix-after-trigger-execution-in-logical-replication.patch).

There is now a lot of fixes for existing code that this patch depends
on. Hopefully some of the fixes get committed soonish.

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

On 2017-02-25 00:08, Petr Jelinek wrote:
>
> There is now a lot of fixes for existing code that this patch depends
> on. Hopefully some of the fixes get committed soonish.

Indeed - could you look over the below list of 8 patches; is it correct
and in the right (apply) order?

0001-Use-asynchronous-connect-API-in-libpqwalreceiver.patch
0002-Fix-after-trigger-execution-in-logical-replication.patch
0003-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION.patch
snapbuild-v3-0001-Reserve-global-xmin-for-create-slot-snasphot-export.patch
snapbuild-v3-0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch
snapbuild-v3-0003-Fix-xl_running_xacts-usage-in-snapshot-builder.patch
snapbuild-v3-0004-Skip-unnecessary-snapshot-builds.patch
0001-Logical-replication-support-for-initial-data-copy-v6.patch

(they do apply & compile like this...)

On 25/02/17 00:39, Erik Rijkers wrote:
> On 2017-02-25 00:08, Petr Jelinek wrote:
>>
>> There is now a lot of fixes for existing code that this patch depends
>> on. Hopefully some of the fixes get committed soonish.
>
> Indeed - could you look over the below list of 8 patches; is it correct
> and in the right (apply) order?
>
> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver.patch
> 0002-Fix-after-trigger-execution-in-logical-replication.patch
> 0003-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION.patch
> snapbuild-v3-0001-Reserve-global-xmin-for-create-slot-snasphot-export.patch
> snapbuild-v3-0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch
>
> snapbuild-v3-0003-Fix-xl_running_xacts-usage-in-snapshot-builder.patch
> snapbuild-v3-0004-Skip-unnecessary-snapshot-builds.patch
> 0001-Logical-replication-support-for-initial-data-copy-v6.patch
>

Yes that should be correct.

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

On 2017-02-25 00:40, Petr Jelinek wrote:

> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver.patch
> 0002-Fix-after-trigger-execution-in-logical-replication.patch
> 0003-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION.patch
> snapbuild-v3-0001-Reserve-global-xmin-for-create-slot-snasphot-export.patch
> snapbuild-v3-0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch
> snapbuild-v3-0003-Fix-xl_running_xacts-usage-in-snapshot-builder.patch
> snapbuild-v3-0004-Skip-unnecessary-snapshot-builds.patch
> 0001-Logical-replication-support-for-initial-data-copy-v6.patch

Here are some results. There is improvement although it's not an
unqualified success.

Several repeat-runs of pgbench_derail2.sh, with different parameters for
number-of-client yielded an output file each.

Those show that logrep is now pretty stable when there is only 1 client
(pgbench -c 1). But it starts making mistakes with 4, 8, 16 clients.
I'll just show a grep of the output files; I think it is
self-explicatory:

Output-files (lines counted with grep | sort | uniq -c):

-- out_20170225_0129.txt
250 -- pgbench -c 1 -j 8 -T 10 -P 5 -n
250 -- All is well.

-- out_20170225_0654.txt
25 -- pgbench -c 4 -j 8 -T 10 -P 5 -n
24 -- All is well.
1 -- Not good, but breaking out of wait (waited more than 60s)

-- out_20170225_0711.txt
25 -- pgbench -c 8 -j 8 -T 10 -P 5 -n
23 -- All is well.
2 -- Not good, but breaking out of wait (waited more than 60s)

-- out_20170225_0803.txt
25 -- pgbench -c 16 -j 8 -T 10 -P 5 -n
11 -- All is well.
14 -- Not good, but breaking out of wait (waited more than 60s)

So, that says:
1 clients: 250x success, zero fail (250 not a typo, ran this overnight)
4 clients: 24x success, 1 fail
8 clients: 23x success, 2 fail
16 clients: 11x success, 14 fail

I want to repeat what I said a few emails back: problems seem to
disappear when a short wait state is introduced (directly after the
'alter subscription sub1 enable' line) to give the logrep machinery time
to 'settle'. It makes one think of a timing error somewhere (now don't
ask me where..).

To show that, here is pgbench_derail2.sh output that waited 10 seconds
(INIT_WAIT in the script) as such a 'settle' period works faultless
(with 16 clients):

-- out_20170225_0852.txt
25 -- pgbench -c 16 -j 8 -T 10 -P 5 -n
25 -- All is well.

QED.

(By the way, no hanged sessions so far, so that's good)

thanks

Erik Rijkers

On 25/02/17 09:40, Erik Rijkers wrote:
> On 2017-02-25 00:40, Petr Jelinek wrote:
>
>> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver.patch
>> 0002-Fix-after-trigger-execution-in-logical-replication.patch
>> 0003-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION.patch
>> snapbuild-v3-0001-Reserve-global-xmin-for-create-slot-snasphot-export.patch
>>
>> snapbuild-v3-0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch
>>
>> snapbuild-v3-0003-Fix-xl_running_xacts-usage-in-snapshot-builder.patch
>> snapbuild-v3-0004-Skip-unnecessary-snapshot-builds.patch
>> 0001-Logical-replication-support-for-initial-data-copy-v6.patch
>
> Here are some results. There is improvement although it's not an
> unqualified success.
>

Yep, I found yet another bug in snapbuild (see the relevant thread). I
hope with the updated patches from there (now 5 of them) it should
finally work correctly.

> I want to repeat what I said a few emails back: problems seem to
> disappear when a short wait state is introduced (directly after the
> 'alter subscription sub1 enable' line) to give the logrep machinery time
> to 'settle'. It makes one think of a timing error somewhere (now don't
> ask me where..).

I think that's because if you sleep, the COPY finishes in meantime and
so there is no concurrency with pgbench when the initial snapshot is
being taken so that's not solution for production.

>
> (By the way, no hanged sessions so far, so that's good)
>

Great.

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

On 2017-02-26 01:45, Petr Jelinek wrote:

Again, much better... :

-- out_20170226_0724.txt
25 -- pgbench -c 1 -j 8 -T 10 -P 5 -n
25 -- All is well.
-- out_20170226_0751.txt
25 -- pgbench -c 4 -j 8 -T 10 -P 5 -n
25 -- All is well.
-- out_20170226_0819.txt
25 -- pgbench -c 8 -j 8 -T 10 -P 5 -n
25 -- All is well.
-- out_20170226_0844.txt
25 -- pgbench -c 16 -j 8 -T 10 -P 5 -n
25 -- All is well.
-- out_20170226_0912.txt
25 -- pgbench -c 32 -j 8 -T 10 -P 5 -n
25 -- All is well.
-- out_20170226_0944.txt
25 -- scale 5 clients 1 INIT_WAIT 0 CLEAN_ONLY=
25 -- pgbench -c 1 -j 8 -T 10 -P 5 -n
25 -- All is well.

.... but not perfect: with the next scale up (pgbench scale 25) I got:

-- out_20170226_1001.txt
3 -- scale 25 clients 1 INIT_WAIT 0 CLEAN_ONLY=
3 -- pgbench -c 1 -j 8 -T 10 -P 5 -n
2 -- All is well.
1 -- Not good, but breaking out of wait (waited more than 60s)

It looks like something got stuck at DROP SUBSCRIPTION again which, I
think, derives from this line:
echo "drop subscription if exists sub1" | psql -qXp $port2

I don't know exactly what is useful/useless to report; below is the
state of some tables/views (note that this is from 31 minutes after the
fact (see 'duration' in the first query)), and a backtrace :

$ ./view.sh
select current_setting('port') as port;
port
------
6973
(1 row)

select
rpad(now()::text,19) as now
, pid as pid
, application_name as app
, state as state
, wait_event as wt_evt
, wait_event_type as wt_evt_type
, date_trunc('second', query_start::timestamp) as query_start
, substring((now() - query_start)::text, 1, position('.' in (now() -
query_start)::text)-1) as duration
, query
from pg_stat_activity
where query !~ 'pg_stat_activity'
;
now | pid | app
| state | wt_evt | wt_evt_type | query_start
| duration | query
---------------------+-------+---------------------------------------------+--------+------------------------+-------------+---------------------+----------+----------------------------------
2017-02-26 10:42:43 | 28232 | logical replication worker 31929
| active | relation | Lock |
| |
2017-02-26 10:42:43 | 28237 | logical replication worker 31929 sync
31906 | | LogicalSyncStateChange | IPC |
| |
2017-02-26 10:42:43 | 28242 | logical replication worker 31929 sync
31909 | | transactionid | Lock |
| |
2017-02-26 10:42:43 | 32023 | psql
| active | BgWorkerShutdown | IPC | 2017-02-26 10:10:52
| 00:31:51 | drop subscription if exists sub1
(4 rows)

select * from pg_stat_replication;
pid | usesysid | usename | application_name | client_addr |
client_hostname | client_port | backend_start | backend_xmin | state |
sent_location | write_location | flush_location | replay_location |
sync_priority | sync_state
-----+----------+---------+------------------+-------------+-----------------+-------------+---------------+--------------+-------+---------------+----------------+----------------+-----------------+---------------+------------
(0 rows)

select * from pg_stat_subscription;
subid | subname | pid | relid | received_lsn |
last_msg_send_time | last_msg_receipt_time |
latest_end_lsn | latest_end_time
-------+---------+-------+-------+--------------+-------------------------------+-------------------------------+----------------+-------------------------------
31929 | sub1 | 28242 | 31909 | | 2017-02-26
10:07:05.723093+01 | 2017-02-26 10:07:05.723093+01 | |
2017-02-26 10:07:05.723093+01
31929 | sub1 | 28237 | 31906 | | 2017-02-26
10:07:04.721229+01 | 2017-02-26 10:07:04.721229+01 | |
2017-02-26 10:07:04.721229+01
31929 | sub1 | 28232 | | 1/73497468 |
| 2017-02-26 10:07:47.781883+01 | 1/59A73EF8 | 2017-02-26
10:07:04.720595+01
(3 rows)

select * from pg_subscription;
subdbid | subname | subowner | subenabled | subconninfo | subslotname |
subpublications
---------+---------+----------+------------+-------------+-------------+-----------------
16384 | sub1 | 10 | t | port=6972 | sub1 |
{pub1}
(1 row)

select * from pg_subscription_rel;
srsubid | srrelid | srsubstate | srsublsn
---------+---------+------------+------------
31929 | 31912 | i |
31929 | 31917 | i |
31929 | 31909 | d |
31929 | 31906 | w | 1/73498F90
(4 rows)

Dunno if a backtrace is is useful

$ gdb -pid 32023 (from the DROP SUBSCRIPTION line of the first query)
[...]
(gdb) bt
#0 0x00000030fcee8f13 in __epoll_wait_nocancel () from /lib64/libc.so.6
#1 0x00000000006fba86 in WaitEventSetWaitBlock (nevents=1,
occurred_events=0x7fff66e74dc0, cur_timeout=1000, set=0x2d15560) at
latch.c:997
#2 WaitEventSetWait (set=set(at)entry=0x2d15560,
timeout=timeout(at)entry=1000,
occurred_events=occurred_events(at)entry=0x7fff66e74dc0,
nevents=nevents(at)entry=1,
wait_event_info=wait_event_info(at)entry=134217728)
at latch.c:949
#3 0x00000000006fbefc in WaitLatchOrSocket (latch=0x7f74ec2d5cb4,
wakeEvents=wakeEvents(at)entry=25, sock=sock(at)entry=-1,
timeout=timeout(at)entry=1000,
wait_event_info=wait_event_info(at)entry=134217728)
at latch.c:349
#4 0x00000000006fbfd0 in WaitLatch (latch=<optimized out>,
wakeEvents=wakeEvents(at)entry=25, timeout=timeout(at)entry=1000,
wait_event_info=wait_event_info(at)entry=134217728) at latch.c:303
#5 0x00000000006c764f in logicalrep_worker_stop
(subid=subid(at)entry=31929, relid=relid(at)entry=0) at launcher.c:404
#6 0x00000000005c44fa in DropSubscription (stmt=stmt(at)entry=0x2d6fec0)
at subscriptioncmds.c:757
#7 0x0000000000724ab9 in ProcessUtilitySlow
(pstate=pstate(at)entry=0x2d0d978, pstmt=pstmt(at)entry=0x2d70220,
queryString=queryString(at)entry=0x2d6f488 "drop subscription if exists
sub1",
context=context(at)entry=PROCESS_UTILITY_TOPLEVEL,
params=params(at)entry=0x0,
completionTag=completionTag(at)entry=0x7fff66e757f0 "", dest=0x2d70318) at
utility.c:1620
#8 0x0000000000723f69 in standard_ProcessUtility (pstmt=0x2d70220,
queryString=0x2d6f488 "drop subscription if exists sub1",
context=PROCESS_UTILITY_TOPLEVEL, params=0x0, dest=0x2d70318,
completionTag=0x7fff66e757f0 "") at utility.c:922
#9 0x00007f74ecd6dd92 in pgss_ProcessUtility (pstmt=0x2d70220,
queryString=0x2d6f488 "drop subscription if exists sub1",
context=PROCESS_UTILITY_TOPLEVEL, params=0x0, dest=0x2d70318,
completionTag=0x7fff66e757f0 "") at pg_stat_statements.c:994
#10 0x0000000000721867 in PortalRunUtility (portal=0x2d05538,
pstmt=0x2d70220, isTopLevel=<optimized out>, setHoldSnapshot=<optimized
out>, dest=<optimized out>, completionTag=0x7fff66e757f0 "")
at pquery.c:1165
#11 0x0000000000722301 in PortalRunMulti (portal=portal(at)entry=0x2d05538,
isTopLevel=isTopLevel(at)entry=1 '\001',
setHoldSnapshot=setHoldSnapshot(at)entry=0 '\000',
dest=dest(at)entry=0x2d70318,
altdest=altdest(at)entry=0x2d70318,
completionTag=completionTag(at)entry=0x7fff66e757f0 "") at pquery.c:1315
#12 0x0000000000722fb8 in PortalRun (portal=portal(at)entry=0x2d05538,
count=count(at)entry=9223372036854775807, isTopLevel=isTopLevel(at)entry=1
'\001', dest=dest(at)entry=0x2d70318, altdest=altdest(at)entry=0x2d70318,
completionTag=completionTag(at)entry=0x7fff66e757f0 "") at pquery.c:788
#13 0x000000000071fefa in exec_simple_query (query_string=0x2d6f488
"drop subscription if exists sub1") at postgres.c:1101
#14 PostgresMain (argc=<optimized out>, argv=argv(at)entry=0x2d18ab8,
dbname=<optimized out>, username=<optimized out>) at postgres.c:4067
#15 0x000000000047571f in BackendRun (port=0x2d0cb40) at
postmaster.c:4310
#16 BackendStartup (port=0x2d0cb40) at postmaster.c:3982
#17 ServerLoop () at postmaster.c:1722
#18 0x00000000006b42a9 in PostmasterMain (argc=argc(at)entry=21,
argv=argv(at)entry=0x2ce5a50) at postmaster.c:1330
#19 0x0000000000636dbc in main (argc=21, argv=0x2ce5a50) at main.c:228

Not yet perfect, but we're getting there...

On 2017-02-26 10:53, Erik Rijkers wrote:

> Not yet perfect, but we're getting there...

Sorry, I made a mistake: I was running the newest patches on master but
the older versions on replica (or more precise: I didn't properly
shutdown the replica so the older version remained up and running during
subsequent testing).

So my last email mentioning the 'DROP SUBSCRIPTION' hang error are
hopefully wrong.

I'll get back when I've repeated these tests. This will take some hours
(at least).

Sorry to cause you these palpitations, perhaps unnecessarily...

Erik Rijkers

With these patches:

-- 0416d87c-09a5-182e-4901-236aec103e9f(at)2ndquadrant(dot)com
Subject: Re: Logical Replication WIP
48.
https://www.postgresql.org/message-id/attachment/49886/0001-Use-asynchronous-connect-API-in-libpqwalreceiver.patch
49.
https://www.postgresql.org/message-id/attachment/49887/0002-Fix-after-trigger-execution-in-logical-replication.patch
50.
https://www.postgresql.org/message-id/attachment/49888/0003-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION.patch

-- 51f65289-54f8-2256-d107-937d662d69f1(at)2ndquadrant(dot)com
Subject: Re: snapbuild woes
48.
https://www.postgresql.org/message-id/attachment/49995/snapbuild-v4-0001-Reserve-global-xmin-for-create-slot-snasphot-export.patch
49.
https://www.postgresql.org/message-id/attachment/49996/snapbuild-v4-0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch
50.
https://www.postgresql.org/message-id/attachment/49997/snapbuild-v4-0003-Prevent-snapshot-builder-xmin-from-going-backwards.patch
51.
https://www.postgresql.org/message-id/attachment/49998/snapbuild-v4-0004-Fix-xl_running_xacts-usage-in-snapshot-builder.patch
52.
https://www.postgresql.org/message-id/attachment/49999/snapbuild-v4-0005-Skip-unnecessary-snapshot-builds.patch

-- c0f90176-efff-0770-1e79-0249fb4b9b0c(at)2ndquadrant(dot)com
Subject: Re: Logical replication existing data copy
48.
https://www.postgresql.org/message-id/attachment/49977/0001-Logical-replication-support-for-initial-data-copy-v6.patch

logical replication now seems pretty stable, at least for the limited
testcase that I am using. I've done dozens of pgbench_derail2.sh runs
without failure. I am now changing the pgbench-test to larger scale
(pgbench -is) and longer periods (-T) which makes running the test slow
(both instances are running on a modest desktop with a single 7200
disk). It is quite a bit slower than I expected (a 5-minute pgbench
scale 5, with 8 clients, takes, after it has finished on master, another
2-3 minutes to get synced on the replica). I suppose it's just a
hardware limitation. I set max_sync_workers_per_subscription to 6 (from
default 2) but it doesn't help much (at all).

To be continued...

Thanks,

Erik Rijkers

On 27/02/17 11:07, Erik Rijkers wrote:
> With these patches:
>
> -- 0416d87c-09a5-182e-4901-236aec103e9f(at)2ndquadrant(dot)com
> Subject: Re: Logical Replication WIP
> 48.
> https://www.postgresql.org/message-id/attachment/49886/0001-Use-asynchronous-connect-API-in-libpqwalreceiver.patch
>
> 49.
> https://www.postgresql.org/message-id/attachment/49887/0002-Fix-after-trigger-execution-in-logical-replication.patch
>
> 50.
> https://www.postgresql.org/message-id/attachment/49888/0003-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION.patch
>
>
> -- 51f65289-54f8-2256-d107-937d662d69f1(at)2ndquadrant(dot)com
> Subject: Re: snapbuild woes
> 48.
> https://www.postgresql.org/message-id/attachment/49995/snapbuild-v4-0001-Reserve-global-xmin-for-create-slot-snasphot-export.patch
>
> 49.
> https://www.postgresql.org/message-id/attachment/49996/snapbuild-v4-0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch
>
> 50.
> https://www.postgresql.org/message-id/attachment/49997/snapbuild-v4-0003-Prevent-snapshot-builder-xmin-from-going-backwards.patch
>
> 51.
> https://www.postgresql.org/message-id/attachment/49998/snapbuild-v4-0004-Fix-xl_running_xacts-usage-in-snapshot-builder.patch
>
> 52.
> https://www.postgresql.org/message-id/attachment/49999/snapbuild-v4-0005-Skip-unnecessary-snapshot-builds.patch
>
>
> -- c0f90176-efff-0770-1e79-0249fb4b9b0c(at)2ndquadrant(dot)com
> Subject: Re: Logical replication existing data copy
> 48.
> https://www.postgresql.org/message-id/attachment/49977/0001-Logical-replication-support-for-initial-data-copy-v6.patch
>
>
>
> logical replication now seems pretty stable, at least for the limited
> testcase that I am using. I've done dozens of pgbench_derail2.sh runs
> without failure. I am now changing the pgbench-test to larger scale
> (pgbench -is) and longer periods (-T) which makes running the test slow
> (both instances are running on a modest desktop with a single 7200
> disk). It is quite a bit slower than I expected (a 5-minute pgbench
> scale 5, with 8 clients, takes, after it has finished on master, another
> 2-3 minutes to get synced on the replica). I suppose it's just a
> hardware limitation. I set max_sync_workers_per_subscription to 6 (from
> default 2) but it doesn't help much (at all).
>
> To be continued...
>

Thanks,

The performance was why in original patch I wanted the apply process to
default to synchronous_commit = off as without it the apply performance
(due to applying transactions individually and in sequences) is quite
lackluster.

It can be worked around using user that has synchronous_commit = off set
via ALTER ROLE as owner of the subscription.

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

On 2017-02-27 15:08, Petr Jelinek wrote:
>
> The performance was why in original patch I wanted the apply process to
> default to synchronous_commit = off as without it the apply performance
> (due to applying transactions individually and in sequences) is quite
> lackluster.
>
> It can be worked around using user that has synchronous_commit = off
> set
> via ALTER ROLE as owner of the subscription.
>

Wow, that's a huge difference in speed.

I set
ALTER ROLE aardvark synchronous_commit = off;

during the first iteration of a 10x pgbench-test (so the first was still
done with it 'on'):
here the pertinent grep | uniq -c lines:

-- out_20170228_0004.txt
10 -- pgbench -c 16 -j 8 -T 900 -P 180 -n -- scale 25
10 -- All is well.
1 -- 1325 seconds total.
9 -- 5 seconds total.

And that 5 seconds is a hardcoded wait; so it's probably even quicker.

This is a slowish machine but that's a really spectacular difference.
It's the difference between keeping up or getting lost.

Would you remind me why synchronous_commit = on was deemed a better
default? This thread isn't very clear about it (not the 'logical
replication WIP' thread).

thanks,

Erik Rijkers

On 2017-02-28 07:38, Erik Rijkers wrote:
> On 2017-02-27 15:08, Petr Jelinek wrote:

> 0001-Use-asynchronous-connect-API-in-libpqwalreceiver.patch
> +
> 0002-Fix-after-trigger-execution-in-logical-replication.patch
> +
> 0003-Add-RENAME-support-for-PUBLICATIONs-and-SUBSCRIPTION.patch
> +
> snapbuild-v4-0001-Reserve-global-xmin-for-create-slot-snasphot-export.patch
> +
> snapbuild-v4-0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch+
> snapbuild-v4-0003-Prevent-snapshot-builder-xmin-from-going-backwards.patch
> +
> snapbuild-v4-0004-Fix-xl_running_xacts-usage-in-snapshot-builder.patch
> +
> snapbuild-v4-0005-Skip-unnecessary-snapshot-builds.patch
> +
> 0001-Logical-replication-support-for-initial-data-copy-v6.patch

This is the most frequent error that happens while doing pgbench-runs
over logical replication: I run it continuously all day, and every few
hours an error occurs of the kind seen below: a table (pgbench_history,
mostly) ends up 1 row short (673466 instead of 673467). I have the
script wait a long time before calling it an error (because in theory it
could still 'finish', and end successfully (although that has not
happened yet, once the system got into this state).

-- pgbench -c 16 -j 8 -T 120 -P 24 -n -M simple -- scale 25

[...]
6972 a,b,t,h: 2500000 25 250 673467 e53236c09 643235708
f952814c3 559d618cd master
6973 a,b,t,h: 2500000 25 250 673466 e53236c09 643235708
f952814c3 4b09337e3 replica NOK a22fb00a6
-- wait another 5 s (total 20 s) (unchanged 1)
-- getting md5 (cb)
6972 a,b,t,h: 2500000 25 250 673467 e53236c09 643235708
f952814c3 559d618cd master
6973 a,b,t,h: 2500000 25 250 673466 e53236c09 643235708
f952814c3 4b09337e3 replica NOK a22fb00a6
-- wait another 5 s (total 25 s) (unchanged 2)
-- getting md5 (cb)
6972 a,b,t,h: 2500000 25 250 673467 e53236c09 643235708
f952814c3 559d618cd master
6973 a,b,t,h: 2500000 25 250 673466 e53236c09 643235708
f952814c3 4b09337e3 replica NOK a22fb00a6
-- wait another 5 s (total 30 s) (unchanged 3)
-- getting md5 (cb)
6972 a,b,t,h: 2500000 25 250 673467 e53236c09 643235708
f952814c3 559d618cd master
6973 a,b,t,h: 2500000 25 250 673466 e53236c09 643235708
f952814c3 4b09337e3 replica NOK a22fb00a6
-- wait another 5 s (total 35 s) (unchanged 4)

I gathered some info in this (proabably deadlocked) state in the hope
there is something suspicious in there:

UID PID PPID C STIME TTY STAT TIME CMD
rijkers 71203 1 0 20:06 pts/57 S 0:00 postgres -D
/var/data1/pg_stuff/pg_installations/pgsql.logical_replication2/data -p
6973 -c wal_level=replica [...]
rijkers 71214 71203 0 20:06 ? Ss 0:00 \_ postgres:
logger process
rijkers 71216 71203 0 20:06 ? Ss 0:00 \_ postgres:
checkpointer process
rijkers 71217 71203 0 20:06 ? Ss 0:00 \_ postgres:
writer process
rijkers 71218 71203 0 20:06 ? Ss 0:00 \_ postgres: wal
writer process
rijkers 71219 71203 0 20:06 ? Ss 0:00 \_ postgres:
autovacuum launcher process
rijkers 71220 71203 0 20:06 ? Ss 0:00 \_ postgres: stats
collector process
rijkers 71221 71203 0 20:06 ? Ss 0:00 \_ postgres:
bgworker: logical replication launcher
rijkers 71222 71203 0 20:06 ? Ss 0:00 \_ postgres:
bgworker: logical replication worker 30042

rijkers 71201 1 0 20:06 pts/57 S 0:00 postgres -D
/var/data1/pg_stuff/pg_installations/pgsql.logical_replication/data -p
6972 -c wal_level=logical [...]
rijkers 71206 71201 0 20:06 ? Ss 0:00 \_ postgres:
logger process
rijkers 71208 71201 0 20:06 ? Ss 0:00 \_ postgres:
checkpointer process
rijkers 71209 71201 0 20:06 ? Ss 0:00 \_ postgres:
writer process
rijkers 71210 71201 0 20:06 ? Ss 0:00 \_ postgres: wal
writer process
rijkers 71211 71201 0 20:06 ? Ss 0:00 \_ postgres:
autovacuum launcher process
rijkers 71212 71201 0 20:06 ? Ss 0:00 \_ postgres: stats
collector process
rijkers 71213 71201 0 20:06 ? Ss 0:00 \_ postgres:
bgworker: logical replication launcher
rijkers 71223 71201 0 20:06 ? Ss 0:00 \_ postgres: wal
sender process rijkers [local] idle

-- replica:
port | shared_buffers | work_mem | m_w_m | e_c_s
------+----------------+----------+-------+-------
6973 | 100MB | 50MB | 2GB | 64GB
(1 row)

select current_setting('port') as port
, datname as db
, to_char(pg_database_size(datname), '9G999G999G999G999')
|| ' (' || pg_size_pretty(pg_database_size(datname)) || ')' as
dbsize
, pid
, application_name as app
, xact_start
, query_start
, regexp_replace( cast(now() - query_start as text),
E'\.[[:digit:]]+\$', '') as duration
, state
, wait_event_type as wt_evt_type
, wait_event as wt_evt
from pg_stat_activity
where query !~ 'pg_stat_activity'
-- and query != '<IDLE>'
port | db | dbsize | pid | app
| xact_start | query_start | duration | state |
wt_evt_type | wt_evt
------+--------+-----------------------------+-------+----------------------------------+------------+-------------+----------+-------+-------------+------------------
6973 | testdb | 817,243,955 (779 MB) | 71222 | logical
replication worker 30042 | | | | idle |
Activity | LogicalApplyMain
(1 row)

select * from pg_locks;
locktype | database | relation | page | tuple | virtualxid |
transactionid | classid | objid | objsubid | virtualtransaction | pid
| mode | granted | fastpath
------------+----------+----------+------+-------+------------+---------------+---------+-------+----------+--------------------+-------+-----------------+---------+----------
relation | 16384 | 11547 | | | |
| | | | 4/568 | 77713 |
AccessShareLock | t | t
virtualxid | | | | | 4/568 |
| | | | 4/568 | 77713 |
ExclusiveLock | t | t
(2 rows)

select * from pg_stat_subscription;
subid | subname | pid | relid | received_lsn |
last_msg_send_time | last_msg_receipt_time |
latest_end_lsn | latest_end_time
-------+---------+-------+-------+--------------+-------------------------------+-------------------------------+----------------+-------------------------------
30042 | sub1 | 71222 | | 29/6C91C980 | 2017-02-28
20:11:50.818774+01 | 2017-02-28 20:11:50.818845+01 | 29/6C91C980 |
2017-02-28 20:11:50.818774+01
(1 row)

select * from pg_subscription;
subdbid | subname | subowner | subenabled | subconninfo | subslotname |
subpublications
---------+---------+----------+------------+-------------+-------------+-----------------
16384 | sub1 | 10 | t | port=6972 | sub1 |
{pub1}
(1 row)

select * from pg_subscription_rel;
srsubid | srrelid | srsubstate | srsublsn
---------+---------+------------+----------
30042 | 30022 | r |
30042 | 30019 | r |
30042 | 30030 | r |
30042 | 30025 | r |
(4 rows)

-- master
\c - - - 6972
select pid , usesysid /* , usename */ , application_name /* ,
client_addr */ /* , client_hostname */ /* , client_port */
, backend_start , backend_xmin , state , sent_location ,
write_location , flush_location
, replay_location , sync_priority , sync_state from
pg_stat_replication;
pid | usesysid | application_name | backend_start |
backend_xmin | state | sent_location | write_location |
flush_location | replay_location | sync_priority | sync_state
-------+----------+------------------+-----------------------------+--------------+-----------+---------------+----------------+----------------+-----------------+---------------+------------
71223 | 10 | sub1 | 2017-02-28 20:06:50.3357+01 |
| streaming | 29/88BC9BB0 | 29/88BC9BB0 | 29/88BC9BB0 |
29/88BC9BB0 | 0 | async
(1 row)

Erik Rijkers

On 28/02/17 20:36, Erik Rijkers wrote:
> This is the most frequent error that happens while doing pgbench-runs
> over logical replication: I run it continuously all day, and every few
> hours an error occurs of the kind seen below: a table (pgbench_history,
> mostly) ends up 1 row short (673466 instead of 673467). I have the
> script wait a long time before calling it an error (because in theory it
> could still 'finish', and end successfully (although that has not
> happened yet, once the system got into this state).
>

Yeah it's unlikely if it's just one row. It suggests there might still
be some snapbuild issue, but I don't immediately see one and I run
couple thousand repeats of the test without getting any inconsistency.
Will continue digging.

>
> I gathered some info in this (proabably deadlocked) state in the hope
> there is something suspicious in there:
>

Hmm that didn't really reveal much :(

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

On Tue, Feb 28, 2017 at 12:08 PM, Erik Rijkers <er(at)xs4all(dot)nl> wrote:
> Would you remind me why synchronous_commit = on was deemed a better default?

I'm wondering about that, too. If you're trying to do logical
synchronous replication, then maybe there's some argument there,
although even in that case I am not sure it's actually necessary. But
if you're doing asynchronous logical replication, it seems not to make
much sense. I mean, walwriter is going to flush the WAL to disk
within a fraction of a second; why would we wait for that to happen
instead of getting on with replicating the next transaction meanwhile?

(There may well be an aspect to this I'm missing, so please forgive me
if the above is off-base.)

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 04/03/17 06:46, Robert Haas wrote:
> On Tue, Feb 28, 2017 at 12:08 PM, Erik Rijkers <er(at)xs4all(dot)nl> wrote:
>> Would you remind me why synchronous_commit = on was deemed a better default?
>
> I'm wondering about that, too. If you're trying to do logical
> synchronous replication, then maybe there's some argument there,
> although even in that case I am not sure it's actually necessary. But
> if you're doing asynchronous logical replication, it seems not to make
> much sense. I mean, walwriter is going to flush the WAL to disk
> within a fraction of a second; why would we wait for that to happen
> instead of getting on with replicating the next transaction meanwhile?
>

I do agree. And even when doing synchronous replication it should not be
problem. We do have code already in place which takes care of reporting
correct write/flush position in the situation where upstream does
syncrep but downstream has synccommit off.

The only anomaly I could think of in terms of having sync commit off on
downstream is that some replicated data that were visible will disappear
after a crash only to reappear again once replication catches up to
where it has been before when doing asynchronous replication. That does
not strike me like good enough reason to have by default something like
order of magnitude worse performance.

So I think we should do it, but it needs to be configurable, my original
patch added GUC for it, Peter wanted it to be configurable per
subscription. I guess we could add it as another option to the list of
WITH (...) options for CREATE and ALTER SUBSCRIPTION.

I am not going to write the patch immediately as I'd like to get the
initial data copy working correctly first (and I've sunk a lot of time
over last couple of weeks into investigation and fixing of various
existing bugs in the snapshot builder so it's taking longer than I
expected). But the patch for this is trivial anyway. Agreement is the
what we need first.

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

On Sat, Mar 4, 2017 at 11:41 AM, Petr Jelinek
<petr(dot)jelinek(at)2ndquadrant(dot)com> wrote:
> On 04/03/17 06:46, Robert Haas wrote:
>> On Tue, Feb 28, 2017 at 12:08 PM, Erik Rijkers <er(at)xs4all(dot)nl> wrote:
>>> Would you remind me why synchronous_commit = on was deemed a better default?
>> I'm wondering about that, too. If you're trying to do logical
>> synchronous replication, then maybe there's some argument there,
>> although even in that case I am not sure it's actually necessary. But
>> if you're doing asynchronous logical replication, it seems not to make
>> much sense. I mean, walwriter is going to flush the WAL to disk
>> within a fraction of a second; why would we wait for that to happen
>> instead of getting on with replicating the next transaction meanwhile?
>>
>
> I do agree. And even when doing synchronous replication it should not be
> problem. We do have code already in place which takes care of reporting
> correct write/flush position in the situation where upstream does
> syncrep but downstream has synccommit off.
>
> The only anomaly I could think of in terms of having sync commit off on
> downstream is that some replicated data that were visible will disappear
> after a crash only to reappear again once replication catches up to
> where it has been before when doing asynchronous replication. That does
> not strike me like good enough reason to have by default something like
> order of magnitude worse performance.

I see. That's a good reason to have an option, but I agree with your
conclusion.

> So I think we should do it, but it needs to be configurable, my original
> patch added GUC for it, Peter wanted it to be configurable per
> subscription. I guess we could add it as another option to the list of
> WITH (...) options for CREATE and ALTER SUBSCRIPTION.

I don't have a terribly well-considered opinion on this point just
yet, but my initial hunch is that Peter has the right idea.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Hi,

updated and rebased version of the patch attached.

I changed a bit how the table handover is done between tablesync worker
and apply worker.

I also changed tablesync worker to do whole thing including catchup in
single transaction, that might mean more bloat on very active servers
but it's currently the only way to make sure that if it fails it can
restart as otherwise there would be leftover data from previous attempt
with no way of continuing from the point of failure. This means that
some of the synchronization states now only exist in memory and are
never saved in catalog, I separated those to make that clear. Hopefully
this didn't break anything.

I also fixed thinko about how we handle the LSN returned by
CREATE_REPLICATION_SLOT which should fix the missing row issue Erik
reported earlier (this time it wasn't snapbuild.c issue :) ).

And lastly I changed the automagic around exporting, not exporting and
using the snapshot produced by CREATE_REPLICATION_SLOT into explicit
parameter for the CREATE_REPLICATION_SLOT command (and added simple
framework for adding more of those if needed in the future).

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

On 2017-03-06 11:27, Petr Jelinek wrote:
> Hi,
>
> updated and rebased version of the patch attached.
>

I compiled with /only/ this one latest patch:
0001-Logical-replication-support-for-initial-data-copy-v6.patch

Is that correct, or are other patches still needed on top, or
underneath?

Anyway, with that one patch, and even after
alter role ... set synchronous_commit = off;
the process is very slow. (sufficiently slow that I haven't
had the patience to see it to completion yet)

What am I doing wrong?

thanks,

Erik Rijkers

On 2017-03-06 16:10, Erik Rijkers wrote:
> On 2017-03-06 11:27, Petr Jelinek wrote:
>> Hi,
>>
>> updated and rebased version of the patch attached.
>>
>
> I compiled with /only/ this one latest patch:
> 0001-Logical-replication-support-for-initial-data-copy-v6.patch
>
> Is that correct, or are other patches still needed on top, or
> underneath?
>

TWIMC, I'll answer my own question: the correct patchset seems to be
these six:

0001-Reserve-global-xmin-for-create-slot-snasphot-export.patch
0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch
0003-Prevent-snapshot-builder-xmin-from-going-backwards.patch
0004-Fix-xl_running_xacts-usage-in-snapshot-builder.patch
0005-Skip-unnecessary-snapshot-builds.patch
0001-Logical-replication-support-for-initial-data-copy-v6.patch

These compile, make check, and install fine. make check-world is also
without errors.

Logical replication tests are now running again (no errors yet); they'll
have to run for a few hours with varying parameters to gain some
confidence but it's looking good for the moment.

Erik Rijkers

On 06/03/17 23:40, Erik Rijkers wrote:
> On 2017-03-06 16:10, Erik Rijkers wrote:
>> On 2017-03-06 11:27, Petr Jelinek wrote:
>>> Hi,
>>>
>>> updated and rebased version of the patch attached.
>>>
>>
>> I compiled with /only/ this one latest patch:
>> 0001-Logical-replication-support-for-initial-data-copy-v6.patch
>>
>> Is that correct, or are other patches still needed on top, or underneath?
>>
>
> TWIMC, I'll answer my own question: the correct patchset seems to be
> these six:
>
> 0001-Reserve-global-xmin-for-create-slot-snasphot-export.patch
> 0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch
> 0003-Prevent-snapshot-builder-xmin-from-going-backwards.patch
> 0004-Fix-xl_running_xacts-usage-in-snapshot-builder.patch
> 0005-Skip-unnecessary-snapshot-builds.patch
> 0001-Logical-replication-support-for-initial-data-copy-v6.patch
>

Yes the 0004 and 0005 improve performance of snapshot creation
considerably. They're also the reason we uncovered all the snapbuilder
bugs now. Before the performance optimization it was very unlikely for
some of the race conditions to happen as the snapshot would just not be
built until there was less concurrent traffic on the server.

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

On 3/4/17 01:46, Robert Haas wrote:
>> So I think we should do it, but it needs to be configurable, my original
>> patch added GUC for it, Peter wanted it to be configurable per
>> subscription. I guess we could add it as another option to the list of
>> WITH (...) options for CREATE and ALTER SUBSCRIPTION.
>
> I don't have a terribly well-considered opinion on this point just
> yet, but my initial hunch is that Peter has the right idea.

Basically, we need to have some way of setting this that makes sense in
the global scheme of things. We don't want a situation where "sometimes
it does this, sometimes it does that". I'm not set on any specific
mechanism.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On Tue, Mar 7, 2017 at 11:39 AM, Peter Eisentraut
<peter(dot)eisentraut(at)2ndquadrant(dot)com> wrote:
> On 3/4/17 01:46, Robert Haas wrote:
>>> So I think we should do it, but it needs to be configurable, my original
>>> patch added GUC for it, Peter wanted it to be configurable per
>>> subscription. I guess we could add it as another option to the list of
>>> WITH (...) options for CREATE and ALTER SUBSCRIPTION.
>>
>> I don't have a terribly well-considered opinion on this point just
>> yet, but my initial hunch is that Peter has the right idea.
>
> Basically, we need to have some way of setting this that makes sense in
> the global scheme of things. We don't want a situation where "sometimes
> it does this, sometimes it does that". I'm not set on any specific
> mechanism.

I think we are on the same page.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 2017-03-06 11:27, Petr Jelinek wrote:

> 0001-Reserve-global-xmin-for-create-slot-snasphot-export.patch +
> 0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch+
> 0003-Prevent-snapshot-builder-xmin-from-going-backwards.patch +
> 0004-Fix-xl_running_xacts-usage-in-snapshot-builder.patch +
> 0005-Skip-unnecessary-snapshot-builds.patch +
> 0001-Logical-replication-support-for-initial-data-copy-v6.patch

I use three different machines (2 desktop, 1 server) to test logical
replication, and all three have now at least once failed to correctly
synchronise a pgbench session (amidst many succesful runs, of course)

I attach an output-file from the test-program, with the 2 logfiles
(master+replica) of the failed run. The outputfile
(out_20170307_1613.txt) contains the output of 5 runs of
pgbench_derail2.sh. The first run failed, the next 4 were ok.

But that's probably not very useful; perhaps is pg_waldump more useful?
From what moment, or leading up to what moment, or period, is a
pg_waldump(s) useful? I can run it from the script, repeatedly, and
only keep the dumped files when things go awry. Would that make sense?

Any other ideas welcome.

thanks,

Erik Rijkers

On 07/03/17 23:30, Erik Rijkers wrote:
> On 2017-03-06 11:27, Petr Jelinek wrote:
>
>> 0001-Reserve-global-xmin-for-create-slot-snasphot-export.patch +
>> 0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch+
>> 0003-Prevent-snapshot-builder-xmin-from-going-backwards.patch +
>> 0004-Fix-xl_running_xacts-usage-in-snapshot-builder.patch +
>> 0005-Skip-unnecessary-snapshot-builds.patch +
>> 0001-Logical-replication-support-for-initial-data-copy-v6.patch
>
> I use three different machines (2 desktop, 1 server) to test logical
> replication, and all three have now at least once failed to correctly
> synchronise a pgbench session (amidst many succesful runs, of course)
>
> I attach an output-file from the test-program, with the 2 logfiles
> (master+replica) of the failed run. The outputfile
> (out_20170307_1613.txt) contains the output of 5 runs of
> pgbench_derail2.sh. The first run failed, the next 4 were ok.
>
> But that's probably not very useful; perhaps is pg_waldump more useful?
> From what moment, or leading up to what moment, or period, is a
> pg_waldump(s) useful? I can run it from the script, repeatedly, and
> only keep the dumped files when things go awry. Would that make sense?

Hi,

yes waldump would be useful, the last segment should be enough, but
possibly all segments mentioned in the log.

The other useful thing would be to turn on log_connections and
log_replication_commands.

And finally if you could dump the contents of pg_subscription_rel,
pg_replication_origin_status on subscriber and pg_replication_slots on
publisher at the end of the failed run that would also help.

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

On 2017-03-08 10:36, Petr Jelinek wrote:
> On 07/03/17 23:30, Erik Rijkers wrote:
>> On 2017-03-06 11:27, Petr Jelinek wrote:
>>
>>> 0001-Reserve-global-xmin-for-create-slot-snasphot-export.patch +
>>> 0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch+
>>> 0003-Prevent-snapshot-builder-xmin-from-going-backwards.patch +
>>> 0004-Fix-xl_running_xacts-usage-in-snapshot-builder.patch +
>>> 0005-Skip-unnecessary-snapshot-builds.patch +
>>> 0001-Logical-replication-support-for-initial-data-copy-v6.patch
>>
>> I use three different machines (2 desktop, 1 server) to test logical
>> replication, and all three have now at least once failed to correctly
>> synchronise a pgbench session (amidst many succesful runs, of course)
>
> yes waldump would be useful, the last segment should be enough, but
> possibly all segments mentioned in the log.

I've inserted a pg_waldump call in the program when the md5s remain the
same (on both master and replica) for 5 wait-cycles (= 5 * 5 seconds +
the time it takes to run (8x) the md5s + select count(*), which is more
than a minute on this slow disk (at least the first time))

>
> The other useful thing would be to turn on log_connections and
> log_replication_commands.

done. (so output will be in the log files.)

> pg_subscription_rel, pg_replication_origin_status on subscriber and
> pg_replication_slots on publisher

done. (added to logs)

The attached bz2 contains
- an output file from pgbench_derail2.sh (also attached, as it changes
somewhat all the time); the

- the pg_waldump output from both master (file with .1. in it) and
replica (.2.).

- the 2 logfiles.

file Name:
logrep.20170309_1021.1.1043.scale_25.clients_64.NOK.log

20170309_1021 is the start-time of the script
1 is master (2 is replica)
1043 is the time, 10:43, just before the pg_waldump call

The tail of the logfiles and of the output file will be a little ahead
of the pg_waldump (not more than a few minutes) because I didn't stop
the script while gathering the files manually.

HTH! Let me know if more is needed (more wal, for instance)

thanks,

Erik Rijkers

PS
the attached script now contains some idiosyncrasies of my setup so it
will probably complain here and there when run unaltered elsewhere)

On 2017-03-09 11:06, Erik Rijkers wrote:

>
> file Name:
> logrep.20170309_1021.1.1043.scale_25.clients_64.NOK.log
>
> 20170309_1021 is the start-time of the script
> 1 is master (2 is replica)
> 1043 is the time, 10:43, just before the pg_waldump call

Sorry, that might be confusing. That 10:43 is the time when script
renames and copies the logfiles (not the waldump)

I meant to show the name of the waldump file:

waldump.20170309_1021_1039.1.5.000000010000002700000069.txt.bz2
where:

20170309_1021 is the start-time of the script
1 is master (2 is replica)
5 is wait-state cycles during which all 8 md5s remained the same
1039 is the time, 10:43, just before the pg_waldump call

On 2017-03-09 11:06, Erik Rijkers wrote:
> On 2017-03-08 10:36, Petr Jelinek wrote:
>> On 07/03/17 23:30, Erik Rijkers wrote:
>>> On 2017-03-06 11:27, Petr Jelinek wrote:
>>>
>>>> 0001-Reserve-global-xmin-for-create-slot-snasphot-export.patch +
>>>> 0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch+
>>>> 0003-Prevent-snapshot-builder-xmin-from-going-backwards.patch +
>>>> 0004-Fix-xl_running_xacts-usage-in-snapshot-builder.patch +
>>>> 0005-Skip-unnecessary-snapshot-builds.patch +
>>>> 0001-Logical-replication-support-for-initial-data-copy-v6.patch
>>>
>
> The attached bz2 contains
> - an output file from pgbench_derail2.sh (also attached, as it changes
> somewhat all the time); the
>
> - the pg_waldump output from both master (file with .1. in it) and
> replica (.2.).
>
> - the 2 logfiles.
>

I forgot to include the bash-output file. Now attached. This file
should have been in the bz2 I sent a few minutes ago.

On 3/6/17 05:27, Petr Jelinek wrote:
> updated and rebased version of the patch attached.

Some comments on this patch:

Can we have a better explanation of different snapshot options in
CREATE_REPLICATION_SLOT. We use all these variants in different
places, but it's not fully documented why. Think about interested
users reading this.

errmsg("subscription table %u in subscription %u does not exist",

Use names instead of IDs if possible.

+ libpqrcv_table_list,
+ libpqrcv_table_info,
+ libpqrcv_table_copy,

I don't think these functions belong into the WAL receiver API, since
they are specific to this particular logical replication
implementation. I would just make an API function libpqrc_exec_sql()
that runs a query, and then put the table_*() functions as wrappers
around that into tablesync.c.

Not sure what the worker init stuff in ApplyLauncherShmemInit() is
doing. Could be commented more.

There are a lot of places that do one of

MyLogicalRepWorker->relid == InvalidOid
OidIsValid(MyLogicalRepWorker->relid)

To check whether the current worker is a sync worker. Wrap that into
a function.

Not a fan of adding CommandCounterIncrement() calls at the end of
functions. In some cases, they are not necessary at all. In cases
where they are, the CCI call should be at a higher level between two
function calls with a comment for why the call below needs to see the
changes from the call above.

The index name pg_subscription_rel_map_index/SubscriptionRelMapIndexId
doesn't seem to match existing style, since there is no "map" column.
How about pg_subscription_rel_rel_sub_index? I see we have a
similarly named index for publications.

max_sync_workers_per_subscription could be PGC_SIGHUP, I think. And
the minimum could be 0, to stop any syncing?

pg_subscription_rel.h: I'm not sure under which circumstances we need
to use BKI_ROWTYPE_OID.

Does pg_subscription_rel need an OID column? The index
SubscriptionRelOidIndexId is not used anywhere.

You removed this command from the tests:

ALTER SUBSCRIPTION testsub SET PUBLICATION testpub, testpub1;

I suppose because it causes a connection. We should have an option to
prevent that (NOCONNECT/NOREFRESH?).

Why was the test 'check replication origin was dropped on subscriber'
removed?

Attached also a small patch with some stylistic changes.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 3/6/17 05:27, Petr Jelinek wrote:
> And lastly I changed the automagic around exporting, not exporting and
> using the snapshot produced by CREATE_REPLICATION_SLOT into explicit
> parameter for the CREATE_REPLICATION_SLOT command (and added simple
> framework for adding more of those if needed in the future).

It might be useful to make this into a separate patch, for clarity.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 09/03/17 18:46, Peter Eisentraut wrote:
> On 3/6/17 05:27, Petr Jelinek wrote:
>> updated and rebased version of the patch attached.
>
> Some comments on this patch:
>
> Can we have a better explanation of different snapshot options in
> CREATE_REPLICATION_SLOT. We use all these variants in different
> places, but it's not fully documented why. Think about interested
> users reading this.
>

I am not quite sure what/where do you want me to expand the docs, the
protocol doc explains what the options do, are you missing reasoning for
why we use them in the calling code?

>
> errmsg("subscription table %u in subscription %u does not exist",
>
> Use names instead of IDs if possible.
>

Well, this message is more or less equal to cache lookup failure,
problem is that neither relation nor subscription are guaranteed to
exist if this fails. I can write code that spits two different messages
depending of they do, not quite sure if it's worth it there though.

>
> + libpqrcv_table_list,
> + libpqrcv_table_info,
> + libpqrcv_table_copy,
>
> I don't think these functions belong into the WAL receiver API, since
> they are specific to this particular logical replication
> implementation. I would just make an API function libpqrc_exec_sql()
> that runs a query, and then put the table_*() functions as wrappers
> around that into tablesync.c.
>

Yeah I was wondering about it as well. The reason why it's in
libpqwalreciver is that if we create some libpqrc_exec_sql as you say,
we'll need code that converts the PQresult to something consumable by
backend that has no access to libpq API and that seemed like quite a bit
of boilerplate work. I really don't want to write another libpq-like or
SPI-like interface for this. Maybe it would be acceptable to return
result as tuplestore?

>
> Not sure what the worker init stuff in ApplyLauncherShmemInit() is
> doing. Could be commented more.
>

Eh, I copy pasted comment there from different place, will fix.

>
> max_sync_workers_per_subscription could be PGC_SIGHUP, I think. And
> the minimum could be 0, to stop any syncing?
>
>
> pg_subscription_rel.h: I'm not sure under which circumstances we need
> to use BKI_ROWTYPE_OID.
>
>
> Does pg_subscription_rel need an OID column? The index
> SubscriptionRelOidIndexId is not used anywhere.
>

Ah, leftover from the time it used dependencies for tracking.

>
> You removed this command from the tests:
>
> ALTER SUBSCRIPTION testsub SET PUBLICATION testpub, testpub1;
>
> I suppose because it causes a connection. We should have an option to
> prevent that (NOCONNECT/NOREFRESH?).

NOREFRESH makes more sense I guess.

>
> Why was the test 'check replication origin was dropped on subscriber'
> removed?
>

I don't know what you mean?

>
> Attached also a small patch with some stylistic changes.
>

Thanks.

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

On 09/03/17 18:48, Peter Eisentraut wrote:
> On 3/6/17 05:27, Petr Jelinek wrote:
>> And lastly I changed the automagic around exporting, not exporting and
>> using the snapshot produced by CREATE_REPLICATION_SLOT into explicit
>> parameter for the CREATE_REPLICATION_SLOT command (and added simple
>> framework for adding more of those if needed in the future).
>
> It might be useful to make this into a separate patch, for clarity.
>

Yes, already working on that (at least part of it), since it's useful
for other patches in CF.

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

On 09/03/17 18:48, Peter Eisentraut wrote:
> On 3/6/17 05:27, Petr Jelinek wrote:
>> And lastly I changed the automagic around exporting, not exporting and
>> using the snapshot produced by CREATE_REPLICATION_SLOT into explicit
>> parameter for the CREATE_REPLICATION_SLOT command (and added simple
>> framework for adding more of those if needed in the future).
>
> It might be useful to make this into a separate patch, for clarity.
>

Okay here it is with this part split out. The first patch also help with
Craig's logical decoding on standby so it definitely makes sense to be
split.

This is also rebased on top of the position tracking fix [1] which
together with this patch fixes the error reported by Erik in his
previous email.

I think I resolved all your notes from the review. The only exception
being that the SQL queries are still in libpqwalreceiver.c as we first
need to agree on how the query interface would look like before moving
it around.

[1]
https://www.postgresql.org/message-id/b235fa69-147a-5e09-f8f3-3f780a1abb2e@2ndquadrant.com

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

On 11 March 2017 at 00:33, Petr Jelinek <petr(dot)jelinek(at)2ndquadrant(dot)com> wrote:
> On 09/03/17 18:48, Peter Eisentraut wrote:
>> On 3/6/17 05:27, Petr Jelinek wrote:
>>> And lastly I changed the automagic around exporting, not exporting and
>>> using the snapshot produced by CREATE_REPLICATION_SLOT into explicit
>>> parameter for the CREATE_REPLICATION_SLOT command (and added simple
>>> framework for adding more of those if needed in the future).
>>
>> It might be useful to make this into a separate patch, for clarity.
>>
>
> Okay here it is with this part split out. The first patch also help with
> Craig's logical decoding on standby so it definitely makes sense to be
> split.

Greatly appreciated.

Committing this in chunks makes sense anyway.

I've attached a slightly version that makes pg_recvlogical skip slot
export. The second patch is unchanged, use the copy from the
immediately prior mail.

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

On 13/03/17 03:57, Craig Ringer wrote:
> On 11 March 2017 at 00:33, Petr Jelinek <petr(dot)jelinek(at)2ndquadrant(dot)com> wrote:
>> On 09/03/17 18:48, Peter Eisentraut wrote:
>>> On 3/6/17 05:27, Petr Jelinek wrote:
>>>> And lastly I changed the automagic around exporting, not exporting and
>>>> using the snapshot produced by CREATE_REPLICATION_SLOT into explicit
>>>> parameter for the CREATE_REPLICATION_SLOT command (and added simple
>>>> framework for adding more of those if needed in the future).
>>>
>>> It might be useful to make this into a separate patch, for clarity.
>>>
>>
>> Okay here it is with this part split out. The first patch also help with
>> Craig's logical decoding on standby so it definitely makes sense to be
>> split.
>
> Greatly appreciated.
>
> Committing this in chunks makes sense anyway.
>
> I've attached a slightly version that makes pg_recvlogical skip slot
> export. The second patch is unchanged, use the copy from the
> immediately prior mail.
>

Okay, I merged your changes in.

Here is that merge, plus the updated main patch that replaces all the
SQL interaces in libpqwalreceiver.c with single exec one which uses
tuplestore to send any tuple results back.

For correct working in every situation, it still needs to snapbuild
fixes and also the logical replication origin tracking fix.

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

On 3/14/17 12:12, Petr Jelinek wrote:
>> Committing this in chunks makes sense anyway.
>>
>> I've attached a slightly version that makes pg_recvlogical skip slot
>> export. The second patch is unchanged, use the copy from the
>> immediately prior mail.
>>
>
> Okay, I merged your changes in.
>
> Here is that merge, plus the updated main patch that replaces all the
> SQL interaces in libpqwalreceiver.c with single exec one which uses
> tuplestore to send any tuple results back.
>
> For correct working in every situation, it still needs to snapbuild
> fixes and also the logical replication origin tracking fix.

Committed 0001. Will look at 0002 next.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 14/03/17 22:39, Peter Eisentraut wrote:
> On 3/14/17 12:12, Petr Jelinek wrote:
>>> Committing this in chunks makes sense anyway.
>>>
>>> I've attached a slightly version that makes pg_recvlogical skip slot
>>> export. The second patch is unchanged, use the copy from the
>>> immediately prior mail.
>>>
>>
>> Okay, I merged your changes in.
>>
>> Here is that merge, plus the updated main patch that replaces all the
>> SQL interaces in libpqwalreceiver.c with single exec one which uses
>> tuplestore to send any tuple results back.
>>
>> For correct working in every situation, it still needs to snapbuild
>> fixes and also the logical replication origin tracking fix.
>
> Committed 0001. Will look at 0002 next.
>

Cool, rebased the main patch on top of merge conflicts.

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

The current patch causes a failure in the pg_dump tests, because the
generated CREATE SUBSCRIPTION commands make connection attempts that
don't work. We have the pg_dump option --no-create-subscription-slots
for this, but I suppose we should expand that to
--no-subscription-connect and use the new NOCONNECT option instead.

I'm a bit puzzled at the moment how it worked before, because the
pg_dump test suite does not use that option. But some change like that
is probably useful anyway.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Peter,

* Peter Eisentraut (peter(dot)eisentraut(at)2ndquadrant(dot)com) wrote:
> The current patch causes a failure in the pg_dump tests, because the
> generated CREATE SUBSCRIPTION commands make connection attempts that
> don't work. We have the pg_dump option --no-create-subscription-slots
> for this, but I suppose we should expand that to
> --no-subscription-connect and use the new NOCONNECT option instead.

I'll admit that I've not followed this very closely, so perhaps I'm
misunderstanding, but I thought our prior discussion lead to the idea
that pg_dump would always dump out subscriptions with 'NOCONNECT', so
that a restore wouldn't automatically start trying to connect to another
system.

In which case, I don't quite understand why we need a
"--no-subscription-connect" option.

Thanks!

Stephen

On 20/03/17 21:25, Stephen Frost wrote:
> Peter,
>
> * Peter Eisentraut (peter(dot)eisentraut(at)2ndquadrant(dot)com) wrote:
>> The current patch causes a failure in the pg_dump tests, because the
>> generated CREATE SUBSCRIPTION commands make connection attempts that
>> don't work. We have the pg_dump option --no-create-subscription-slots
>> for this, but I suppose we should expand that to
>> --no-subscription-connect and use the new NOCONNECT option instead.
>
> I'll admit that I've not followed this very closely, so perhaps I'm
> misunderstanding, but I thought our prior discussion lead to the idea
> that pg_dump would always dump out subscriptions with 'NOCONNECT', so
> that a restore wouldn't automatically start trying to connect to another
> system.
>
> In which case, I don't quite understand why we need a
> "--no-subscription-connect" option.
>

Yeah I think that was the agreement as well.

Here is fixed version, also rebased on top of all the changes to pg_dump
tests. Subscriptions are dumped unless --no-subscriptions is specified.
They are dumped with NOCONNECT option (which didn't exist before this
patch so it was bit harder to do the dump by default).

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

On 3/20/17 19:54, Petr Jelinek wrote:
> Here is fixed version, also rebased on top of all the changes to pg_dump
> tests. Subscriptions are dumped unless --no-subscriptions is specified.

The problem with that is that pg_dump will now fail for unprivileged
users. That's a separate problem to solve. I suggest not overloading
this patch with that.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

This patch is looking pretty good to me, modulo the failing pg_dump tests.

Attached is a fixup patch. I have mainly updated some comments and
variable naming for (my) clarity. No functional changes.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 3/20/17 16:08, Peter Eisentraut wrote:
> The current patch causes a failure in the pg_dump tests, because the
> generated CREATE SUBSCRIPTION commands make connection attempts that
> don't work. We have the pg_dump option --no-create-subscription-slots
> for this, but I suppose we should expand that to
> --no-subscription-connect and use the new NOCONNECT option instead.

Small top-up patch to accomplish that.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 22/03/17 13:36, Peter Eisentraut wrote:
> On 3/20/17 16:08, Peter Eisentraut wrote:
>> The current patch causes a failure in the pg_dump tests, because the
>> generated CREATE SUBSCRIPTION commands make connection attempts that
>> don't work. We have the pg_dump option --no-create-subscription-slots
>> for this, but I suppose we should expand that to
>> --no-subscription-connect and use the new NOCONNECT option instead.
>
> Small top-up patch to accomplish that.
>

Works for me. I'd maybe explicitly mention in the docs for
---no-subscription-connect that it dumps subscriptions as CREATE
SUBSCRIPTION ... WITH(NOCONNECT).

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

On 3/21/17 21:38, Peter Eisentraut wrote:
> This patch is looking pretty good to me, modulo the failing pg_dump tests.
>
> Attached is a fixup patch. I have mainly updated some comments and
> variable naming for (my) clarity. No functional changes.

Committed all that.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Hi,

On Thu, Mar 23, 2017 at 09:00:16AM -0400, Peter Eisentraut wrote:
> On 3/21/17 21:38, Peter Eisentraut wrote:
> > This patch is looking pretty good to me, modulo the failing pg_dump tests.
> >
> > Attached is a fixup patch. I have mainly updated some comments and
> > variable naming for (my) clarity. No functional changes.
>
> Committed all that.

Maybe I'm doing something wrong, but I'm getting a segfault trying to
start logical replication since that patch went in.

I've blown away my build tree and started over with this minimal
example, any obvious mistakes here? Quoting the publisher/subscriber
names doesn't seem to change things:

$ initdb --pgdata=data_pg1
$ sed -i -e 's/^#wal_level.=.replica/wal_level = logical/' data_pg1/postgresql.conf
$ pg_ctl --pgdata=data_pg1 -l pg1.log start
$ pg_basebackup --pgdata=data_pg2
$ sed -i -e 's/^#port.=.5432/port = 5433/' data_pg2/postgresql.conf
$ pg_ctl --pgdata=data_pg2 -l pg2.log start
$ psql -c "CREATE PUBLICATION pub1;"
$ psql --port=5433 -c "CREATE SUBSCRIPTION sub1 CONNECTION 'dbname=postgres' PUBLICATION pub1;"

Backtrace:

Program received signal SIGSEGV, Segmentation fault.
ExecSetSlotDescriptor (slot=slot(at)entry=0xfc4d38, tupdesc=tupdesc(at)entry=0x0)
at /home/mba/Projekte/OSS/PostgreSQL/git/postgresql/build/../src/backend/executor/execTuples.c:269
269 PinTupleDesc(tupdesc);
(gdb) bt
#0 ExecSetSlotDescriptor (slot=slot(at)entry=0xfc4d38, tupdesc=tupdesc(at)entry=0x0)
at /home/mba/Projekte/OSS/PostgreSQL/git/postgresql/build/../src/backend/executor/execTuples.c:269
#1 0x00000000005dc4fc in MakeSingleTupleTableSlot (tupdesc=0x0)
at /home/mba/Projekte/OSS/PostgreSQL/git/postgresql/build/../src/backend/executor/execTuples.c:203
#2 0x00000000005a16ff in fetch_table_list (wrconn=wrconn(at)entry=0xc00300000001,
publications=publications(at)entry=0xffb448)
at /home/mba/Projekte/OSS/PostgreSQL/git/postgresql/build/../src/backend/commands/subscriptioncmds.c:996
#3 0x00000000005a1efa in CreateSubscription (stmt=0x101cd40, isTopLevel=<optimized out>)
at /home/mba/Projekte/OSS/PostgreSQL/git/postgresql/build/../src/backend/commands/subscriptioncmds.c:396
#4 0x00000000006ecf96 in ProcessUtilitySlow (pstate=0x0, pstate(at)entry=0xfc4818, pstmt=0x0,
pstmt(at)entry=0x101d080, queryString=0xf9d248 <incomplete sequence \340>,
queryString(at)entry=0x101c0b8 "CREATE SUBSCRIPTION \"sub1\" CONNECTION 'dbname=postgres' PUBLICATION pub1 WITH (COPY DATA);", context=(unknown: 16534992), context(at)entry=PROCESS_UTILITY_TOPLEVEL,
params=0x7ffd7e6263d0, params(at)entry=0x0,
completionTag=0x45 <error: Cannot access memory at address 0x45>,
completionTag(at)entry=0x7ffd7e626b00 "", dest=<optimized out>)
at /home/mba/Projekte/OSS/PostgreSQL/git/postgresql/build/../src/backend/tcop/utility.c:1612
#5 0x00000000006ec4e9 in standard_ProcessUtility (pstmt=0x101d080,
queryString=0x101c0b8 "CREATE SUBSCRIPTION \"sub1\" CONNECTION 'dbname=postgres' PUBLICATION pub1 WITH (COPY DATA);", context=PROCESS_UTILITY_TOPLEVEL, params=0x0, dest=0x101d160,
completionTag=0x7ffd7e626b00 "")
at /home/mba/Projekte/OSS/PostgreSQL/git/postgresql/build/../src/backend/tcop/utility.c:922
#6 0x00000000006e9f5f in PortalRunUtility (portal=0xfbb9d8, pstmt=0x101d080,
isTopLevel=<optimized out>, setHoldSnapshot=<optimized out>, dest=<optimized out>,
completionTag=0x7ffd7e626b00 "")
at /home/mba/Projekte/OSS/PostgreSQL/git/postgresql/build/../src/backend/tcop/pquery.c:1165
#7 0x00000000006ea977 in PortalRunMulti (portal=portal(at)entry=0xfbb9d8,
isTopLevel=isTopLevel(at)entry=1 '\001', setHoldSnapshot=setHoldSnapshot(at)entry=0 '\000',
dest=dest(at)entry=0x101d160, altdest=altdest(at)entry=0x101d160,
completionTag=completionTag(at)entry=0x7ffd7e626b00 "")
at /home/mba/Projekte/OSS/PostgreSQL/git/postgresql/build/../src/backend/tcop/pquery.c:1315
#8 0x00000000006eb4cb in PortalRun (portal=portal(at)entry=0xfbb9d8,
count=count(at)entry=9223372036854775807, isTopLevel=isTopLevel(at)entry=1 '\001',
dest=dest(at)entry=0x101d160, altdest=altdest(at)entry=0x101d160,
completionTag=completionTag(at)entry=0x7ffd7e626b00 "")
at /home/mba/Projekte/OSS/PostgreSQL/git/postgresql/build/../src/backend/tcop/pquery.c:788
#9 0x00000000006e7868 in exec_simple_query (
query_string=0x101c0b8 "CREATE SUBSCRIPTION \"sub1\" CONNECTION 'dbname=postgres' PUBLICATION pub1 WITH (COPY DATA);")
at /home/mba/Projekte/OSS/PostgreSQL/git/postgresql/build/../src/backend/tcop/postgres.c:1101
#10 0x00000000006e94a9 in PostgresMain (argc=1, argv=0x101c0b8, dbname=0xfc8478 "postgres",
username=0xfc8458 "postgres")
at /home/mba/Projekte/OSS/PostgreSQL/git/postgresql/build/../src/backend/tcop/postgres.c:4069
#11 0x00000000004770ad in BackendRun (port=0xfc2970)
at /home/mba/Projekte/OSS/PostgreSQL/git/postgresql/build/../src/backend/postmaster/postmaster.c:4317
#12 BackendStartup (port=0xfc2970)
at /home/mba/Projekte/OSS/PostgreSQL/git/postgresql/build/../src/backend/postmaster/postmaster.c:3989
#13 ServerLoop ()
at /home/mba/Projekte/OSS/PostgreSQL/git/postgresql/build/../src/backend/postmaster/postmaster.c:1729
#14 0x000000000068819c in PostmasterMain (argc=argc(at)entry=3, argv=argv(at)entry=0xf9c420)
at /home/mba/Projekte/OSS/PostgreSQL/git/postgresql/build/../src/backend/postmaster/postmaster.c:1337
#15 0x0000000000477f27 in main (argc=3, argv=0xf9c420)
at /home/mba/Projekte/OSS/PostgreSQL/git/postgresql/build/../src/backend/main/main.c:228

The TAP tests in src/test/subscriber pass for me, going back to
707576b571f05ec5b89adb65964d55f3ccccbd1b also makes the above chain of
commands run fine.

Michael

--
Michael Banck
Projektleiter / Senior Berater
Tel.: +49 2166 9901-171
Fax: +49 2166 9901-100
Email: michael(dot)banck(at)credativ(dot)de

credativ GmbH, HRB Mönchengladbach 12080
USt-ID-Nummer: DE204566209
Trompeterallee 108, 41189 Mönchengladbach
Geschäftsführung: Dr. Michael Meskes, Jörg Folz, Sascha Heuer

Hi,

On 23/03/17 23:06, Michael Banck wrote:
> Hi,
>
> On Thu, Mar 23, 2017 at 09:00:16AM -0400, Peter Eisentraut wrote:
>> On 3/21/17 21:38, Peter Eisentraut wrote:
>>> This patch is looking pretty good to me, modulo the failing pg_dump tests.
>>>
>>> Attached is a fixup patch. I have mainly updated some comments and
>>> variable naming for (my) clarity. No functional changes.
>>
>> Committed all that.
>
> Maybe I'm doing something wrong, but I'm getting a segfault trying to
> start logical replication since that patch went in.
>

Thanks for report. Looks like we don't handle correctly empty result set
when fetching table list. Will post fix tomorrow.

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

On 24/03/17 02:00, Peter Eisentraut wrote:
> On 3/21/17 21:38, Peter Eisentraut wrote:
>> This patch is looking pretty good to me, modulo the failing pg_dump tests.
>>
>> Attached is a fixup patch. I have mainly updated some comments and
>> variable naming for (my) clarity. No functional changes.
> Committed all that.
>

Testing now this patch is in, I'm unable to create a subscription:

(master)

bench=# CREATE PUBLICATION pgbench
FOR TABLE pgbench_accounts , pgbench_branches,
pgbench_tellers, pgbench_history
WITH (PUBLISH INSERT, PUBLISH UPDATE, PUBLISH DELETE);

(slave)

bench=# CREATE SUBSCRIPTION pgbench
CONNECTION 'port=5447 user=postgres dbname=bench'
PUBLICATION pgbench
WITH (COPY DATA);
ERROR: duplicate key value violates unique constraint
"pg_subscription_rel_srrelid_srsubid_index"
DETAIL: Key (srrelid, srsubid)=(0, 16389) already exists.

This is a pair of freshly initdb'ed instances, the master has a size 100
pgbench schema.

I'm guessing this is a different bug from the segfault also reported

regards

Mark

On 24/03/17 00:14, Mark Kirkwood wrote:
> On 24/03/17 02:00, Peter Eisentraut wrote:
>> On 3/21/17 21:38, Peter Eisentraut wrote:
>>> This patch is looking pretty good to me, modulo the failing pg_dump
>>> tests.
>>>
>>> Attached is a fixup patch. I have mainly updated some comments and
>>> variable naming for (my) clarity. No functional changes.
>> Committed all that.
>>
>
> Testing now this patch is in, I'm unable to create a subscription:
>
> (master)
>
> bench=# CREATE PUBLICATION pgbench
> FOR TABLE pgbench_accounts , pgbench_branches,
> pgbench_tellers, pgbench_history
> WITH (PUBLISH INSERT, PUBLISH UPDATE, PUBLISH DELETE);
>
> (slave)
>
> bench=# CREATE SUBSCRIPTION pgbench
> CONNECTION 'port=5447 user=postgres dbname=bench'
> PUBLICATION pgbench
> WITH (COPY DATA);
> ERROR: duplicate key value violates unique constraint
> "pg_subscription_rel_srrelid_srsubid_index"
> DETAIL: Key (srrelid, srsubid)=(0, 16389) already exists.
>
> This is a pair of freshly initdb'ed instances, the master has a size 100
> pgbench schema.
>
> I'm guessing this is a different bug from the segfault also reported
>

Yes, I also forgot to check if the table actually exists on subscriber
when fetching them in CREATE SUBSCRIPTION (we have check during
replication but not there).

Attached patches should fix both issues.

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

Hi,

On Fri, Mar 24, 2017 at 12:32:28AM +0100, Petr Jelinek wrote:
> Yes, I also forgot to check if the table actually exists on subscriber
> when fetching them in CREATE SUBSCRIPTION (we have check during
> replication but not there).
>
> Attached patches should fix both issues.

I no longer get a segfault, thanks.

However, replication also seems to not work, I'm using the following
script right now:

--8<--
#!/bin/sh

set -x

#rm -rf data_* pg*.log

initdb --pgdata=data_pg1 1> /dev/null 2>&1
sed -i -e 's/^#wal_level.=.replica/wal_level = logical/'
data_pg1/postgresql.conf
pg_ctl --pgdata=data_pg1 -l pg1.log start 1> /dev/null
psql -c "CREATE TABLE t1(id int);"
pg_basebackup --pgdata=data_pg2
sed -i -e 's/^#port.=.5432/port = 5433/' data_pg2/postgresql.conf
psql -c "INSERT INTO t1 VALUES(1);"
pg_ctl --pgdata=data_pg2 -l pg2.log start 1> /dev/null
psql -c "CREATE PUBLICATION pub1;"
psql --port=5433 -c "CREATE SUBSCRIPTION sub1 CONNECTION
'dbname=postgres' PUBLICATION pub1 WITH (COPY DATA);"
sleep 6
psql -c 'SELECT application_name, state FROM pg_stat_replication;'
psql --port=5433 -c "SELECT COUNT(*) FROM t1;"
--8<--

(I had to add the sleep 6 - 5 wasn't always enough - in order to get the
subcription from 'catchup' to 'streaming' which was a bit surprising to
me)

This is the output:

--8<--
+ initdb --pgdata=data_pg1
+ sed -i -e s/^#wal_level.=.replica/wal_level = logical/
data_pg1/postgresql.conf
+ pg_ctl --pgdata=data_pg1 -l pg1.log start
+ psql -c CREATE TABLE t1(id int);
CREATE TABLE
+ pg_basebackup --pgdata=data_pg2
+ sed -i -e s/^#port.=.5432/port = 5433/ data_pg2/postgresql.conf
+ psql -c INSERT INTO t1 VALUES(1);
INSERT 0 1
+ pg_ctl --pgdata=data_pg2 -l pg2.log start
+ psql -c CREATE PUBLICATION pub1;
CREATE PUBLICATION
+ psql --port=5433 -c CREATE SUBSCRIPTION sub1 CONNECTION
'dbname=postgres' PUBLICATION pub1 WITH (COPY DATA);
NOTICE: created replication slot "sub1" on publisher
NOTICE: synchronized table states
CREATE SUBSCRIPTION
+ sleep 6
+ psql -c SELECT application_name, state FROM pg_stat_replication;
application_name | state
------------------+-----------
sub1 | streaming
(1 row)

+ psql --port=5433 -c SELECT COUNT(*) FROM t1;
count
-------
0
(1 row)
--8<--

I would have assumed the inserted value to be visible on the standby.
If I insert further values, don't show up, either.

Michael

--
Michael Banck
Projektleiter / Senior Berater
Tel.: +49 2166 9901-171
Fax: +49 2166 9901-100
Email: michael(dot)banck(at)credativ(dot)de

credativ GmbH, HRB Mönchengladbach 12080
USt-ID-Nummer: DE204566209
Trompeterallee 108, 41189 Mönchengladbach
Geschäftsführung: Dr. Michael Meskes, Jörg Folz, Sascha Heuer

On 24/03/17 12:32, Petr Jelinek wrote:

> On 24/03/17 00:14, Mark Kirkwood wrote:
>> On 24/03/17 02:00, Peter Eisentraut wrote:
>>> On 3/21/17 21:38, Peter Eisentraut wrote:
>>>> This patch is looking pretty good to me, modulo the failing pg_dump
>>>> tests.
>>>>
>>>> Attached is a fixup patch. I have mainly updated some comments and
>>>> variable naming for (my) clarity. No functional changes.
>>> Committed all that.
>>>
>> Testing now this patch is in, I'm unable to create a subscription:
>>
>> (master)
>>
>> bench=# CREATE PUBLICATION pgbench
>> FOR TABLE pgbench_accounts , pgbench_branches,
>> pgbench_tellers, pgbench_history
>> WITH (PUBLISH INSERT, PUBLISH UPDATE, PUBLISH DELETE);
>>
>> (slave)
>>
>> bench=# CREATE SUBSCRIPTION pgbench
>> CONNECTION 'port=5447 user=postgres dbname=bench'
>> PUBLICATION pgbench
>> WITH (COPY DATA);
>> ERROR: duplicate key value violates unique constraint
>> "pg_subscription_rel_srrelid_srsubid_index"
>> DETAIL: Key (srrelid, srsubid)=(0, 16389) already exists.
>>
>> This is a pair of freshly initdb'ed instances, the master has a size 100
>> pgbench schema.
>>
>> I'm guessing this is a different bug from the segfault also reported
>>
> Yes, I also forgot to check if the table actually exists on subscriber
> when fetching them in CREATE SUBSCRIPTION (we have check during
> replication but not there).
>
> Attached patches should fix both issues.
>
>

Yep, does seem to.

I note that (probably intensional) specifying 'COPY DATA' does not
'CREATE TABLES' for you...ok, I probably didn't read ...something
somewhere...but anyway, after creating the tables it all seems to work.
Nice.

However one minor observation - as Michael Banck noted - the elapsed
time for slave to catch up after running:

$ pgbench -c8 -T600 bench

on the master was (subjectively) much longer than for physical streaming
replication. Is this expected?

regards

Mark

On 3/23/17 19:32, Petr Jelinek wrote:
> Yes, I also forgot to check if the table actually exists on subscriber
> when fetching them in CREATE SUBSCRIPTION (we have check during
> replication but not there).

I think for this we can probably just change the missing_ok argument of
RangeVarGetRelid() to false.

Unless we want the custom error message, in which case we need to change
AlterSubscription_refresh(), because right now it errors out because
missing_ok = false.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 24/03/17 15:05, Peter Eisentraut wrote:
> On 3/23/17 19:32, Petr Jelinek wrote:
>> Yes, I also forgot to check if the table actually exists on subscriber
>> when fetching them in CREATE SUBSCRIPTION (we have check during
>> replication but not there).
>
> I think for this we can probably just change the missing_ok argument of
> RangeVarGetRelid() to false.
>
> Unless we want the custom error message, in which case we need to change
> AlterSubscription_refresh(), because right now it errors out because
> missing_ok = false.
>

You are right, stupid me.

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

On 3/24/17 10:09, Petr Jelinek wrote:
> On 24/03/17 15:05, Peter Eisentraut wrote:
>> On 3/23/17 19:32, Petr Jelinek wrote:
>>> Yes, I also forgot to check if the table actually exists on subscriber
>>> when fetching them in CREATE SUBSCRIPTION (we have check during
>>> replication but not there).
>>
>> I think for this we can probably just change the missing_ok argument of
>> RangeVarGetRelid() to false.
>>
>> Unless we want the custom error message, in which case we need to change
>> AlterSubscription_refresh(), because right now it errors out because
>> missing_ok = false.
>>
>
> You are right, stupid me.

Committed this version.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 3/24/17 05:22, Michael Banck wrote:
> However, replication also seems to not work, I'm using the following
> script right now:

The problem is that your publication does not include any tables.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Am Freitag, den 24.03.2017, 14:57 -0400 schrieb Peter Eisentraut:
> On 3/24/17 05:22, Michael Banck wrote:
> > However, replication also seems to not work, I'm using the following
> > script right now:
>
> The problem is that your publication does not include any tables.

Oops, of course. That part must've got lost in a copy-paste or when I
tried to dig further why the CREATE SUBSCRIPTION segfaulted, sorry for
the noise.

Michael

--
Michael Banck
Projektleiter / Senior Berater
Tel.: +49 2166 9901-171
Fax: +49 2166 9901-100
Email: michael(dot)banck(at)credativ(dot)de

credativ GmbH, HRB Mönchengladbach 12080
USt-ID-Nummer: DE204566209
Trompeterallee 108, 41189 Mönchengladbach
Geschäftsführung: Dr. Michael Meskes, Jörg Folz, Sascha Heuer

On 25/03/17 07:52, Peter Eisentraut wrote:
> On 3/24/17 10:09, Petr Jelinek wrote:
>> On 24/03/17 15:05, Peter Eisentraut wrote:
>>> On 3/23/17 19:32, Petr Jelinek wrote:
>>>> Yes, I also forgot to check if the table actually exists on subscriber
>>>> when fetching them in CREATE SUBSCRIPTION (we have check during
>>>> replication but not there).
>>> I think for this we can probably just change the missing_ok argument of
>>> RangeVarGetRelid() to false.
>>>
>>> Unless we want the custom error message, in which case we need to change
>>> AlterSubscription_refresh(), because right now it errors out because
>>> missing_ok = false.
>>>
>> You are right, stupid me.
> Committed this version.
>

Minor niggle:

bench=# DROP PUBLICATION pgbench;
DROP STATISTICS <===

I'm guessing that notification is wrong.

regards

Mark

On 3/25/17 00:45, Mark Kirkwood wrote:
> Minor niggle:
>
> bench=# DROP PUBLICATION pgbench;
> DROP STATISTICS <===
>
> I'm guessing that notification is wrong.

Fixed.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 2017-03-09 11:06, Erik Rijkers wrote:
>>>
>>> I use three different machines (2 desktop, 1 server) to test logical
>>> replication, and all three have now at least once failed to correctly
>>> synchronise a pgbench session (amidst many succesful runs, of course)
>>

(At the moment using tese patches for tests:)

> 0001-Reserve-global-xmin-for-create-slot-snasphot-export.patch +
> 0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch+
> 0003-Prevent-snapshot-builder-xmin-from-going-backwards.patch +
> 0004-Fix-xl_running_xacts-usage-in-snapshot-builder.patch +
> 0005-Skip-unnecessary-snapshot-builds.patch +

The failed tests that I kept seeing (see the
pgbench-over-logical-replication tests upthread) were never really
'solved'.

But I have now finally figured out what caused these unexpected failed
tests: it was wal_sender_timeout or rather, its default of 60 s.

This caused 'terminating walsender process due to replication timeout'
on the primary (not strictly an error), and the concomittant ERROR on
the replica: 'could not receive data from WAL stream: server closed the
connection unexpectedly'.

here is a typical example (primary/replica logs time-intertwined, with
'primary'):

[...]
2017-03-24 16:21:38.129 CET [15002] primary LOG: using stale
statistics instead of current ones because stats collector is not
responding
2017-03-24 16:21:42.690 CET [27515] primary LOG: using stale
statistics instead of current ones because stats collector is not
responding
2017-03-24 16:21:42.965 CET [14999] replica LOG: using stale
statistics instead of current ones because stats collector is not
responding
2017-03-24 16:21:49.816 CET [14930] primary LOG: terminating
walsender process due to
2017-03-24 16:21:49.817 CET [14926] replica ERROR: could not
receive data from WAL stream: server closed the connection unexpectedly
2017-03-24 16:21:49.824 CET [27502] replica LOG: worker process:
logical replication worker for subscription 24864 (PID 14926) exited
with exit code 1
2017-03-24 16:21:49.824 CET [27521] replica LOG: starting logical
replication worker for subscription "sub1"
2017-03-24 16:21:49.828 CET [15008] replica LOG: logical
replication apply for subscription sub1 started
2017-03-24 16:21:49.832 CET [15009] primary LOG: received
replication command: IDENTIFY_SYSTEM
2017-03-24 16:21:49.832 CET [15009] primary LOG: received
replication command: START_REPLICATION SLOT "sub1" LOGICAL 3/FC976440
(proto_version '1', publication_names '"pub1"')
2017-03-24 16:21:49.833 CET [15009] primary DETAIL: streaming
transactions committing after 3/FC889810, reading WAL from 3/FC820FC0
2017-03-24 16:21:49.833 CET [15009] primary LOG: starting logical
decoding for slot "sub1"
2017-03-24 16:21:50.471 CET [15009] primary DETAIL: Logical
decoding will begin using saved snapshot.
2017-03-24 16:21:50.471 CET [15009] primary LOG: logical decoding
found consistent point at 3/FC820FC0
2017-03-24 16:21:51.169 CET [15008] replica DETAIL: Key
(hid)=(9014) already exists.
2017-03-24 16:21:51.169 CET [15008] replica ERROR: duplicate key
value violates unique constraint "pgbench_history_pkey"
2017-03-24 16:21:51.170 CET [27502] replica LOG: worker process:
logical replication worker for subscription 24864 (PID 15008) exited
with exit code 1
2017-03-24 16:21:51.170 CET [27521] replica LOG: starting logical
replication worker for subscription "sub1"
[...]

My primary and replica were always on a single machine (making it more
likely that that timeout is reached?). In my testing it seems that
reaching the timeout on the primary (and 'closing the connection
unexpectedly' on the replica) does not necessarily break the logical
replication. But almost all log-rep failures that I have seen were
started by this sequence of events.

After setting wal_sender_timeout to 3 minutes there were no more
failed tests.

Perhaps it warrants setting wal_sender_timeout a bit higher than the
current default of 60 seconds? After all I also saw the 'replication
timeout' / 'closed the connection' couple rather often during
not-failing tests. (These also disappeared, almost completely, with a
higher setting of wal_sender_timeout)

In any case it would be good to mention the setting (and its potentially
deteriorating effect) somehere nearer the logical replication treatment.

( I read about wal_sender_timeout and keepalive ping, perhaps there's
(still) something amiss there? Just a guess, I don't know )

As I said, I saw no more failures with the higher 3 minute setting, with
one exception: the one test that straddled the DST change (saterday 24
march 02:00 h). I am happy to discount that one failure but strictly
speaking I suppose it should be able to take DST into its stride.

Thanks,

Erik Rijkers

On 29/03/17 10:14, Erik Rijkers wrote:
> On 2017-03-09 11:06, Erik Rijkers wrote:
>>>>
>>>> I use three different machines (2 desktop, 1 server) to test logical
>>>> replication, and all three have now at least once failed to correctly
>>>> synchronise a pgbench session (amidst many succesful runs, of course)
>>>
>
>
> (At the moment using tese patches for tests:)
>
>> 0001-Reserve-global-xmin-for-create-slot-snasphot-export.patch +
>> 0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch+
>> 0003-Prevent-snapshot-builder-xmin-from-going-backwards.patch +
>> 0004-Fix-xl_running_xacts-usage-in-snapshot-builder.patch +
>> 0005-Skip-unnecessary-snapshot-builds.patch +
>
>
> The failed tests that I kept seeing (see the
> pgbench-over-logical-replication tests upthread) were never really
> 'solved'.
>
>
> But I have now finally figured out what caused these unexpected failed
> tests: it was wal_sender_timeout or rather, its default of 60 s.
>
> This caused 'terminating walsender process due to replication timeout'
> on the primary (not strictly an error), and the concomittant ERROR on
> the replica: 'could not receive data from WAL stream: server closed the
> connection unexpectedly'.
>
> here is a typical example (primary/replica logs time-intertwined, with
> 'primary'):
>
> [...]
> 2017-03-24 16:21:38.129 CET [15002] primary LOG: using stale
> statistics instead of current ones because stats collector is not
> responding
> 2017-03-24 16:21:42.690 CET [27515] primary LOG: using stale
> statistics instead of current ones because stats collector is not
> responding
> 2017-03-24 16:21:42.965 CET [14999] replica LOG: using stale
> statistics instead of current ones because stats collector is not
> responding
> 2017-03-24 16:21:49.816 CET [14930] primary LOG: terminating
> walsender process due to
> 2017-03-24 16:21:49.817 CET [14926] replica ERROR: could not
> receive data from WAL stream: server closed the connection unexpectedly
> 2017-03-24 16:21:49.824 CET [27502] replica LOG: worker process:
> logical replication worker for subscription 24864 (PID 14926) exited
> with exit code 1
> 2017-03-24 16:21:49.824 CET [27521] replica LOG: starting logical
> replication worker for subscription "sub1"
> 2017-03-24 16:21:49.828 CET [15008] replica LOG: logical
> replication apply for subscription sub1 started
> 2017-03-24 16:21:49.832 CET [15009] primary LOG: received
> replication command: IDENTIFY_SYSTEM
> 2017-03-24 16:21:49.832 CET [15009] primary LOG: received
> replication command: START_REPLICATION SLOT "sub1" LOGICAL 3/FC976440
> (proto_version '1', publication_names '"pub1"')
> 2017-03-24 16:21:49.833 CET [15009] primary DETAIL: streaming
> transactions committing after 3/FC889810, reading WAL from 3/FC820FC0
> 2017-03-24 16:21:49.833 CET [15009] primary LOG: starting logical
> decoding for slot "sub1"
> 2017-03-24 16:21:50.471 CET [15009] primary DETAIL: Logical
> decoding will begin using saved snapshot.
> 2017-03-24 16:21:50.471 CET [15009] primary LOG: logical decoding
> found consistent point at 3/FC820FC0
> 2017-03-24 16:21:51.169 CET [15008] replica DETAIL: Key
> (hid)=(9014) already exists.
> 2017-03-24 16:21:51.169 CET [15008] replica ERROR: duplicate key
> value violates unique constraint "pgbench_history_pkey"
> 2017-03-24 16:21:51.170 CET [27502] replica LOG: worker process:
> logical replication worker for subscription 24864 (PID 15008) exited
> with exit code 1
> 2017-03-24 16:21:51.170 CET [27521] replica LOG: starting logical
> replication worker for subscription "sub1"
> [...]
>
> My primary and replica were always on a single machine (making it more
> likely that that timeout is reached?). In my testing it seems that
> reaching the timeout on the primary (and 'closing the connection
> unexpectedly' on the replica) does not necessarily break the logical
> replication. But almost all log-rep failures that I have seen were
> started by this sequence of events.
>
> After setting wal_sender_timeout to 3 minutes there were no more
> failed tests.
>
> Perhaps it warrants setting wal_sender_timeout a bit higher than the
> current default of 60 seconds? After all I also saw the 'replication
> timeout' / 'closed the connection' couple rather often during
> not-failing tests. (These also disappeared, almost completely, with a
> higher setting of wal_sender_timeout)
>
> In any case it would be good to mention the setting (and its potentially
> deteriorating effect) somehere nearer the logical replication treatment.
>
> ( I read about wal_sender_timeout and keepalive ping, perhaps there's
> (still) something amiss there? Just a guess, I don't know )
>
> As I said, I saw no more failures with the higher 3 minute setting, with
> one exception: the one test that straddled the DST change (saterday 24
> march 02:00 h). I am happy to discount that one failure but strictly
> speaking I suppose it should be able to take DST into its stride.
>
>

Hi,

I think what you have seen is because of this:
https://www.postgresql.org/message-id/flat/b235fa69-147a-5e09-f8f3-3f780a1abb2e(at)2ndquadrant(dot)com#b235fa69-147a-5e09-f8f3-3f780a1abb2e@2ndquadrant.com

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

(At the moment using these patches for tests:)
0001-Reserve-global-xmin-for-create-slot-snasphot-export.patch +
0002-Don-t-use-on-disk-snapshots-for-snapshot-export-in-l.patch+
0003-Prevent-snapshot-builder-xmin-from-going-backwards.patch +
0004-Fix-xl_running_xacts-usage-in-snapshot-builder.patch +
0005-Skip-unnecessary-snapshot-builds.patch +
and now (Tuesday 30) added :
0001-Fix-remote-position-tracking-in-logical-replication.patch

> I think what you have seen is because of this:
> https://www.postgresql.org/message-id/flat/b235fa69-147a-5e09-f8f3-3f780a1abb2e(at)2ndquadrant(dot)com#b235fa69-147a-5e09-f8f3-3f780a1abb2e@2ndquadrant.com
>

You were right: with that 6th patch (and wal_sender_timout back at its
default 60s) there are no errors either (I tested on all 3
test-machines).

I must have missed that last patch when you posted it. Anyway all seems
fine now; I hope the above patches can all be committed soon.

thanks,

Erik Rijkers