Обсуждение: Too many files in pg_replslot folder
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 releasehim. > 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 -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs
> 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! -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs