Thread: Failed to delete old ReorderBuffer spilled files

Hi,

I put many queries into one transaction and made ReorderBuffer spill
data to disk, and sent SIGKILL to postgres before the end of the
transaction.

After starting up postgres again, I observed the files spilled to
data wasn't deleted.

I think these files should be deleted because its transaction was no
more valid, so no one can use these files.


Below is a reproduction instructions.

------------------------------------------------
1. Create table and publication at publiser.

   @pub =# CREATE TABLE t1(
       id INT PRIMARY KEY,
       name TEXT);

   @pub =# CREATE PUBLICATION pub FOR TABLE t1;

2. Create table and subscription at subscriber.

   @sub =# CREATE TABLE t1(
       id INT PRIMARY KEY,
       name TEXT
       );

   @sub =# CREATE SUBSCRIPTION sub
       CONNECTION 'host=[hostname] port=[port] dbname=[dbname]'
       PUBLICATION pub;

3. Put many queries into one transaction.

   @pub =# BEGIN;
         INSERT INTO t1
         SELECT
           i,
           'aaaaaaaaaa'
         FROM
         generate_series(1, 1000000) as i;

4. Then we can see spilled files.

   @pub $ ls -1 ${PGDATA}/pg_replslot/sub/
     state
     xid-561-lsn-0-1000000.snap
     xid-561-lsn-0-2000000.snap
     xid-561-lsn-0-3000000.snap
     xid-561-lsn-0-4000000.snap
     xid-561-lsn-0-5000000.snap
     xid-561-lsn-0-6000000.snap
     xid-561-lsn-0-7000000.snap
     xid-561-lsn-0-8000000.snap
     xid-561-lsn-0-9000000.snap

5. Kill publisher's postgres process before COMMIT.

   @pub $ kill -s SIGKILL [pid of postgres]

6. Start publisher's postgres process.

   @pub $ pg_ctl start -D ${PGDATA}

7. After a while, we can see the files remaining.
   (Immediately after starting publiser, we can not see these files.)

   @pub $ pg_ctl start -D ${PGDATA}

   When I configured with '--enable-cassert', below assertion error
   was appeared.

     TRAP: FailedAssertion("!(txn->final_lsn != 0)", File:  
"reorderbuffer.c", Line: 2576)
------------------------------------------------

Attached patch sets final_lsn to the last ReorderBufferChange if
final_lsn == 0.

--
Atsushi Torikoshi
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

On Mon, Nov 20, 2017 at 7:35 PM, atorikoshi
<torikoshi_atsushi_z2@lab.ntt.co.jp> wrote:
> Hi,
>
> I put many queries into one transaction and made ReorderBuffer spill
> data to disk, and sent SIGKILL to postgres before the end of the
> transaction.
>
> After starting up postgres again, I observed the files spilled to
> data wasn't deleted.
>
> I think these files should be deleted because its transaction was no
> more valid, so no one can use these files.
>
>
> Below is a reproduction instructions.
>
> ------------------------------------------------
> 1. Create table and publication at publiser.
>
>   @pub =# CREATE TABLE t1(
>       id INT PRIMARY KEY,
>       name TEXT);
>
>   @pub =# CREATE PUBLICATION pub FOR TABLE t1;
>
> 2. Create table and subscription at subscriber.
>
>   @sub =# CREATE TABLE t1(
>       id INT PRIMARY KEY,
>       name TEXT
>       );
>
>   @sub =# CREATE SUBSCRIPTION sub
>       CONNECTION 'host=[hostname] port=[port] dbname=[dbname]'
>       PUBLICATION pub;
>
> 3. Put many queries into one transaction.
>
>   @pub =# BEGIN;
>         INSERT INTO t1
>         SELECT
>           i,
>           'aaaaaaaaaa'
>         FROM
>         generate_series(1, 1000000) as i;
>
> 4. Then we can see spilled files.
>
>   @pub $ ls -1 ${PGDATA}/pg_replslot/sub/
>     state
>     xid-561-lsn-0-1000000.snap
>     xid-561-lsn-0-2000000.snap
>     xid-561-lsn-0-3000000.snap
>     xid-561-lsn-0-4000000.snap
>     xid-561-lsn-0-5000000.snap
>     xid-561-lsn-0-6000000.snap
>     xid-561-lsn-0-7000000.snap
>     xid-561-lsn-0-8000000.snap
>     xid-561-lsn-0-9000000.snap
>
> 5. Kill publisher's postgres process before COMMIT.
>
>   @pub $ kill -s SIGKILL [pid of postgres]
>
> 6. Start publisher's postgres process.
>
>   @pub $ pg_ctl start -D ${PGDATA}
>
> 7. After a while, we can see the files remaining.
>   (Immediately after starting publiser, we can not see these files.)
>
>   @pub $ pg_ctl start -D ${PGDATA}
>
>   When I configured with '--enable-cassert', below assertion error
>   was appeared.
>
>     TRAP: FailedAssertion("!(txn->final_lsn != 0)", File: "reorderbuffer.c",
> Line: 2576)
> ------------------------------------------------
>
> Attached patch sets final_lsn to the last ReorderBufferChange if
> final_lsn == 0.

Thank you for the report. I could reproduce this issue with the above
step. My analysis is, the cause of that a serialized reorder buffer
isn't cleaned up is that the aborted transaction without an abort WAL
record has no chance to set ReorderBufferTXN->final_lsn. So if there
is such serialized transactions ReorderBufferRestoreCleanup cleanups
no files, which is cause of the assertion failure (or a file being
orphaned). What do you think?

On detail of your patch, I'm not sure it's safe if we set the lsn of
other than commit record or abort record to final_lsn. The comment in
reorderbuffer.h says,

typedef trcut ReorderBufferTXN
{
(snip)
   /* ----    * LSN of the record that lead to this xact to be committed or    * aborted. This can be a    * * plain
commitrecord    * * plain commit record, of a parent transaction    * * prepared transaction commit    * * plain abort
record   * * prepared transaction abort    * * error during decoding    * ----    */   XLogRecPtr  final_lsn;
 

But with your patch, we could set a lsn of a record that is other than
what listed above to final_lsn. One way I came up with is to make
ReorderBufferRestoreCleanup accept an invalid value of final_lsn and
regards it as a aborted transaction that doesn't has a abort WAL
record. So we can cleanup all serialized files if final_lsn of a
transaction is invalid. Since I'm not very familiar with snapshot
building part please check it.

Anyway I think you should register this patch to the next commit fest
so as not forget.

Regards,

--
Masahiko Sawada
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

On Tue, Nov 21, 2017 at 3:48 PM, Masahiko Sawada <sawada.mshk@gmail.com> wrote:
> On Mon, Nov 20, 2017 at 7:35 PM, atorikoshi
> <torikoshi_atsushi_z2@lab.ntt.co.jp> wrote:
>> Hi,
>>
>> I put many queries into one transaction and made ReorderBuffer spill
>> data to disk, and sent SIGKILL to postgres before the end of the
>> transaction.
>>
>> After starting up postgres again, I observed the files spilled to
>> data wasn't deleted.
>>
>> I think these files should be deleted because its transaction was no
>> more valid, so no one can use these files.
>>
>>
>> Below is a reproduction instructions.
>>
>> ------------------------------------------------
>> 1. Create table and publication at publiser.
>>
>>   @pub =# CREATE TABLE t1(
>>       id INT PRIMARY KEY,
>>       name TEXT);
>>
>>   @pub =# CREATE PUBLICATION pub FOR TABLE t1;
>>
>> 2. Create table and subscription at subscriber.
>>
>>   @sub =# CREATE TABLE t1(
>>       id INT PRIMARY KEY,
>>       name TEXT
>>       );
>>
>>   @sub =# CREATE SUBSCRIPTION sub
>>       CONNECTION 'host=[hostname] port=[port] dbname=[dbname]'
>>       PUBLICATION pub;
>>
>> 3. Put many queries into one transaction.
>>
>>   @pub =# BEGIN;
>>         INSERT INTO t1
>>         SELECT
>>           i,
>>           'aaaaaaaaaa'
>>         FROM
>>         generate_series(1, 1000000) as i;
>>
>> 4. Then we can see spilled files.
>>
>>   @pub $ ls -1 ${PGDATA}/pg_replslot/sub/
>>     state
>>     xid-561-lsn-0-1000000.snap
>>     xid-561-lsn-0-2000000.snap
>>     xid-561-lsn-0-3000000.snap
>>     xid-561-lsn-0-4000000.snap
>>     xid-561-lsn-0-5000000.snap
>>     xid-561-lsn-0-6000000.snap
>>     xid-561-lsn-0-7000000.snap
>>     xid-561-lsn-0-8000000.snap
>>     xid-561-lsn-0-9000000.snap
>>
>> 5. Kill publisher's postgres process before COMMIT.
>>
>>   @pub $ kill -s SIGKILL [pid of postgres]
>>
>> 6. Start publisher's postgres process.
>>
>>   @pub $ pg_ctl start -D ${PGDATA}
>>
>> 7. After a while, we can see the files remaining.
>>   (Immediately after starting publiser, we can not see these files.)
>>
>>   @pub $ pg_ctl start -D ${PGDATA}
>>
>>   When I configured with '--enable-cassert', below assertion error
>>   was appeared.
>>
>>     TRAP: FailedAssertion("!(txn->final_lsn != 0)", File: "reorderbuffer.c",
>> Line: 2576)
>> ------------------------------------------------
>>
>> Attached patch sets final_lsn to the last ReorderBufferChange if
>> final_lsn == 0.
>
> Thank you for the report. I could reproduce this issue with the above
> step. My analysis is, the cause of that a serialized reorder buffer
> isn't cleaned up is that the aborted transaction without an abort WAL
> record has no chance to set ReorderBufferTXN->final_lsn. So if there
> is such serialized transactions ReorderBufferRestoreCleanup cleanups
> no files, which is cause of the assertion failure (or a file being
> orphaned). What do you think?
>
> On detail of your patch, I'm not sure it's safe if we set the lsn of
> other than commit record or abort record to final_lsn. The comment in
> reorderbuffer.h says,
>
> typedef trcut ReorderBufferTXN
> {
> (snip)
>
>     /* ----
>      * LSN of the record that lead to this xact to be committed or
>      * aborted. This can be a
>      * * plain commit record
>      * * plain commit record, of a parent transaction
>      * * prepared transaction commit
>      * * plain abort record
>      * * prepared transaction abort
>      * * error during decoding
>      * ----
>      */
>     XLogRecPtr  final_lsn;
>
> But with your patch, we could set a lsn of a record that is other than
> what listed above to final_lsn. One way I came up with is to make
> ReorderBufferRestoreCleanup accept an invalid value of final_lsn and
> regards it as a aborted transaction that doesn't has a abort WAL
> record. So we can cleanup all serialized files if final_lsn of a
> transaction is invalid.

After more thought, since there are some codes cosmetically setting
final_lsn when the fate of transaction is determined possibly we
should not accept a invalid value of final_lsn even in the case.

> Since I'm not very familiar with snapshot
> building part please check it.

Sorry I wanted to say the reorderbuffer module. The snapshot building
isn't relevant.

Regards,

--
Masahiko Sawada
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

Thanks for reviewing!


On 2017/11/21 18:12, Masahiko Sawada wrote:
> On Tue, Nov 21, 2017 at 3:48 PM, Masahiko Sawada <sawada.mshk@gmail.com> wrote:
>> On Mon, Nov 20, 2017 at 7:35 PM, atorikoshi
>> <torikoshi_atsushi_z2@lab.ntt.co.jp> wrote:
>>> Hi,
>>>
>>> I put many queries into one transaction and made ReorderBuffer spill
>>> data to disk, and sent SIGKILL to postgres before the end of the
>>> transaction.
>>>
>>> After starting up postgres again, I observed the files spilled to
>>> data wasn't deleted.
>>>
>>> I think these files should be deleted because its transaction was no
>>> more valid, so no one can use these files.
>>>
>>>
>>> Below is a reproduction instructions.
>>>
>>> ------------------------------------------------
>>> 1. Create table and publication at publiser.
>>>
>>>   @pub =# CREATE TABLE t1(
>>>       id INT PRIMARY KEY,
>>>       name TEXT);
>>>
>>>   @pub =# CREATE PUBLICATION pub FOR TABLE t1;
>>>
>>> 2. Create table and subscription at subscriber.
>>>
>>>   @sub =# CREATE TABLE t1(
>>>       id INT PRIMARY KEY,
>>>       name TEXT
>>>       );
>>>
>>>   @sub =# CREATE SUBSCRIPTION sub
>>>       CONNECTION 'host=[hostname] port=[port] dbname=[dbname]'
>>>       PUBLICATION pub;
>>>
>>> 3. Put many queries into one transaction.
>>>
>>>   @pub =# BEGIN;
>>>         INSERT INTO t1
>>>         SELECT
>>>           i,
>>>           'aaaaaaaaaa'
>>>         FROM
>>>         generate_series(1, 1000000) as i;
>>>
>>> 4. Then we can see spilled files.
>>>
>>>   @pub $ ls -1 ${PGDATA}/pg_replslot/sub/
>>>     state
>>>     xid-561-lsn-0-1000000.snap
>>>     xid-561-lsn-0-2000000.snap
>>>     xid-561-lsn-0-3000000.snap
>>>     xid-561-lsn-0-4000000.snap
>>>     xid-561-lsn-0-5000000.snap
>>>     xid-561-lsn-0-6000000.snap
>>>     xid-561-lsn-0-7000000.snap
>>>     xid-561-lsn-0-8000000.snap
>>>     xid-561-lsn-0-9000000.snap
>>>
>>> 5. Kill publisher's postgres process before COMMIT.
>>>
>>>   @pub $ kill -s SIGKILL [pid of postgres]
>>>
>>> 6. Start publisher's postgres process.
>>>
>>>   @pub $ pg_ctl start -D ${PGDATA}
>>>
>>> 7. After a while, we can see the files remaining.
>>>   (Immediately after starting publiser, we can not see these files.)
>>>
>>>   @pub $ pg_ctl start -D ${PGDATA}
>>>
>>>   When I configured with '--enable-cassert', below assertion error
>>>   was appeared.
>>>
>>>     TRAP: FailedAssertion("!(txn->final_lsn != 0)", File: "reorderbuffer.c",
>>> Line: 2576)
>>> ------------------------------------------------
>>>
>>> Attached patch sets final_lsn to the last ReorderBufferChange if
>>> final_lsn == 0.
>>
>> Thank you for the report. I could reproduce this issue with the above
>> step. My analysis is, the cause of that a serialized reorder buffer
>> isn't cleaned up is that the aborted transaction without an abort WAL
>> record has no chance to set ReorderBufferTXN->final_lsn. So if there
>> is such serialized transactions ReorderBufferRestoreCleanup cleanups
>> no files, which is cause of the assertion failure (or a file being
>> orphaned). What do you think?
>>
>> On detail of your patch, I'm not sure it's safe if we set the lsn of
>> other than commit record or abort record to final_lsn. The comment in
>> reorderbuffer.h says,
>>
>> typedef trcut ReorderBufferTXN
>> {
>> (snip)
>>
>>     /* ----
>>      * LSN of the record that lead to this xact to be committed or
>>      * aborted. This can be a
>>      * * plain commit record
>>      * * plain commit record, of a parent transaction
>>      * * prepared transaction commit
>>      * * plain abort record
>>      * * prepared transaction abort
>>      * * error during decoding
>>      * ----
>>      */
>>     XLogRecPtr  final_lsn;
>>
>> But with your patch, we could set a lsn of a record that is other than
>> what listed above to final_lsn. One way I came up with is to make

I added some comments on final_lsn.

>> ReorderBufferRestoreCleanup accept an invalid value of final_lsn and
>> regards it as a aborted transaction that doesn't has a abort WAL
>> record. So we can cleanup all serialized files if final_lsn of a
>> transaction is invalid.
>
> After more thought, since there are some codes cosmetically setting
> final_lsn when the fate of transaction is determined possibly we
> should not accept a invalid value of final_lsn even in the case.
>

My new patch keeps setting final_lsn, but changed its location to the
top of ReorderBufferCleanupTXN().
I think it's a kind of preparation, so doing it at the top improves
readability.

> Anyway I think you should register this patch to the next commit fest so as not forget.

Thanks for you advice, I've registered this issue as a bug.

Regards,

--
Atsushi Torikoshi
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

Hello,

At Tue, 21 Nov 2017 20:27:25 +0900, atorikoshi <torikoshi_atsushi_z2@lab.ntt.co.jp> wrote in
<d5dddea9-4182-a7e4-f368-156f5470d244@lab.ntt.co.jp>
> Thanks for reviewing!
> 
> 
> On 2017/11/21 18:12, Masahiko Sawada wrote:
> > On Tue, Nov 21, 2017 at 3:48 PM, Masahiko Sawada
> > <sawada.mshk@gmail.com> wrote:
> >> On Mon, Nov 20, 2017 at 7:35 PM, atorikoshi
> >> <torikoshi_atsushi_z2@lab.ntt.co.jp> wrote:
> >>> Hi,
> >>>
> >>> I put many queries into one transaction and made ReorderBuffer spill
> >>> data to disk, and sent SIGKILL to postgres before the end of the
> >>> transaction.
> >>>
> >>> After starting up postgres again, I observed the files spilled to
> >>> data wasn't deleted.
> >>>
> >>> I think these files should be deleted because its transaction was no
> >>> more valid, so no one can use these files.
> >>>
> >>>
> >>> Below is a reproduction instructions.
> >>>
> >>> ------------------------------------------------
> >>> 1. Create table and publication at publiser.
> >>>
> >>>   @pub =# CREATE TABLE t1(
> >>>       id INT PRIMARY KEY,
> >>>       name TEXT);
> >>>
> >>>   @pub =# CREATE PUBLICATION pub FOR TABLE t1;
> >>>
> >>> 2. Create table and subscription at subscriber.
> >>>
> >>>   @sub =# CREATE TABLE t1(
> >>>       id INT PRIMARY KEY,
> >>>       name TEXT
> >>>       );
> >>>
> >>>   @sub =# CREATE SUBSCRIPTION sub
> >>>       CONNECTION 'host=[hostname] port=[port] dbname=[dbname]'
> >>>       PUBLICATION pub;
> >>>
> >>> 3. Put many queries into one transaction.
> >>>
> >>>   @pub =# BEGIN;
> >>>         INSERT INTO t1
> >>>         SELECT
> >>>           i,
> >>>           'aaaaaaaaaa'
> >>>         FROM
> >>>         generate_series(1, 1000000) as i;
> >>>
> >>> 4. Then we can see spilled files.
> >>>
> >>>   @pub $ ls -1 ${PGDATA}/pg_replslot/sub/
> >>>     state
> >>>     xid-561-lsn-0-1000000.snap
> >>>     xid-561-lsn-0-2000000.snap
> >>>     xid-561-lsn-0-3000000.snap
> >>>     xid-561-lsn-0-4000000.snap
> >>>     xid-561-lsn-0-5000000.snap
> >>>     xid-561-lsn-0-6000000.snap
> >>>     xid-561-lsn-0-7000000.snap
> >>>     xid-561-lsn-0-8000000.snap
> >>>     xid-561-lsn-0-9000000.snap
> >>>
> >>> 5. Kill publisher's postgres process before COMMIT.
> >>>
> >>>   @pub $ kill -s SIGKILL [pid of postgres]
> >>>
> >>> 6. Start publisher's postgres process.
> >>>
> >>>   @pub $ pg_ctl start -D ${PGDATA}
> >>>
> >>> 7. After a while, we can see the files remaining.
> >>>   (Immediately after starting publiser, we can not see these files.)
> >>>
> >>>   @pub $ pg_ctl start -D ${PGDATA}
> >>>
> >>>   When I configured with '--enable-cassert', below assertion error
> >>>   was appeared.
> >>>
> >>>     TRAP: FailedAssertion("!(txn->final_lsn != 0)", File:
> >>>     "reorderbuffer.c",
> >>> Line: 2576)
> >>> ------------------------------------------------
> >>>
> >>> Attached patch sets final_lsn to the last ReorderBufferChange if
> >>> final_lsn == 0.
> >>
> >> Thank you for the report. I could reproduce this issue with the above
> >> step. My analysis is, the cause of that a serialized reorder buffer
> >> isn't cleaned up is that the aborted transaction without an abort WAL
> >> record has no chance to set ReorderBufferTXN->final_lsn. So if there
> >> is such serialized transactions ReorderBufferRestoreCleanup cleanups
> >> no files, which is cause of the assertion failure (or a file being
> >> orphaned). What do you think?
> >>
> >> On detail of your patch, I'm not sure it's safe if we set the lsn of
> >> other than commit record or abort record to final_lsn. The comment in
> >> reorderbuffer.h says,
> >>
> >> typedef trcut ReorderBufferTXN
> >> {
> >> (snip)
> >>
> >>     /* ----
> >>      * LSN of the record that lead to this xact to be committed or
> >>      * aborted. This can be a
> >>      * * plain commit record
> >>      * * plain commit record, of a parent transaction
> >>      * * prepared transaction commit
> >>      * * plain abort record
> >>      * * prepared transaction abort
> >>      * * error during decoding
> >>      * ----
> >>      */
> >>     XLogRecPtr  final_lsn;
> >>
> >> But with your patch, we could set a lsn of a record that is other than
> >> what listed above to final_lsn. One way I came up with is to make
> 
> I added some comments on final_lsn.
> 
> >> ReorderBufferRestoreCleanup accept an invalid value of final_lsn and
> >> regards it as a aborted transaction that doesn't has a abort WAL
> >> record. So we can cleanup all serialized files if final_lsn of a
> >> transaction is invalid.
> >
> > After more thought, since there are some codes cosmetically setting
> > final_lsn when the fate of transaction is determined possibly we
> > should not accept a invalid value of final_lsn even in the case.
> >

It doesn't seem just a cosmetic. The first/last_lsn are used to
determin the files to be deleted. On the other hand the TXN
cannot have last_lsn since it hasn't see abort/commit record.

> My new patch keeps setting final_lsn, but changed its location to the
> top of ReorderBufferCleanupTXN().
> I think it's a kind of preparation, so doing it at the top improves
> readability.
> 
> > Anyway I think you should register this patch to the next commit fest
> > so as not forget.
> 
> Thanks for you advice, I've registered this issue as a bug.

Using last changing LSN might work but I'm afraid that that fails
to remove the last snap file if the crash happens at the very
start of a segment.

Anyway all files of the transaction is no longer useless at the
time, but it seems that the last_lsn is required to avoid
directory scanning at every transaction end.

Letting ReorderBufferAbortOld scan the directory and determine
the first and last LSN then set to the txn would work but it
might be an overkill. Using the beginning LSN of the next segment
of the last_change->lsn could surely work... really?
(ReorderBufferRestoreCleanup doesn't complain on ENOENT.)


By the way, just using unlink() there might lead to the revmoed
file's resurrection but it would be another issue.

regards

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

At Tue, 21 Nov 2017 20:53:04 +0900 (Tokyo Standard Time), Kyotaro HORIGUCHI <horiguchi.kyotaro@lab.ntt.co.jp> wrote in
<20171121.205304.90315453.horiguchi.kyotaro@lab.ntt.co.jp>
> At Tue, 21 Nov 2017 20:27:25 +0900, atorikoshi <torikoshi_atsushi_z2@lab.ntt.co.jp> wrote in
<d5dddea9-4182-a7e4-f368-156f5470d244@lab.ntt.co.jp>
> > Thanks for reviewing!
> > 
> > 
> > On 2017/11/21 18:12, Masahiko Sawada wrote:
> > > On Tue, Nov 21, 2017 at 3:48 PM, Masahiko Sawada
> > > <sawada.mshk@gmail.com> wrote:
> > >> On Mon, Nov 20, 2017 at 7:35 PM, atorikoshi
> > >> <torikoshi_atsushi_z2@lab.ntt.co.jp> wrote:
> > >>> Hi,
> > >>>
> > >>> I put many queries into one transaction and made ReorderBuffer spill
> > >>> data to disk, and sent SIGKILL to postgres before the end of the
> > >>> transaction.
> > >>>
> > >>> After starting up postgres again, I observed the files spilled to
> > >>> data wasn't deleted.
> > >>>
> > >>> I think these files should be deleted because its transaction was no
> > >>> more valid, so no one can use these files.
> > >>>
> > >>>
> > >>> Below is a reproduction instructions.
> > >>>
> > >>> ------------------------------------------------
> > >>> 1. Create table and publication at publiser.
> > >>>
> > >>>   @pub =# CREATE TABLE t1(
> > >>>       id INT PRIMARY KEY,
> > >>>       name TEXT);
> > >>>
> > >>>   @pub =# CREATE PUBLICATION pub FOR TABLE t1;
> > >>>
> > >>> 2. Create table and subscription at subscriber.
> > >>>
> > >>>   @sub =# CREATE TABLE t1(
> > >>>       id INT PRIMARY KEY,
> > >>>       name TEXT
> > >>>       );
> > >>>
> > >>>   @sub =# CREATE SUBSCRIPTION sub
> > >>>       CONNECTION 'host=[hostname] port=[port] dbname=[dbname]'
> > >>>       PUBLICATION pub;
> > >>>
> > >>> 3. Put many queries into one transaction.
> > >>>
> > >>>   @pub =# BEGIN;
> > >>>         INSERT INTO t1
> > >>>         SELECT
> > >>>           i,
> > >>>           'aaaaaaaaaa'
> > >>>         FROM
> > >>>         generate_series(1, 1000000) as i;
> > >>>
> > >>> 4. Then we can see spilled files.
> > >>>
> > >>>   @pub $ ls -1 ${PGDATA}/pg_replslot/sub/
> > >>>     state
> > >>>     xid-561-lsn-0-1000000.snap
> > >>>     xid-561-lsn-0-2000000.snap
> > >>>     xid-561-lsn-0-3000000.snap
> > >>>     xid-561-lsn-0-4000000.snap
> > >>>     xid-561-lsn-0-5000000.snap
> > >>>     xid-561-lsn-0-6000000.snap
> > >>>     xid-561-lsn-0-7000000.snap
> > >>>     xid-561-lsn-0-8000000.snap
> > >>>     xid-561-lsn-0-9000000.snap
> > >>>
> > >>> 5. Kill publisher's postgres process before COMMIT.
> > >>>
> > >>>   @pub $ kill -s SIGKILL [pid of postgres]
> > >>>
> > >>> 6. Start publisher's postgres process.
> > >>>
> > >>>   @pub $ pg_ctl start -D ${PGDATA}
> > >>>
> > >>> 7. After a while, we can see the files remaining.
> > >>>   (Immediately after starting publiser, we can not see these files.)
> > >>>
> > >>>   @pub $ pg_ctl start -D ${PGDATA}
> > >>>
> > >>>   When I configured with '--enable-cassert', below assertion error
> > >>>   was appeared.
> > >>>
> > >>>     TRAP: FailedAssertion("!(txn->final_lsn != 0)", File:
> > >>>     "reorderbuffer.c",
> > >>> Line: 2576)
> > >>> ------------------------------------------------
> > >>>
> > >>> Attached patch sets final_lsn to the last ReorderBufferChange if
> > >>> final_lsn == 0.
> > >>
> > >> Thank you for the report. I could reproduce this issue with the above
> > >> step. My analysis is, the cause of that a serialized reorder buffer
> > >> isn't cleaned up is that the aborted transaction without an abort WAL
> > >> record has no chance to set ReorderBufferTXN->final_lsn. So if there
> > >> is such serialized transactions ReorderBufferRestoreCleanup cleanups
> > >> no files, which is cause of the assertion failure (or a file being
> > >> orphaned). What do you think?
> > >>
> > >> On detail of your patch, I'm not sure it's safe if we set the lsn of
> > >> other than commit record or abort record to final_lsn. The comment in
> > >> reorderbuffer.h says,
> > >>
> > >> typedef trcut ReorderBufferTXN
> > >> {
> > >> (snip)
> > >>
> > >>     /* ----
> > >>      * LSN of the record that lead to this xact to be committed or
> > >>      * aborted. This can be a
> > >>      * * plain commit record
> > >>      * * plain commit record, of a parent transaction
> > >>      * * prepared transaction commit
> > >>      * * plain abort record
> > >>      * * prepared transaction abort
> > >>      * * error during decoding
> > >>      * ----
> > >>      */
> > >>     XLogRecPtr  final_lsn;
> > >>
> > >> But with your patch, we could set a lsn of a record that is other than
> > >> what listed above to final_lsn. One way I came up with is to make
> > 
> > I added some comments on final_lsn.
> > 
> > >> ReorderBufferRestoreCleanup accept an invalid value of final_lsn and
> > >> regards it as a aborted transaction that doesn't has a abort WAL
> > >> record. So we can cleanup all serialized files if final_lsn of a
> > >> transaction is invalid.
> > >
> > > After more thought, since there are some codes cosmetically setting
> > > final_lsn when the fate of transaction is determined possibly we
> > > should not accept a invalid value of final_lsn even in the case.
> > >
> 
> It doesn't seem just a cosmetic. The first/last_lsn are used to
> determin the files to be deleted. On the other hand the TXN
> cannot have last_lsn since it hasn't see abort/commit record.
> 
> > My new patch keeps setting final_lsn, but changed its location to the
> > top of ReorderBufferCleanupTXN().
> > I think it's a kind of preparation, so doing it at the top improves
> > readability.
> > 
> > > Anyway I think you should register this patch to the next commit fest
> > > so as not forget.
> > 
> > Thanks for you advice, I've registered this issue as a bug.
> 
> Using last changing LSN might work but I'm afraid that that fails
> to remove the last snap file if the crash happens at the very
> start of a segment.
> 
> Anyway all files of the transaction is no longer useless at the
> time, but it seems that the last_lsn is required to avoid
> directory scanning at every transaction end.
> 
> Letting ReorderBufferAbortOld scan the directory and determine
> the first and last LSN then set to the txn would work but it
> might be an overkill. Using the beginning LSN of the next segment
> of the last_change->lsn could surely work... really?
> (ReorderBufferRestoreCleanup doesn't complain on ENOENT.)

Somehow I deleted exessively while editing. One more possible
solution is making ReorderBufferAbortOld take final LSN and
DecodeStandbyOp passes the LSN of XLOG_RUNNING_XACTS record to
it.

> By the way, just using unlink() there might lead to the revmoed
> file's resurrection but it would be another issue.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

On Wed, Nov 22, 2017 at 9:03 AM, Kyotaro HORIGUCHI
<horiguchi.kyotaro@lab.ntt.co.jp> wrote:
> At Tue, 21 Nov 2017 20:53:04 +0900 (Tokyo Standard Time), Kyotaro HORIGUCHI <horiguchi.kyotaro@lab.ntt.co.jp> wrote
in<20171121.205304.90315453.horiguchi.kyotaro@lab.ntt.co.jp>
 
>> At Tue, 21 Nov 2017 20:27:25 +0900, atorikoshi <torikoshi_atsushi_z2@lab.ntt.co.jp> wrote in
<d5dddea9-4182-a7e4-f368-156f5470d244@lab.ntt.co.jp>
>> > Thanks for reviewing!
>> >
>> >
>> > On 2017/11/21 18:12, Masahiko Sawada wrote:
>> > > On Tue, Nov 21, 2017 at 3:48 PM, Masahiko Sawada
>> > > <sawada.mshk@gmail.com> wrote:
>> > >> On Mon, Nov 20, 2017 at 7:35 PM, atorikoshi
>> > >> <torikoshi_atsushi_z2@lab.ntt.co.jp> wrote:
>> > >>> Hi,
>> > >>>
>> > >>> I put many queries into one transaction and made ReorderBuffer spill
>> > >>> data to disk, and sent SIGKILL to postgres before the end of the
>> > >>> transaction.
>> > >>>
>> > >>> After starting up postgres again, I observed the files spilled to
>> > >>> data wasn't deleted.
>> > >>>
>> > >>> I think these files should be deleted because its transaction was no
>> > >>> more valid, so no one can use these files.
>> > >>>
>> > >>>
>> > >>> Below is a reproduction instructions.
>> > >>>
>> > >>> ------------------------------------------------
>> > >>> 1. Create table and publication at publiser.
>> > >>>
>> > >>>   @pub =# CREATE TABLE t1(
>> > >>>       id INT PRIMARY KEY,
>> > >>>       name TEXT);
>> > >>>
>> > >>>   @pub =# CREATE PUBLICATION pub FOR TABLE t1;
>> > >>>
>> > >>> 2. Create table and subscription at subscriber.
>> > >>>
>> > >>>   @sub =# CREATE TABLE t1(
>> > >>>       id INT PRIMARY KEY,
>> > >>>       name TEXT
>> > >>>       );
>> > >>>
>> > >>>   @sub =# CREATE SUBSCRIPTION sub
>> > >>>       CONNECTION 'host=[hostname] port=[port] dbname=[dbname]'
>> > >>>       PUBLICATION pub;
>> > >>>
>> > >>> 3. Put many queries into one transaction.
>> > >>>
>> > >>>   @pub =# BEGIN;
>> > >>>         INSERT INTO t1
>> > >>>         SELECT
>> > >>>           i,
>> > >>>           'aaaaaaaaaa'
>> > >>>         FROM
>> > >>>         generate_series(1, 1000000) as i;
>> > >>>
>> > >>> 4. Then we can see spilled files.
>> > >>>
>> > >>>   @pub $ ls -1 ${PGDATA}/pg_replslot/sub/
>> > >>>     state
>> > >>>     xid-561-lsn-0-1000000.snap
>> > >>>     xid-561-lsn-0-2000000.snap
>> > >>>     xid-561-lsn-0-3000000.snap
>> > >>>     xid-561-lsn-0-4000000.snap
>> > >>>     xid-561-lsn-0-5000000.snap
>> > >>>     xid-561-lsn-0-6000000.snap
>> > >>>     xid-561-lsn-0-7000000.snap
>> > >>>     xid-561-lsn-0-8000000.snap
>> > >>>     xid-561-lsn-0-9000000.snap
>> > >>>
>> > >>> 5. Kill publisher's postgres process before COMMIT.
>> > >>>
>> > >>>   @pub $ kill -s SIGKILL [pid of postgres]
>> > >>>
>> > >>> 6. Start publisher's postgres process.
>> > >>>
>> > >>>   @pub $ pg_ctl start -D ${PGDATA}
>> > >>>
>> > >>> 7. After a while, we can see the files remaining.
>> > >>>   (Immediately after starting publiser, we can not see these files.)
>> > >>>
>> > >>>   @pub $ pg_ctl start -D ${PGDATA}
>> > >>>
>> > >>>   When I configured with '--enable-cassert', below assertion error
>> > >>>   was appeared.
>> > >>>
>> > >>>     TRAP: FailedAssertion("!(txn->final_lsn != 0)", File:
>> > >>>     "reorderbuffer.c",
>> > >>> Line: 2576)
>> > >>> ------------------------------------------------
>> > >>>
>> > >>> Attached patch sets final_lsn to the last ReorderBufferChange if
>> > >>> final_lsn == 0.
>> > >>
>> > >> Thank you for the report. I could reproduce this issue with the above
>> > >> step. My analysis is, the cause of that a serialized reorder buffer
>> > >> isn't cleaned up is that the aborted transaction without an abort WAL
>> > >> record has no chance to set ReorderBufferTXN->final_lsn. So if there
>> > >> is such serialized transactions ReorderBufferRestoreCleanup cleanups
>> > >> no files, which is cause of the assertion failure (or a file being
>> > >> orphaned). What do you think?
>> > >>
>> > >> On detail of your patch, I'm not sure it's safe if we set the lsn of
>> > >> other than commit record or abort record to final_lsn. The comment in
>> > >> reorderbuffer.h says,
>> > >>
>> > >> typedef trcut ReorderBufferTXN
>> > >> {
>> > >> (snip)
>> > >>
>> > >>     /* ----
>> > >>      * LSN of the record that lead to this xact to be committed or
>> > >>      * aborted. This can be a
>> > >>      * * plain commit record
>> > >>      * * plain commit record, of a parent transaction
>> > >>      * * prepared transaction commit
>> > >>      * * plain abort record
>> > >>      * * prepared transaction abort
>> > >>      * * error during decoding
>> > >>      * ----
>> > >>      */
>> > >>     XLogRecPtr  final_lsn;
>> > >>
>> > >> But with your patch, we could set a lsn of a record that is other than
>> > >> what listed above to final_lsn. One way I came up with is to make
>> >
>> > I added some comments on final_lsn.
>> >
>> > >> ReorderBufferRestoreCleanup accept an invalid value of final_lsn and
>> > >> regards it as a aborted transaction that doesn't has a abort WAL
>> > >> record. So we can cleanup all serialized files if final_lsn of a
>> > >> transaction is invalid.
>> > >
>> > > After more thought, since there are some codes cosmetically setting
>> > > final_lsn when the fate of transaction is determined possibly we
>> > > should not accept a invalid value of final_lsn even in the case.
>> > >
>>
>> It doesn't seem just a cosmetic. The first/last_lsn are used to
>> determin the files to be deleted. On the other hand the TXN
>> cannot have last_lsn since it hasn't see abort/commit record.
>>
>> > My new patch keeps setting final_lsn, but changed its location to the
>> > top of ReorderBufferCleanupTXN().
>> > I think it's a kind of preparation, so doing it at the top improves
>> > readability.
>> >
>> > > Anyway I think you should register this patch to the next commit fest
>> > > so as not forget.
>> >
>> > Thanks for you advice, I've registered this issue as a bug.
>>
>> Using last changing LSN might work but I'm afraid that that fails
>> to remove the last snap file if the crash happens at the very
>> start of a segment.

I think it works even in the case because the we can compute the
largest WAL segment number that we need to remove by using the lsn of
the last change in old transaction. Am I missing something?

>>
>> Anyway all files of the transaction is no longer useless at the
>> time, but it seems that the last_lsn is required to avoid
>> directory scanning at every transaction end.
>>
>> Letting ReorderBufferAbortOld scan the directory and determine
>> the first and last LSN then set to the txn would work but it
>> might be an overkill. Using the beginning LSN of the next segment
>> of the last_change->lsn could surely work... really?
>> (ReorderBufferRestoreCleanup doesn't complain on ENOENT.)
>
> Somehow I deleted exessively while editing. One more possible
> solution is making ReorderBufferAbortOld take final LSN and
> DecodeStandbyOp passes the LSN of XLOG_RUNNING_XACTS record to
> it.
>

Setting final_lsn in ReorderBufferAbortOld seems good to me but I'm
not sure we can use the lsn of XLOG_RUNNING_XACTS record. Doesn't
ReorderBufferRestoreCleanup() raise an error due to ENOENT if the wal
segment having XLOG_RUNNING_XACTS records doesn't have any changes of
the old transaction?

Regards,

--
Masahiko Sawada
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

Hi,

At Wed, 22 Nov 2017 10:10:27 +0900, Masahiko Sawada <sawada.mshk@gmail.com> wrote in
<CAD21AoDkPbCNX-d_VqKrW4rDt5W5Y3=LQr7zYbbxF=uVDayt-A@mail.gmail.com>
> >> Using last changing LSN might work but I'm afraid that that fails
> >> to remove the last snap file if the crash happens at the very
> >> start of a segment.
> 
> I think it works even in the case because the we can compute the
> largest WAL segment number that we need to remove by using the lsn of
> the last change in old transaction. Am I missing something?

I'm concerned by the window that can leave an empty file in
ReorderBufferSerializeTXN. But I had a closer look and found that
the snap files for old transactions are not of the previous run,
but rebuilt from WAL records after restart. So there cannot be an
empty file there.

I'm convinced that it is the proper way to deal with this problem.

> >> Anyway all files of the transaction is no longer useless at the
> >> time, but it seems that the last_lsn is required to avoid
> >> directory scanning at every transaction end.
> >>
> >> Letting ReorderBufferAbortOld scan the directory and determine
> >> the first and last LSN then set to the txn would work but it
> >> might be an overkill. Using the beginning LSN of the next segment
> >> of the last_change->lsn could surely work... really?
> >> (ReorderBufferRestoreCleanup doesn't complain on ENOENT.)
> >
> > Somehow I deleted exessively while editing. One more possible
> > solution is making ReorderBufferAbortOld take final LSN and
> > DecodeStandbyOp passes the LSN of XLOG_RUNNING_XACTS record to
> > it.
> >
> 
> Setting final_lsn in ReorderBufferAbortOld seems good to me but I'm
> not sure we can use the lsn of XLOG_RUNNING_XACTS record. Doesn't
> ReorderBufferRestoreCleanup() raise an error due to ENOENT if the wal

It no longer matters but the function does *not* raise an error
on ENOENT.

> segment having XLOG_RUNNING_XACTS records doesn't have any changes of
> the old transaction?

Since the transaction doesn't meet abort record any larger LSN
can work as final_lsn and the record is guaranteed to be so. But
anyway I agree that the last_change->lsn is more proper than it.

regards,

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

On Wed, Nov 22, 2017 at 11:49 AM, Craig Ringer <craig@2ndquadrant.com> wrote:
> On 20 November 2017 at 18:35, atorikoshi
> <torikoshi_atsushi_z2@lab.ntt.co.jp> wrote:
>> I put many queries into one transaction and made ReorderBuffer spill
>> data to disk, and sent SIGKILL to postgres before the end of the
>> transaction.
>>
>> After starting up postgres again, I observed the files spilled to
>> data wasn't deleted.
>
> Since this can only happen  on crash exits, and the reorderbuffer data is
> useless after a decoding backend exits, why don't we just recursively delete
> the tree contents on Pg startup?

+1. You would just need an extra step after say
DeleteAllExportedSnapshotFiles() in startup.c. Looks saner to me do so
so as well.
-- 
Michael

At Wed, 22 Nov 2017 12:57:34 +0900, Michael Paquier <michael.paquier@gmail.com> wrote in
<CAB7nPqQP52cLEUZJv-1MoCiejNYQ4CGs=tzwhP2oEErvv7R3Bg@mail.gmail.com>
> On Wed, Nov 22, 2017 at 11:49 AM, Craig Ringer <craig@2ndquadrant.com> wrote:
> > On 20 November 2017 at 18:35, atorikoshi
> > <torikoshi_atsushi_z2@lab.ntt.co.jp> wrote:
> >> I put many queries into one transaction and made ReorderBuffer spill
> >> data to disk, and sent SIGKILL to postgres before the end of the
> >> transaction.
> >>
> >> After starting up postgres again, I observed the files spilled to
> >> data wasn't deleted.
> >
> > Since this can only happen  on crash exits, and the reorderbuffer data is
> > useless after a decoding backend exits, why don't we just recursively delete
> > the tree contents on Pg startup?
> 
> +1. You would just need an extra step after say
> DeleteAllExportedSnapshotFiles() in startup.c. Looks saner to me do so
> so as well.

The old files are being removed at startup by
StartupReorderBuffer.

At the time of assertion failure, the files are not of the
previous run, but they are created after reconnection from the
subscriber.

regards,

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

On Wed, Nov 22, 2017 at 2:56 PM, Craig Ringer <craig@2ndquadrant.com> wrote:
> On 22 November 2017 at 12:15, Kyotaro HORIGUCHI
> <horiguchi.kyotaro@lab.ntt.co.jp> wrote:
>>
>> At Wed, 22 Nov 2017 12:57:34 +0900, Michael Paquier
>> <michael.paquier@gmail.com> wrote in
>> <CAB7nPqQP52cLEUZJv-1MoCiejNYQ4CGs=tzwhP2oEErvv7R3Bg@mail.gmail.com>
>> > On Wed, Nov 22, 2017 at 11:49 AM, Craig Ringer <craig@2ndquadrant.com>
>> > wrote:
>> > > On 20 November 2017 at 18:35, atorikoshi
>> > > <torikoshi_atsushi_z2@lab.ntt.co.jp> wrote:
>> > >> I put many queries into one transaction and made ReorderBuffer spill
>> > >> data to disk, and sent SIGKILL to postgres before the end of the
>> > >> transaction.
>> > >>
>> > >> After starting up postgres again, I observed the files spilled to
>> > >> data wasn't deleted.
>> > >
>> > > Since this can only happen  on crash exits, and the reorderbuffer data
>> > > is
>> > > useless after a decoding backend exits, why don't we just recursively
>> > > delete
>> > > the tree contents on Pg startup?
>> >
>> > +1. You would just need an extra step after say
>> > DeleteAllExportedSnapshotFiles() in startup.c. Looks saner to me do so
>> > so as well.
>>
>> The old files are being removed at startup by
>> StartupReorderBuffer.
>
>
> That seems to contradict the statement above, that "after starting up
> postgres again, I observed the files spilled to disk weren't deleted".
>
>>
>> At the time of assertion failure, the files are not of the
>> previous run, but they are created after reconnection from the
>> subscriber.
>
>
> Are you saying the problem files do not exist when we start up, but are
> created and then leaked after logical decoding resumes after an unclean
> startup?
>
> ... Yes, that does appear to be the case, per the original report:
>
> "7. After a while, we can see the files remaining.
>   (Immediately after starting publiser, we can not see these files.)"
>
> I was confused by "remaining". They're not remaining, they've been
> re-created.
>
> But if they're re-created, why are they not recreated correctly after an
> unclean shutdown? What persistent state is causing that? We should be
> clobbering saved reorder buffer temp files, snapshots, etc at startup. The
> slot state is pretty simple, it'd just be a bit behind.
>
> The key difference seems to be that we hard-kill the server so it can't
> write anything to clog. The xact is implicitly aborted, we never wrote any
> xlog record for a commit or abort. The problem is presumably with decoding
> xacts that were implicitly aborted by server crash, after we restart the
> server and resume decoding.
>
> The assertion failure reported is in ReorderBufferRestoreCleanup, which
> makes sense.
>
> Because there's no xlog record of the crash, we never set the buffer's
> final_lsn in ReorderBufferCommit or ReorderBufferAbort .

Yeah, that's the same as my analysis.

> Note the comment there:
>
>  * NB: Transactions handled here have to have actively aborted (i.e. have
>  * produced an abort record). Implicitly aborted transactions are handled
> via
>  * ReorderBufferAbortOld(); transactions we're just not interested in, but
>  * which have committed are handled in ReorderBufferForget().
>
> That's only called from DecodeStandbyOp in response to an xl_running_xacts.
>
> Here's the backtrace.
>
> Core was generated by `postgres: wal sender process postgres [local'.
> Program terminated with signal SIGABRT, Aborted.
> ...
> #2  0x00000000008537b7 in ExceptionalCondition
> (conditionName=conditionName@entry=0x9fcdf6 "!(txn->final_lsn != 0)",
> errorType=errorType@entry=0x89bcb4 "FailedAssertion",
>     fileName=fileName@entry=0x9fcd04 "reorderbuffer.c",
> lineNumber=lineNumber@entry=2576) at assert.c:54
> #3  0x00000000006fec02 in ReorderBufferRestoreCleanup
> (rb=rb@entry=0x1b4c370, txn=txn@entry=0x1b5c3b8) at reorderbuffer.c:2576
> #4  0x0000000000700693 in ReorderBufferCleanupTXN (rb=rb@entry=0x1b4c370,
> txn=txn@entry=0x1b5c3b8) at reorderbuffer.c:1145
> #5  0x0000000000701516 in ReorderBufferAbortOld (rb=0x1b4c370,
> oldestRunningXid=558) at reorderbuffer.c:1730
> #6  0x00000000006f5a47 in DecodeStandbyOp (ctx=0x1af9ce0,
> buf=buf@entry=0x7ffd11761200) at decode.c:325
> #7  0x00000000006f65bf in LogicalDecodingProcessRecord (ctx=<optimized out>,
> record=<optimized out>) at decode.c:117
> #8  0x00000000007098ab in XLogSendLogical () at walsender.c:2766
> #9  0x000000000070a875 in WalSndLoop (send_data=send_data@entry=0x709857
> <XLogSendLogical>) at walsender.c:2134
> #10 0x000000000070b011 in StartLogicalReplication (cmd=cmd@entry=0x1a9cd68)
> at walsender.c:1101
> #11 0x000000000070b46f in exec_replication_command
> (cmd_string=cmd_string@entry=0x1afec30 "START_REPLICATION SLOT \"sub\"
> LOGICAL 0/0 (proto_version '1', publication_names '\"pub\"')") at
> walsender.c:1527
> #12 0x0000000000758809 in PostgresMain (argc=<optimized out>,
> argv=argv@entry=0x1aab870, dbname=<optimized out>, username=<optimized out>)
> at postgres.c:4086
> #13 0x00000000006e178d in BackendRun (port=port@entry=0x1aa3430) at
> postmaster.c:4357
> #14 0x00000000006e35e9 in BackendStartup (port=port@entry=0x1aa3430) at
> postmaster.c:4029
> #15 0x00000000006e39e3 in ServerLoop () at postmaster.c:1753
> #16 0x00000000006e4b36 in PostmasterMain (argc=argc@entry=3,
> argv=argv@entry=0x1a7c5d0) at postmaster.c:1361
> #17 0x000000000065d093 in main (argc=3, argv=0x1a7c5d0) at main.c:228
>
> So it's clear why we can call ReorderBufferCleanupOld with no final_lsn set.
>
> I think your approach of setting final_lsn to the last buffered action is
> fine.
>
> I wonder if we should be setting it in ReorderBufferAbortOld though, when we
> know for sure that we're seeing final_lsn==0 in response to this specific
> situation. That way we don't mask other potential bugs the assertions are
> there to catch.
>

+1

+    /*
+     * Before cleaning up, do a preparation.
+     * If this transaction encountered crash during transaction,
+     * txn->final_lsn remains initial value.
+     * To properly remove entries which were spilled to disk, we need valid
+     * final_lsn.
+     * So set final_lsn to the lsn of last ReorderBufferChange.
+     */

ISTM the comment is slightly unclear. How about something like "The
final_lsn of which transaction that haven't produced an abort record
have is invalid. To ensure cleanup the serialized changes of such
transaction we set the LSN of the last change action to final_lsn."?

-------
@@ -168,6 +168,8 @@ typedef struct ReorderBufferTXN     * * plain abort record     * * prepared transaction abort     *
*error during decoding
 
+     * Only when this xact encountered server crash, this value is set to
+     * the lsn of last ReorderBufferChange for cleaning up spilled files.     * ----     */    XLogRecPtr
final_lsn;

Also, how about something like "Note that this can also be a LSN of
the last change action of this xact if it is an implicitely aborted
transaction."? Since I'm not a native speaker it sounds might be wrong
though.

Regards,

--
Masahiko Sawada
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

On Wed, Nov 22, 2017 at 12:27 AM, atorikoshi
<torikoshi_atsushi_z2@lab.ntt.co.jp> wrote:
> [set_final_lsn_2.patch]

Hi Torikoshi-san,

FYI "make check" in contrib/test_decoding fails a couple of isolation
tests, one with an assertion failure for my automatic patch tester[1].
Same result on my laptop:

test ondisk_startup           ... FAILED (test process exited with exit code 1)
test concurrent_ddl_dml       ... FAILED (test process exited with exit code 1)

TRAP: FailedAssertion("!(!dlist_is_empty(head))", File:
"../../../../src/include/lib/ilist.h", Line: 458)

[1] https://travis-ci.org/postgresql-cfbot/postgresql/builds/305636335

-- 
Thomas Munro
http://www.enterprisedb.com

On 2017/11/22 16:49, Masahiko Sawada wrote:
> On Wed, Nov 22, 2017 at 2:56 PM, Craig Ringer <craig@2ndquadrant.com> wrote:
>> On 22 November 2017 at 12:15, Kyotaro HORIGUCHI
>> <horiguchi.kyotaro@lab.ntt.co.jp> wrote:
>>>
>>> At Wed, 22 Nov 2017 12:57:34 +0900, Michael Paquier
>>> <michael.paquier@gmail.com> wrote in
>>> <CAB7nPqQP52cLEUZJv-1MoCiejNYQ4CGs=tzwhP2oEErvv7R3Bg@mail.gmail.com>
>>>> On Wed, Nov 22, 2017 at 11:49 AM, Craig Ringer <craig@2ndquadrant.com>
>>>> wrote:
>>>>> On 20 November 2017 at 18:35, atorikoshi
>>>>> <torikoshi_atsushi_z2@lab.ntt.co.jp> wrote:
>>>>>> I put many queries into one transaction and made ReorderBuffer spill
>>>>>> data to disk, and sent SIGKILL to postgres before the end of the
>>>>>> transaction.
>>>>>>
>>>>>> After starting up postgres again, I observed the files spilled to
>>>>>> data wasn't deleted.
>>>>>
>>>>> Since this can only happen  on crash exits, and the reorderbuffer data
>>>>> is
>>>>> useless after a decoding backend exits, why don't we just recursively
>>>>> delete
>>>>> the tree contents on Pg startup?
>>>>
>>>> +1. You would just need an extra step after say
>>>> DeleteAllExportedSnapshotFiles() in startup.c. Looks saner to me do so
>>>> so as well.
>>>
>>> The old files are being removed at startup by
>>> StartupReorderBuffer.
>>
>>
>> That seems to contradict the statement above, that "after starting up
>> postgres again, I observed the files spilled to disk weren't deleted".
>>
>>>
>>> At the time of assertion failure, the files are not of the
>>> previous run, but they are created after reconnection from the
>>> subscriber.
>>
>>
>> Are you saying the problem files do not exist when we start up, but are
>> created and then leaked after logical decoding resumes after an unclean
>> startup?
>>
>> ... Yes, that does appear to be the case, per the original report:
>>
>> "7. After a while, we can see the files remaining.
>>   (Immediately after starting publiser, we can not see these files.)"
>>
>> I was confused by "remaining". They're not remaining, they've been
>> re-created.

Sorry for my incorrect description, I should have said re-created.

>>
>> But if they're re-created, why are they not recreated correctly after an
>> unclean shutdown? What persistent state is causing that? We should be
>> clobbering saved reorder buffer temp files, snapshots, etc at startup. The
>> slot state is pretty simple, it'd just be a bit behind.
>>
>> The key difference seems to be that we hard-kill the server so it can't
>> write anything to clog. The xact is implicitly aborted, we never wrote any
>> xlog record for a commit or abort. The problem is presumably with decoding
>> xacts that were implicitly aborted by server crash, after we restart the
>> server and resume decoding.
>>
>> The assertion failure reported is in ReorderBufferRestoreCleanup, which
>> makes sense.
>>
>> Because there's no xlog record of the crash, we never set the buffer's
>> final_lsn in ReorderBufferCommit or ReorderBufferAbort .
>
> Yeah, that's the same as my analysis.
>
>> Note the comment there:
>>
>>  * NB: Transactions handled here have to have actively aborted (i.e. have
>>  * produced an abort record). Implicitly aborted transactions are handled
>> via
>>  * ReorderBufferAbortOld(); transactions we're just not interested in, but
>>  * which have committed are handled in ReorderBufferForget().
>>
>> That's only called from DecodeStandbyOp in response to an xl_running_xacts.
>>
>> Here's the backtrace.
>>
>> Core was generated by `postgres: wal sender process postgres [local'.
>> Program terminated with signal SIGABRT, Aborted.
>> ...
>> #2  0x00000000008537b7 in ExceptionalCondition
>> (conditionName=conditionName@entry=0x9fcdf6 "!(txn->final_lsn != 0)",
>> errorType=errorType@entry=0x89bcb4 "FailedAssertion",
>>     fileName=fileName@entry=0x9fcd04 "reorderbuffer.c",
>> lineNumber=lineNumber@entry=2576) at assert.c:54
>> #3  0x00000000006fec02 in ReorderBufferRestoreCleanup
>> (rb=rb@entry=0x1b4c370, txn=txn@entry=0x1b5c3b8) at reorderbuffer.c:2576
>> #4  0x0000000000700693 in ReorderBufferCleanupTXN (rb=rb@entry=0x1b4c370,
>> txn=txn@entry=0x1b5c3b8) at reorderbuffer.c:1145
>> #5  0x0000000000701516 in ReorderBufferAbortOld (rb=0x1b4c370,
>> oldestRunningXid=558) at reorderbuffer.c:1730
>> #6  0x00000000006f5a47 in DecodeStandbyOp (ctx=0x1af9ce0,
>> buf=buf@entry=0x7ffd11761200) at decode.c:325
>> #7  0x00000000006f65bf in LogicalDecodingProcessRecord (ctx=<optimized out>,
>> record=<optimized out>) at decode.c:117
>> #8  0x00000000007098ab in XLogSendLogical () at walsender.c:2766
>> #9  0x000000000070a875 in WalSndLoop (send_data=send_data@entry=0x709857
>> <XLogSendLogical>) at walsender.c:2134
>> #10 0x000000000070b011 in StartLogicalReplication (cmd=cmd@entry=0x1a9cd68)
>> at walsender.c:1101
>> #11 0x000000000070b46f in exec_replication_command
>> (cmd_string=cmd_string@entry=0x1afec30 "START_REPLICATION SLOT \"sub\"
>> LOGICAL 0/0 (proto_version '1', publication_names '\"pub\"')") at
>> walsender.c:1527
>> #12 0x0000000000758809 in PostgresMain (argc=<optimized out>,
>> argv=argv@entry=0x1aab870, dbname=<optimized out>, username=<optimized out>)
>> at postgres.c:4086
>> #13 0x00000000006e178d in BackendRun (port=port@entry=0x1aa3430) at
>> postmaster.c:4357
>> #14 0x00000000006e35e9 in BackendStartup (port=port@entry=0x1aa3430) at
>> postmaster.c:4029
>> #15 0x00000000006e39e3 in ServerLoop () at postmaster.c:1753
>> #16 0x00000000006e4b36 in PostmasterMain (argc=argc@entry=3,
>> argv=argv@entry=0x1a7c5d0) at postmaster.c:1361
>> #17 0x000000000065d093 in main (argc=3, argv=0x1a7c5d0) at main.c:228
>>
>> So it's clear why we can call ReorderBufferCleanupOld with no final_lsn set.
>>
>> I think your approach of setting final_lsn to the last buffered action is
>> fine.
>>
>> I wonder if we should be setting it in ReorderBufferAbortOld though, when we
>> know for sure that we're seeing final_lsn==0 in response to this specific
>> situation. That way we don't mask other potential bugs the assertions are
>> there to catch.
>>
>
> +1

