Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1agh3P-0006aL-K3 for pgsql-bugs@arkaria.postgresql.org; Thu, 17 Mar 2016 23:10:08 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.84_2) (envelope-from ) id 1agh3P-0006jq-6W for pgsql-bugs@arkaria.postgresql.org; Thu, 17 Mar 2016 23:10:07 +0000 Received: from makus.postgresql.org ([2001:4800:1501:1::229]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1ag9LQ-0001kW-Us for pgsql-bugs@postgresql.org; Wed, 16 Mar 2016 11:10:29 +0000 Received: from smtp49.i.mail.ru ([94.100.177.109]) by makus.postgresql.org with esmtps (TLS1.0:DHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.84_2) (envelope-from ) id 1ag9LM-0004Vz-R1 for pgsql-bugs@postgresql.org; Wed, 16 Mar 2016 11:10:27 +0000 DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=bk.ru; s=mail; h=Content-Type:In-Reply-To:MIME-Version:Date:Message-ID:From:Cc:To:References:Subject; bh=Dr7OogYcPQqeUQbfsWdJ27Y2mEn77s1QTqxFtroXhgQ=; b=iw1cltfdLaIOeWGpVx7P8w80iwugFgQ6SG7vnUr5NvRgDLJBb0kD1UxesvnL5aygAAh6KFxoxRaProxBlaJ8/7qiRkvZGyw42xTtc7mXjRMXdJJrMUpLxy5ECozMwy5QecYjWFOT1ODNCUSOttgzqqNnORRX+EtHbqZnCoMA7F0=; Received: from [109.188.87.20] (port=45557 helo=[192.168.0.229]) by smtp49.i.mail.ru with esmtpa (envelope-from ) id 1ag9Hg-0002Ka-Q9; Wed, 16 Mar 2016 14:06:36 +0300 Subject: Re: Too many files in pg_replslot folder References: <1457621358.355011041@f382.i.mail.ru> <20160310153412.GA53338@alvherre.pgsql> <1457684211.431682571@f351.i.mail.ru> To: Alvaro Herrera Cc: PostgreSQL Bugs From: Dmitriy Sarafannikov Message-ID: <56E93E3B.8000104@bk.ru> Date: Wed, 16 Mar 2016 14:06:35 +0300 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:38.0) Gecko/20100101 Icedove/38.6.0 MIME-Version: 1.0 In-Reply-To: <1457684211.431682571@f351.i.mail.ru> Content-Type: multipart/alternative; boundary="------------070001090907040309010903" X-Mras: Ok X-Pg-Spam-Score: -2.7 (--) List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-bugs Precedence: bulk Sender: pgsql-bugs-owner@postgresql.org This is a multi-part message in MIME format. --------------070001090907040309010903 Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 7bit 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 --------------070001090907040309010903 Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: 8bit
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
--------------070001090907040309010903--