Re: Too many files in pg_replslot folder

Hi, all.

I tried to test logical replication with 'test_decoding' plugin.
I created logical slot and launched pg_recvlogical utility on ~8 hours.
When i tried to drop replication slot via pg_drop_replication_slot, backend ate my disk on 100% and didn't want to release him.
I saw via strace, that he deletes files:

lstat("pg_replslot/test_slot.tmp/xid-2917185562-lsn-4981-AE000000.snap", {st_mode=S_IFREG|0600, st_size=169, ...}) = 0
unlink("pg_replslot/test_slot.tmp/xid-2917185562-lsn-4981-AE000000.snap") = 0
lstat("pg_replslot/test_slot.tmp/xid-2915407454-lsn-497F-14000000.snap", {st_mode=S_IFREG|0600, st_size=161, ...}) = 0
unlink("pg_replslot/test_slot.tmp/xid-2915407454-lsn-497F-14000000.snap") = 0
lstat("pg_replslot/test_slot.tmp/xid-2915727847-lsn-497F-8C000000.snap", {st_mode=S_IFREG|0600, st_size=169, ...}) = 0
unlink("pg_replslot/test_slot.tmp/xid-2915727847-lsn-497F-8C000000.snap") = 0
lstat("pg_replslot/test_slot.tmp/xid-2919565207-lsn-4984-94000000.snap", {st_mode=S_IFREG|0600, st_size=177, ...}) = 0
unlink("pg_replslot/test_slot.tmp/xid-2919565207-lsn-4984-94000000.snap") = 0
lstat("pg_replslot/test_slot.tmp/xid-2915738746-lsn-497F-8D000000.snap", {st_mode=S_IFREG|0600, st_size=177, ...}) = 0
unlink("pg_replslot/test_slot.tmp/xid-2915738746-lsn-497F-8D000000.snap") = 0
lstat("pg_replslot/test_slot.tmp/xid-2917437588-lsn-4981-F2000000.snap", {st_mode=S_IFREG|0600, st_size=161, ...}) = 0
unlink("pg_replslot/test_slot.tmp/xid-2917437588-lsn-4981-F2000000.snap") = 0
lstat("pg_replslot/test_slot.tmp/xid-2917359031-lsn-4981-E5000000.snap", {st_mode=S_IFREG|0600, st_size=161, ...}) = 0
unlink("pg_replslot/test_slot.tmp/xid-2917359031-lsn-4981-E5000000.snap") = 0
lstat("pg_replslot/test_slot.tmp/xid-2917766393-lsn-4982-84000000.snap", {st_mode=S_IFREG|0600, st_size=177, ...}) = 0
unlink("pg_replslot/test_slot.tmp/xid-2917766393-lsn-4982-84000000.snap") = 0
lstat("pg_replslot/test_slot.tmp/xid-2915337440-lsn-497F-8000000.snap", {st_mode=S_IFREG|0600, st_size=169, ...}) = 0
unlink("pg_replslot/test_slot.tmp/xid-2915337440-lsn-497F-8000000.snap") = 0
lstat("pg_replslot/test_slot.tmp/xid-2916494069-lsn-4980-C3000000.snap", {st_mode=S_IFREG|0600, st_size=177, ...}) = 0
unlink("pg_replslot/test_slot.tmp/xid-2916494069-lsn-4980-C3000000.snap") = 0
lstat("pg_replslot/test_slot.tmp/xid-2916877166-lsn-4981-4F000000.snap", {st_mode=S_IFREG|0600, st_size=169, ...}) = 0
unlink("pg_replslot/test_slot.tmp/xid-2916877166-lsn-4981-4F000000.snap") = 0
He seemed to be in infinite loop. 1109428 files were in the slot folder.
It looks like abnormal behavior. Why are so many files?
Maybe i'm doing something wrong? Or maybe it is bug?
How i can avoid this?

And wal sender ate ~800 mb of memory during this test. Is it leakage?

version
-----------------------------------------------------------------------------------------------
PostgreSQL 9.4.6 on x86_64-unknown-linux-gnu, compiled by gcc (Debian 4.9.2-10) 4.9.2, 64-bit

Thanks for advance and sorry for my English.

Regards,
Dmitriy Sarafannikov

Dmitriy Sarafannikov wrote:
> Hi, all.
>
> I tried to test logical replication with 'test_decoding' plugin.
> I created logical slot and launched pg_recvlogical utility on ~8 hours.
> When i tried to drop replication slot via pg_drop_replication_slot, backend ate my disk on 100% and didn't want to release him.
> I saw via strace, that he deletes files:
>
> lstat("pg_replslot/test_slot.tmp/xid-2917185562-lsn-4981-AE000000.snap", {st_mode=S_IFREG|0600, st_size=169, ...}) = 0
> unlink("pg_replslot/test_slot.tmp/xid-2917185562-lsn-4981-AE000000.snap") = 0

> He seemed to be in infinite loop. 1109428 files were in the slot folder.
> It looks like abnormal behavior. Why are so many files?
> Maybe i'm doing something wrong? Or maybe it is bug?
> How i can avoid this?

Well, the files are all different in what you reported, so I would say
it's not a loop but a very long sequence.

This can happen if you have a very long transaction while the snapshot
for the slot is being built, and a million other transactions happen
before the long transaction commits. One way in which this would go on
and on until it fills the disk is that you have a prepared transaction
that you forgot about (See select * from pg_prepared_xacts to diagnose
this one). Or you could just have a very long transaction (see select *
from pg_stat_activity).

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

> Well, the files are all different in what you reported, so I would say
> it's not a loop but a very long sequence.

Yes, i have noticed this, sorry for bad explanation.

> This can happen if you have a very long transaction while the snapshot
> for the slot is being built, and a million other transactions happen
> before the long transaction commits. One way in which this would go on
> and on until it fills the disk is that you have a prepared transaction
> that you forgot about (See select * from pg_prepared_xacts to diagnose
> this one). Or you could just have a very long transaction (see select *
> from pg_stat_activity).

Thanks for explanation. Where was a long autovacuum on big table.
What will happen when he finished?
Wal sender will remove all of this files together and will utilze disk on 100% again?

Regards,
Dmitriy Sarafannikov

On 03/11/2016 11:16 AM, Dmitriy Sarafannikov wrote:
>
>> Well, the files are all different in what you reported, so I would say
>> it's not a loop but a very long sequence.
> Yes, i have noticed this, sorry for bad explanation.
>
>> This can happen if you have a very long transaction while the snapshot
>> for the slot is being built, and a million other transactions happen
>> before the long transaction commits. One way in which this would go on
>> and on until it fills the disk is that you have a prepared transaction
>> that you forgot about (See select * from pg_prepared_xacts to diagnose
>> this one). Or you could just have a very long transaction (see select *
>> from pg_stat_activity).
> Thanks for explanation. Where was a long autovacuum on big table.
> What will happen when he finished?
> Wal sender will remove all of this files together and will utilze disk on 100% again?
>
>
> Regards,
> Dmitriy Sarafannikov

Sorry, autovacuum not involved in this.
I took several xids from this files and found them in WAL with pg_xlogdump:
rmgr: Heap len (rec/tot): 67/ 99, tx: 2918822231, lsn:
4983/D8FF8388, prev 4983/D8FF8338, bkp: 0000, desc: insert: rel
1663/16428/133587958; tid 5737/114
rmgr: Btree len (rec/tot): 34/ 66, tx: 2918822231, lsn:
4983/D8FF83F0, prev 4983/D8FF8388, bkp: 0000, desc: insert: rel
1663/16428/133587964; tid 6560/2
rmgr: Btree len (rec/tot): 50/ 82, tx: 2918822231, lsn:
4983/D8FF8438, prev 4983/D8FF83F0, bkp: 0000, desc: insert: rel
1663/16428/133926198; tid 27418/14
rmgr: Btree len (rec/tot): 50/ 82, tx: 2918822231, lsn:
4983/D8FF8490, prev 4983/D8FF8438, bkp: 0000, desc: insert: rel
1663/16428/148286684; tid 14048/2