+1, I've changed the location.

>
> +    /*
> +     * Before cleaning up, do a preparation.
> +     * If this transaction encountered crash during transaction,
> +     * txn->final_lsn remains initial value.
> +     * To properly remove entries which were spilled to disk, we need valid
> +     * final_lsn.
> +     * So set final_lsn to the lsn of last ReorderBufferChange.
> +     */
>
> ISTM the comment is slightly unclear. How about something like "The
> final_lsn of which transaction that haven't produced an abort record
> have is invalid. To ensure cleanup the serialized changes of such
> transaction we set the LSN of the last change action to final_lsn."?
>
> -------
> @@ -168,6 +168,8 @@ typedef struct ReorderBufferTXN
>       * * plain abort record
>       * * prepared transaction abort
>       * * error during decoding
> +     * Only when this xact encountered server crash, this value is set to
> +     * the lsn of last ReorderBufferChange for cleaning up spilled files.
>       * ----
>       */
>      XLogRecPtr    final_lsn;
>
> Also, how about something like "Note that this can also be a LSN of
> the last change action of this xact if it is an implicitely aborted
> transaction."? Since I'm not a native speaker it sounds might be wrong
> though.
>

+1, I've changed comments using your proposal.


> Hi Torikoshi-san,
>
> FYI "make check" in contrib/test_decoding fails a couple of isolation
> tests, one with an assertion failure for my automatic patch tester[1].
> Same result on my laptop:
>
> test ondisk_startup           ... FAILED (test process exited with exit code 1)
> test concurrent_ddl_dml       ... FAILED (test process exited with exit code 1)
>
> TRAP: FailedAssertion("!(!dlist_is_empty(head))", File:
> "../../../../src/include/lib/ilist.h", Line: 458)

