Re: Logical replication is missing block of rows when sending initial sync?

On Fri, Nov 03, 2023 at 01:22:42PM +0100, hubert depesz lubaczewski wrote:
> On Fri, Nov 03, 2023 at 01:20:22PM +0100, Tomas Vondra wrote:
> > I think it'd be interesting to know:
> >
> > 1) Commit LSN for the missing rows (for the xmin).
> >
> > 2) Are the other changes for these transactions that *got* replicated
> > correctly?
>
> How would I know?
>
> > 3) LSNs used for the tablesync slot, catchup etc. I believe those are in
> > the server log.
>
> I will provide more logs on the next problem.

OK. found another case (maybe two).

First, error:
ALTER TABLE ONLY c203s15531.conversation_message_participants ADD CONSTRAINT fk_rails_992a8b9e13 FOREIGN KEY (conversation_message_id) REFERENCES c203s15531.conversation_messages(id);
ERROR: insert or update on table "conversation_message_participants" violates foreign key constraint "fk_rails_992a8b9e13"
DETAIL: Key (conversation_message_id)=(431568) is not present in table "conversation_messages".

With forced seq scans (set enable_indexscan = false; set enable_bitmapscan = false; set enable_indexonlyscan = false;)

I got:

(12/bionic):

#v+
=# select count(*) from c203s15531.conversation_messages where id = 431568;
count
───────
1
(1 row)

=# select count(*) from c203s15531.conversation_message_participants where conversation_message_id=431568;
count
───────
2
(1 row)
#v-

(14/focal):

#v+
=# select count(*) from c203s15531.conversation_messages where id = 431568;
count
───────
0
(1 row)

=# select count(*) from c203s15531.conversation_message_participants where conversation_message_id=431568;
count
───────
2
(1 row)
#v-

So it looks that some rows are missing. Let's see the missing range:

#v+
Pg14# select max(id) from conversation_messages where id < 431568;
max
────────
431567
(1 row)

Pg14# select min(id) from conversation_messages where id > 431568;
min
────────
431572
(1 row)
#v-

So, the block from 431568 to 431571 is missing. On pg12, though:

#v+
Pg12# select count(*) from conversation_messages where id between 431568 and 431571;
count
───────
4
(1 row)
Pg12# select ctid, xmin, cmin, xmax, cmax, id, created_at from conversation_messages where id between 431568 and 431571;
ctid │ xmin │ cmin │ xmax │ cmax │ id │ created_at
────────────┼────────────┼──────┼────────────┼──────┼────────┼────────────────────────────
(29604,10) │ 3095841913 │ 1 │ 3095841995 │ 1 │ 431568 │ 2023-11-07 15:12:38.712504
(29604,11) │ 3095848690 │ 2 │ 3095848745 │ 2 │ 431569 │ 2023-11-07 15:12:49.5695
(29604,12) │ 3095884949 │ 2 │ 3095885033 │ 2 │ 431570 │ 2023-11-07 15:13:37.511025
(29604,13) │ 3095917833 │ 2 │ 3095917890 │ 2 │ 431571 │ 2023-11-07 15:14:40.058367
(4 rows)
#v-

In logs on bionic/pg12 I found when this particular table was added to subscription:

#v+
2023-11-07 15:10:19.023 UTC,"postgres","dbname",7350,"[local]",654a535a.1cb6,29,"idle",2023-11-07 15:10:18 UTC,30/865502097,0,LOG,00000,"statement: ALTER PUBLICATION focal14 ADD TABLE ONLY c203s15745.a_g_c_r_2023_10;",,,,,,,,,"psql"
2023-11-07 15:10:19.026 UTC,"postgres","dbname",7350,"[local]",654a535a.1cb6,30,"idle",2023-11-07 15:10:18 UTC,30/865502098,0,LOG,00000,"statement: ALTER PUBLICATION focal14 ADD TABLE ONLY c203s15311.q_q;",,,,,,,,,"psql"
2023-11-07 15:10:19.032 UTC,"postgres","dbname",7350,"[local]",654a535a.1cb6,31,"idle",2023-11-07 15:10:18 UTC,30/865502099,0,LOG,00000,"statement: ALTER PUBLICATION focal14 ADD TABLE ONLY c203s16352.m_2023_06;",,,,,,,,,"psql"
2023-11-07 15:10:19.035 UTC,"postgres","dbname",7350,"[local]",654a535a.1cb6,32,"idle",2023-11-07 15:10:18 UTC,30/865502100,0,LOG,00000,"statement: ALTER PUBLICATION focal14 ADD TABLE ONLY c203s15531.conversation_messages;",,,,,,,,,"psql"
2023-11-07 15:10:19.039 UTC,"postgres","dbname",7350,"[local]",654a535a.1cb6,33,"idle",2023-11-07 15:10:18 UTC,30/865502101,0,LOG,00000,"statement: ALTER PUBLICATION focal14 ADD TABLE ONLY c203s15479.q_s_e_2023_10;",,,,,,,,,"psql"
2023-11-07 15:10:19.043 UTC,"postgres","dbname",7350,"[local]",654a535a.1cb6,34,"idle",2023-11-07 15:10:18 UTC,30/865502102,0,LOG,00000,"statement: ALTER PUBLICATION focal14 ADD TABLE ONLY c203s17062.wiki_pages;",,,,,,,,,"psql"
2023-11-07 15:10:19.046 UTC,"postgres","dbname",7350,"[local]",654a535a.1cb6,35,"idle",2023-11-07 15:10:18 UTC,30/865502103,0,LOG,00000,"statement: ALTER PUBLICATION focal14 ADD TABLE ONLY c203s15841.a_g_c_r_2023_10;",,,,,,,,,"psql"
#v-