i noticed that they are points to table, that filled by trigger
functions with upsert.

I have reproduced this case on clean instance (9.4.6):

create tables:

postgres=# create table test (id int primary key);
CREATE TABLE
postgres=# create table test2 (id int primary key);
CREATE TABLE

fill test2 table:
postgres=# insert into test2 (id) select generate_series(1,10000);
INSERT 0 10000

create upsert trigger:

postgres=# \sf tg_test
CREATE OR REPLACE FUNCTION public.tg_test()
RETURNS trigger
LANGUAGE plpgsql
AS $function$
begin
loop
update test2 set id = new.id where id = new.id;
exit when found;
begin
insert into test2 values (new.*);
exit;
exception when unique_violation then
end;
end loop;
return new;
end
$function$

postgres=# create trigger test_trigger after insert or update on test
for each row execute procedure tg_test();
CREATE TRIGGER

create slot:

postgres=# select * from pg_create_logical_replication_slot('test_slot',
'test_decoding');
slot_name | xlog_position
-----------+---------------
test_slot | 0/227DFE18
(1 row)

start pg_recvlogical:

$ pg_recvlogical --start -S test_slot -d postgres -hlocalhost -p5433 -f
/tmp/test_logical

postgres=# select * from pg_replication_slots ;
slot_name | plugin | slot_type | datoid | database | active |
xmin | catalog_xmin | restart_lsn
-----------+---------------+-----------+--------+----------+--------+------+--------------+-------------
test_slot | test_decoding | logical | 12141 | postgres | t
| | 330838 | 0/227DFE18
(1 row)

There are 1 file in slot folder (state file):

$ find ./testdata_9.4/pg_replslot/test_slot/ -type f | wc -l
1

Then start transaction and insert data into test table:
postgres=# begin ;
BEGIN
postgres=# insert into test (id) select generate_series(1,10000);
INSERT 0 10000

Now we have 2 files on slot folder:
$ find ./testdata_9.4/pg_replslot/test_slot/ -type f
./testdata_9.4/pg_replslot/test_slot/xid-330839-lsn-0-22000000.snap
./testdata_9.4/pg_replslot/test_slot/state

Then commit:
postgres=# commit ;
COMMIT

And now we have only state file on folder:
$ find ./testdata_9.4/pg_replslot/test_slot/ -type f
./testdata_9.4/pg_replslot/test_slot/state

Ok.

Then lets truncate both tables test and test2
and repeat:
postgres=# truncate test;
TRUNCATE TABLE
postgres=# truncate test2;
TRUNCATE TABLE

postgres=# begin ;
BEGIN
postgres=# insert into test (id) select generate_series(1,10000);
INSERT 0 10000

there are 2 files:
$ find ./testdata_9.4/pg_replslot/test_slot/ -type f
./testdata_9.4/pg_replslot/test_slot/xid-330842-lsn-0-22000000.snap
./testdata_9.4/pg_replslot/test_slot/state

postgres=# commit ;
COMMIT

and there are 10001 files:
$ find ./testdata_9.4/pg_replslot/test_slot/ -type f | wc -l
10001

$ find ./testdata_9.4/pg_replslot/test_slot/ -type f | head
./testdata_9.4/pg_replslot/test_slot/xid-332964-lsn-0-22000000.snap
./testdata_9.4/pg_replslot/test_slot/xid-336489-lsn-0-22000000.snap
./testdata_9.4/pg_replslot/test_slot/xid-331289-lsn-0-22000000.snap
./testdata_9.4/pg_replslot/test_slot/xid-339354-lsn-0-22000000.snap
./testdata_9.4/pg_replslot/test_slot/xid-337343-lsn-0-22000000.snap
./testdata_9.4/pg_replslot/test_slot/xid-336479-lsn-0-22000000.snap
./testdata_9.4/pg_replslot/test_slot/xid-332975-lsn-0-22000000.snap
./testdata_9.4/pg_replslot/test_slot/xid-331320-lsn-0-22000000.snap
./testdata_9.4/pg_replslot/test_slot/xid-331664-lsn-0-22000000.snap
./testdata_9.4/pg_replslot/test_slot/xid-334975-lsn-0-22000000.snap