Thanks for letting me know.
I think I only tested running "make check" at top directory, sorry
for my insufficient test.

The test failure happened at the beginning of replication(creating
slot), so there are no changes yet and getting the tail of changes
failed.

Because the bug we are fixing only happens after creating files,
I've added "txn->serialized" to the if statement condition.


Regards,

-- 
Atsushi Torikoshi
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

On 2017/11/24 10:57, Craig Ringer wrote:
 > On 24 November 2017 at 09:20, atorikoshi 
<torikoshi_atsushi_z2@lab.ntt.co.jp
 >> wrote:
 >
 >>
 >> Thanks for letting me know.
 >> I think I only tested running "make check" at top directory, sorry
 >> for my insufficient test.
 >>
 >> The test failure happened at the beginning of replication(creating
 >> slot), so there are no changes yet and getting the tail of changes
 >> failed.
 >>
 >> Because the bug we are fixing only happens after creating files,
 >> I've added "txn->serialized" to the if statement condition.
 >
 >
 > Thanks.
 >
 > Re-reading the patch I see
 >
 >  * The final_lsn of which transaction that hasn't produced an abort
 >  * record is invalid.
 >
 > which I find very hard to parse. I suggest:
 >
 >  We set final_lsn when we decode the commit or abort record for a
 > transaction,
 >  but transactions implicitly aborted by a crash never write such a 