Since it was previously asked - schema:

#v+
Column │ Type │ Collation │ Nullable │ Default
───────────────────────┼─────────────────────────────┼───────────┼──────────┼───────────────────────────────────────────────────
id │ bigint │ │ not null │ nextval('conversation_messages_id_seq'::regclass)
..................... │ bigint │ │ │
..................... │ bigint │ │ │
created_at │ timestamp without time zone │ │ │
..................... │ boolean │ │ │
..................... │ text │ │ │
..................... │ text │ │ │
..................... │ character varying(255) │ │ │
..................... │ character varying(255) │ │ │
..................... │ bigint │ │ │
..................... │ character varying(255) │ │ │
..................... │ bigint │ │ │
..................... │ character varying(255) │ │ │
..................... │ text │ │ │
..................... │ boolean │ │ │
..................... │ boolean │ │ │
..................... │ text │ │ │
Indexes:
"conversation_messages_pkey" PRIMARY KEY, btree (id), tablespace "data1"
"index_conversation_messages_on_...." btree (.........), tablespace "data1"
"index_conversation_messages_on_......_and_created_at" btree (..........., created_at), tablespace "data1"
Foreign-key constraints:
"fk_rails_c3c322d882" FOREIGN KEY (conversation_id) REFERENCES conversations(id)
Referenced by:
TABLE "conversation_message_participants" CONSTRAINT "fk_rails_992a8b9e13" FOREIGN KEY (conversation_message_id) REFERENCES conversation_messages(id)
TABLE "conversation_batches" CONSTRAINT "fk_rails_d421fc74f4" FOREIGN KEY (root_conversation_message_id) REFERENCES conversation_messages(id)
Publications:
"cdc"
"focal14"
Triggers:
guard_excessive_deletes AFTER DELETE ON conversation_messages REFERENCING OLD TABLE AS oldtbl FOR EACH STATEMENT EXECUTE FUNCTION guard_excessive_updates()
guard_excessive_updates AFTER UPDATE ON conversation_messages REFERENCING OLD TABLE AS oldtbl FOR EACH STATEMENT EXECUTE FUNCTION guard_excessive_updates()
#v-

There are no dropped attributes.

Stats:

#v+
Pg12# select * from pg_stat_user_tables where relid = 'c203s15531.conversation_messages'::regclass \gx
─[ RECORD 1 ]───────┬──────────────────────────────
relid │ 166420
schemaname │ c203s15531
relname │ conversation_messages
seq_scan │ 14
seq_tup_read │ 2595888
idx_scan │ 16059568
idx_tup_fetch │ 27426090
n_tup_ins │ 372696
n_tup_upd │ 38
n_tup_del │ 0
n_tup_hot_upd │ 0
n_live_tup │ 432630
n_dead_tup │ 0
n_mod_since_analyze │ 7034
last_vacuum │ [null]
last_autovacuum │ 2023-08-10 18:06:11.655573+00
last_analyze │ [null]
last_autoanalyze │ 2023-11-01 18:56:52.868395+00
vacuum_count │ 0
autovacuum_count │ 5
analyze_count │ 0
autoanalyze_count │ 91
#v-

I can leave it as is for, let's say, a day. So if there are any queries/data
you'd like me to find out, let me know, but afterwards I will have to rebuild
the focal from scratch.

For whatever it's worth, we're adding tables to publication using:

#v+
with base as (
select n.nspname, c.relname, c.relpages
from pg_class c join pg_namespace n on c.relnamespace = n.oid
left outer join pg_catalog.pg_publication_tables pt on pt.pubname = 'focal14' and pt.schemaname = n.nspname and pt.tablename = c.relname
where c.relkind in ('p', 'r') and n.nspname ~ 'schemas|we|care|about' and pt.pubname is null
)
select format('ALTER PUBLICATION focal14 ADD TABLE ONLY %I.%I;', nspname, relname)
from base
order by relpages desc
limit 40 \gexec
#v-

Best regards,

depesz