there are 1 file per xid:
$ find ./testdata_9.4/pg_replslot/test_slot/ -type f -name '*.snap' |
cut -d'-' -f2 | sort | uniq -c | sort -nr | head
1 340842
1 340841
1 340840
1 340839
1 340838
1 340837
1 340836
1 340835
1 340834
1 340833

$ find ./testdata_9.4/pg_replslot/test_slot/ -type f -name '*.snap' |
cut -d'-' -f4,5 | sort | uniq -c | sort -nr | head
10000 0-22000000.snap

in test_logical file we see, that pg_recvlogical received this transaction:

$ tail /tmp/test_logical
table public.test2: INSERT: id[integer]:9996
table public.test2: INSERT: id[integer]:9997
table public.test2: INSERT: id[integer]:9998
table public.test2: INSERT: id[integer]:9999
table public.test2: INSERT: id[integer]:10000
COMMIT 330842
BEGIN 340843
COMMIT 340843
BEGIN 340844
COMMIT 340844

postgres=# select * from pg_replication_slots ;
slot_name | plugin | slot_type | datoid | database | active |
xmin | catalog_xmin | restart_lsn
-----------+---------------+-----------+--------+----------+--------+------+--------------+-------------
test_slot | test_decoding | logical | 12141 | postgres | t
| | 340845 | 0/22D97140
(1 row)

files are not deleted. They will be deleted if you will drop replication
slot.

It turns out that, if rows are updated in function, it's ok. But if rows
are inserted inside BEGIN..END block in function,
we get forgotten files in slot folder.

--
Best Regards,
Dmitriy Sarafannikov

Hi,

On 2016-03-16 14:06:35 +0300, Dmitriy Sarafannikov wrote:
> Sorry, autovacuum not involved in this.
> I took several xids from this files and found them in WAL with pg_xlogdump:
> rmgr: Heap len (rec/tot): 67/ 99, tx: 2918822231, lsn:
> 4983/D8FF8388, prev 4983/D8FF8338, bkp: 0000, desc: insert: rel
> 1663/16428/133587958; tid 5737/114
> rmgr: Btree len (rec/tot): 34/ 66, tx: 2918822231, lsn:
> 4983/D8FF83F0, prev 4983/D8FF8388, bkp: 0000, desc: insert: rel
> 1663/16428/133587964; tid 6560/2
> rmgr: Btree len (rec/tot): 50/ 82, tx: 2918822231, lsn:
> 4983/D8FF8438, prev 4983/D8FF83F0, bkp: 0000, desc: insert: rel
> 1663/16428/133926198; tid 27418/14
> rmgr: Btree len (rec/tot): 50/ 82, tx: 2918822231, lsn:
> 4983/D8FF8490, prev 4983/D8FF8438, bkp: 0000, desc: insert: rel
> 1663/16428/148286684; tid 14048/2
>
> i noticed that they are points to table, that filled by trigger functions
> with upsert.

Hm, interesting. I wonder, could you try this with a source checkout of
9.4? There's some fixes in the upcoming minor release that might be
related. If not, I'll look into it.

- Andres

On 03/18/2016 02:21 AM, Andres Freund wrote:
> Hm, interesting. I wonder, could you try this with a source checkout
> of 9.4? There's some fixes in the upcoming minor release that might be
> related. If not, I'll look into it. - Andres
Thank you for you attention!

It's reproducible for REL9_4_STABLE
(17a250b189a94a470e37ce14d0ebf72390c86d4d).

I looked a little at the code. And i have reproduced this case with
debugger in case of 5000 rows.

There was xact with 5000 subxacts and 5000 ->nentries.
Because 5000 > max_changes_in_memory (4096) then xact was spilled to
disk partially.
Then in ReorderBufferCommit xact was spilled to disk with all their
subxacts by
ReorderBufferSerializeTXN and had ->nentries = 5000, ->nentries_mem = 0.