record.
 >
 > then continue from there with the same text as in the patch.
 >
 > Otherwise I'm happy. It passes make check, test decoding and the recovery
 > TAP tests too.
 >

Thanks for your kind suggestion and running test.
I've added your comment at the beginning.

-- 
Atsushi Torikoshi
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

Thomas Munro wrote:
> On Wed, Nov 22, 2017 at 12:27 AM, atorikoshi
> <torikoshi_atsushi_z2@lab.ntt.co.jp> wrote:
> > [set_final_lsn_2.patch]
> 
> Hi Torikoshi-san,
> 
> FYI "make check" in contrib/test_decoding fails a couple of isolation
> tests, one with an assertion failure for my automatic patch tester[1].
> Same result on my laptop:
> 
> test ondisk_startup           ... FAILED (test process exited with exit code 1)
> test concurrent_ddl_dml       ... FAILED (test process exited with exit code 1)
> 
> TRAP: FailedAssertion("!(!dlist_is_empty(head))", File:
> "../../../../src/include/lib/ilist.h", Line: 458)

I observed a couple of crashes too a couple of times, while testing this
patch.  But I have seen several completely different crashes.  This
crash you show I have not been able to reproduce, though I've run this
in 94 and master many times.

For example, I got a backtrace that looks like this in 9.6:

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#1  0x00007f19ccb913fa in __GI_abort () at abort.c:89
#2  0x000055e7511f451b in errfinish (dummy=<optimized out>)
    at /pgsql/source/REL9_6_STABLE/src/backend/utils/error/elog.c:557