if (txn->nentries_mem != txn->nentries)
ReorderBufferSerializeTXN(rb, txn);

Each subxact had ->nentries = 1 and ->nentries_mem = 1 before it was
spilled and ->nentries = 1, ->nentries_mem = 0 after.

Then xact with all subxacts was restored in ReorderBufferIterTXNInit.
And each subxact had ->nentries = 1 and ->nentries_mem = 1, and main
xact had ->nentries = 5000, ->nentries_mem = 4096
after.

As i understood, it implied that all files will be deleted in
ReorderBufferCleanupTXN
which recursively called for each subxact.
And for subxacts ReorderBufferRestoreCleanup has not been called because
they had ->nentries = 1 == ->nentries_mem = 1.

/* remove entries spilled to disk */
if (txn->nentries != txn->nentries_mem)
ReorderBufferRestoreCleanup(rb, txn);

I have a suggestion, but i'm not sure that it will be fully correct,
because i don't know yet this logic fully:
add condition for subxact to "if"

/* remove entries spilled to disk */
if (txn->nentries != txn->nentries_mem || txn->is_known_as_subxact)
ReorderBufferRestoreCleanup(rb, txn);

And, perhaps, i found a typo in ReorderBufferIterTXNInit:

/* add subtransactions if they contain changes */
dlist_foreach(cur_txn_i, &txn->subtxns)
{
ReorderBufferTXN *cur_txn;

cur_txn = dlist_container(ReorderBufferTXN, node, cur_txn_i.cur);

if (cur_txn->nentries > 0)
{
ReorderBufferChange *cur_change;

if (txn->nentries != txn->nentries_mem)
ReorderBufferRestoreChanges(rb, cur_txn,
&state->entries[off].fd,
&state->entries[off].segno);

cur_change = dlist_head_element(ReorderBufferChange, node,
&cur_txn->changes);

state->entries[off].lsn = cur_change->lsn;
state->entries[off].change = cur_change;
state->entries[off].txn = cur_txn;

binaryheap_add_unordered(state->heap, Int32GetDatum(off++));
}
}

maybe, it was implied as

if (cur_txn->nentries != cur_txn->nentries_mem)
ReorderBufferRestoreChanges(rb, cur_txn,
&state->entries[off].fd,
&state->entries[off].segno);
instead of

if (txn->nentries != txn->nentries_mem)
ReorderBufferRestoreChanges(rb, cur_txn,
&state->entries[off].fd,
&state->entries[off].segno);

Or i'm wrong?

Just in case, the patch for REL9_4_STABLE attached.

--
Best Regards,
Dmitriy Sarafannikov

This bug is still reproducible, in particular on recent release 9.4.7.
Can you look at it? I'm worried about it because this is a hindrance
before use this helpful feature on production for me.

Thanks a lot.

> On 03/18/2016 02:21 AM, Andres Freund wrote:
>> Hm, interesting. I wonder, could you try this with a source checkout
>> of 9.4? There's some fixes in the upcoming minor release that might
>> be related. If not, I'll look into it. - Andres

--
Best Regards,
Dmitriy Sarafannikov

Hi,

On 2016-04-19 12:43:24 +0300, Dmitriy Sarafannikov wrote:
> This bug is still reproducible, in particular on recent release 9.4.7. Can
> you look at it? I'm worried about it because this is a hindrance before use
> this helpful feature on production for me.

Sorry for loosing track of this. I think I was just moving between
continents, and I have dropped the ball somewhere along that. I've now
pushed a fix - I didn't want to unconditionally do the removal as you
did, that'd have some performance impact for small transactions, quite
common in OLTP workloads.

- Andres

> Sorry for loosing track of this. I think I was just moving between
> continents, and I have dropped the ball somewhere along that. I've now
> pushed a fix - I didn't want to unconditionally do the removal as you
> did, that'd have some performance impact for small transactions, quite
> common in OLTP workloads.

Thank you!