#3  0x000055e750ed732b in XLogFileInit (logsegno=1, 
    use_existent=use_existent@entry=0x7ffdbc34ab6f "\001\002", use_lock=use_lock@entry=1 '\001')
    at /pgsql/source/REL9_6_STABLE/src/backend/access/transam/xlog.c:3023
#4  0x000055e750edb227 in XLogWrite (WriteRqst=..., flexible=flexible@entry=0 '\000')
    at /pgsql/source/REL9_6_STABLE/src/backend/access/transam/xlog.c:2258
#5  0x000055e750ee162d in XLogBackgroundFlush ()
    at /pgsql/source/REL9_6_STABLE/src/backend/access/transam/xlog.c:2894

then in 9.4 I saw this one:

creating information schema ... ok
loading PL/pgSQL server-side language ... ok
vacuuming database template1 ... ok
copying template1 to template0 ... FATAL:  could not open directory "pg_logical/snapshots": No such file or directory
STATEMENT:  CREATE DATABASE template0;
    
WARNING:  could not remove file or directory "base/12148": No such file or directory
WARNING:  some useless files may be left behind in old database directory "base/12148"
FATAL:  could not access status of transaction 0
DETAIL:  Could not open file "pg_clog/0000": No such file or directory.
child process exited with exit code 1

What this indicates to me is that perhaps the test harness is doing
stupid things such as running two servers concurrently in the same
datadir, so they overwrite one another.  If I take out the "-j2" from
make, this no longer reproduces.

Therefore, I'm going to push this patch shortly because clearly this
problem is not its fault.

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

atorikoshi wrote:

> > FYI "make check" in contrib/test_decoding fails a couple of isolation
> > tests, one with an assertion failure for my automatic patch tester[1].
> > Same result on my laptop:
> > 
> > test ondisk_startup           ... FAILED (test process exited with exit code 1)
> > test concurrent_ddl_dml       ... FAILED (test process exited with exit code 1)
> > 
> > TRAP: FailedAssertion("!(!dlist_is_empty(head))", File:
> > "../../../../src/include/lib/ilist.h", Line: 458)
> 
> Thanks for letting me know.
> I think I only tested running "make check" at top directory, sorry
> for my insufficient test.
> 
> The test failure happened at the beginning of replication(creating
> slot), so there are no changes yet and getting the tail of changes
> failed.
> 
> Because the bug we are fixing only happens after creating files,
> I've added "txn->serialized" to the if statement condition.

Ahh, so the reason I didn't see these crashes is that Atsushi had
already fixed them.  Nice.  It would be *very* good to trim the quoted
material when you reply --- don't leave everything, just enough lines
for context.  I would have seen this comment if it didn't require me to
scroll pages and pages and pages of useless material.

I have pushed this patch from 9.4 to master.  I reformulated the
comments.

This is an "implicitly aborted transaction":

alvherre=# create table implicit (a int);
CREATE TABLE
Duración: 0,959 ms
alvherre=# insert into implicit select 1/i from generate_series(5, -5, -1) i;
ERROR:  division by zero

Note there is no explicit ABORT here, so it is implicit.

But that is not what you were trying to say.  The term "crashed
transaction" seems to me to convey the meaning better, so I used that.

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

On 2018/01/06 0:30, Alvaro Herrera wrote:
> Ahh, so the reason I didn't see these crashes is that Atsushi had
> already fixed them.  Nice.  It would be *very* good to trim the quoted
> material when you reply --- don't leave everything, just enough lines
> for context.  I would have seen this comment if it didn't require me to
> scroll pages and pages and pages of useless material.

Sorry for the confusion.

>
> I have pushed this patch from 9.4 to master.  I reformulated the
> comments.

Thanks for modifications and committing.

Regards,

-- 
Atsushi Torikoshi
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center