GIN logging GIN_SEGMENT_UNMODIFIED actions?

Started by Andres Freundalmost 10 years ago13 messageshackers

andres@anarazel.de

almost 10 years ago

Hi,

trying to debug something I saw the following in pg_xlogdump output:

rmgr: Gin len (rec/tot): 0/ 274, tx: 0, lsn: 1C/DF28AEB0, prev 1C/DF289858, desc: VACUUM_DATA_LEAF_PAGE 3 segments: 5 unknown action 0 ???, blkref #0: rel 1663/16384/16435 blk 310982

note the "segments: 5 unknown action 0 ???" bit. That doesn't seem
right, given:
#define GIN_SEGMENT_UNMODIFIED 0 /* no action (not used in WAL records) */

Greetings,

Andres Freund

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Alexander Korotkov

aekorotkov@gmail.com

almost 10 years ago

In reply to: Andres Freund (#1)

Re: GIN logging GIN_SEGMENT_UNMODIFIED actions?

Hi!

On Mon, May 9, 2016 at 10:46 PM, Andres Freund <andres@anarazel.de> wrote:

trying to debug something I saw the following in pg_xlogdump output:

rmgr: Gin len (rec/tot): 0/ 274, tx: 0, lsn:
1C/DF28AEB0, prev 1C/DF289858, desc: VACUUM_DATA_LEAF_PAGE 3 segments: 5
unknown action 0 ???, blkref #0: rel 1663/16384/16435 blk 310982

note the "segments: 5 unknown action 0 ???" bit. That doesn't seem
right, given:
#define GIN_SEGMENT_UNMODIFIED 0 /* no action (not used in
WAL records) */

I've checked GIN code. Have no idea of how such wal record could be
generated...
The only idea I have is to add check that we're inserting valid WAL record
immediately before XLogInsert().

------
Alexander Korotkov
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

masao.fujii@gmail.com

over 9 years ago

In reply to: Alexander Korotkov (#2)

Re: GIN logging GIN_SEGMENT_UNMODIFIED actions?

On Tue, May 10, 2016 at 9:57 PM, Alexander Korotkov
<a.korotkov@postgrespro.ru> wrote:

Hi!

On Mon, May 9, 2016 at 10:46 PM, Andres Freund <andres@anarazel.de> wrote:

trying to debug something I saw the following in pg_xlogdump output:

rmgr: Gin len (rec/tot): 0/ 274, tx: 0, lsn:
1C/DF28AEB0, prev 1C/DF289858, desc: VACUUM_DATA_LEAF_PAGE 3 segments: 5
unknown action 0 ???, blkref #0: rel 1663/16384/16435 blk 310982

note the "segments: 5 unknown action 0 ???" bit. That doesn't seem
right, given:
#define GIN_SEGMENT_UNMODIFIED 0 /* no action (not used in
WAL records) */

I've checked GIN code. Have no idea of how such wal record could be
generated...

I encountered the same issue when executing the following queries and
running pg_xlogdump.

CREATE EXTENSION pg_trgm;
CREATE TABLE test (col1 TEXT);
CREATE INDEX testidx ON test USING gin (col1 gin_trgm_ops) WITH
(fastupdate = off);
INSERT INTO test SELECT 'ABCDE' FROM generate_series(1,10000);
DELETE FROM test;
VACUUM test;

$ pg_xlogdump data/pg_xlog/000000010000000000000004 | grep Gin | grep action
rmgr: Gin len (rec/tot): 0/ 88, tx: 0, lsn:
0/04A4B468, prev 0/04A4B438, desc: VACUUM_DATA_LEAF_PAGE 1663
segments: 0 unknown action 0 ???, blkref #0: rel 1663/13286/16455 blk
11
rmgr: Gin len (rec/tot): 0/ 78, tx: 0, lsn:
0/04A4B4C0, prev 0/04A4B468, desc: VACUUM_DATA_LEAF_PAGE 1663
segments: 0 unknown action 0 ???, blkref #0: rel 1663/13286/16455 blk
10
rmgr: Gin len (rec/tot): 0/ 88, tx: 0, lsn:
0/04A4B510, prev 0/04A4B4C0, desc: VACUUM_DATA_LEAF_PAGE 1663
segments: 0 unknown action 0 ???, blkref #0: rel 1663/13286/16455 blk
13
rmgr: Gin len (rec/tot): 0/ 78, tx: 0, lsn:
0/04A4B568, prev 0/04A4B510, desc: VACUUM_DATA_LEAF_PAGE 1663
segments: 0 unknown action 0 ???, blkref #0: rel 1663/13286/16455 blk
12
rmgr: Gin len (rec/tot): 0/ 88, tx: 0, lsn:
0/04A4B5B8, prev 0/04A4B568, desc: VACUUM_DATA_LEAF_PAGE 1663
segments: 0 unknown action 0 ???, blkref #0: rel 1663/13286/16455 blk
15
rmgr: Gin len (rec/tot): 0/ 78, tx: 0, lsn:
0/04A4B610, prev 0/04A4B5B8, desc: VACUUM_DATA_LEAF_PAGE 1663
segments: 0 unknown action 0 ???, blkref #0: rel 1663/13286/16455 blk
14
rmgr: Gin len (rec/tot): 0/ 88, tx: 0, lsn:
0/04A4B660, prev 0/04A4B610, desc: VACUUM_DATA_LEAF_PAGE 1663
segments: 0 unknown action 0 ???, blkref #0: rel 1663/13286/16455 blk
17
rmgr: Gin len (rec/tot): 0/ 78, tx: 0, lsn:
0/04A4B6B8, prev 0/04A4B660, desc: VACUUM_DATA_LEAF_PAGE 1663
segments: 0 unknown action 0 ???, blkref #0: rel 1663/13286/16455 blk
16
rmgr: Gin len (rec/tot): 0/ 88, tx: 0, lsn:
0/04A4B708, prev 0/04A4B6B8, desc: VACUUM_DATA_LEAF_PAGE 1663
segments: 0 unknown action 0 ???, blkref #0: rel 1663/13286/16455 blk
19
rmgr: Gin len (rec/tot): 0/ 78, tx: 0, lsn:
0/04A4B760, prev 0/04A4B708, desc: VACUUM_DATA_LEAF_PAGE 1663
segments: 0 unknown action 0 ???, blkref #0: rel 1663/13286/16455 blk
18
rmgr: Gin len (rec/tot): 0/ 88, tx: 0, lsn:
0/04A4B7B0, prev 0/04A4B760, desc: VACUUM_DATA_LEAF_PAGE 1663
segments: 0 unknown action 0 ???, blkref #0: rel 1663/13286/16455 blk
21
rmgr: Gin len (rec/tot): 0/ 78, tx: 0, lsn:
0/04A4B808, prev 0/04A4B7B0, desc: VACUUM_DATA_LEAF_PAGE 1663
segments: 0 unknown action 0 ???, blkref #0: rel 1663/13286/16455 blk
20

Regards,

--
Fujii Masao

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

masao.fujii@gmail.com

over 9 years ago

In reply to: Fujii Masao (#3)

Re: GIN logging GIN_SEGMENT_UNMODIFIED actions?

On Fri, Aug 26, 2016 at 11:35 PM, Fujii Masao <masao.fujii@gmail.com> wrote:

On Tue, May 10, 2016 at 9:57 PM, Alexander Korotkov
<a.korotkov@postgrespro.ru> wrote:

Hi!

On Mon, May 9, 2016 at 10:46 PM, Andres Freund <andres@anarazel.de> wrote:

trying to debug something I saw the following in pg_xlogdump output:

rmgr: Gin len (rec/tot): 0/ 274, tx: 0, lsn:
1C/DF28AEB0, prev 1C/DF289858, desc: VACUUM_DATA_LEAF_PAGE 3 segments: 5
unknown action 0 ???, blkref #0: rel 1663/16384/16435 blk 310982

note the "segments: 5 unknown action 0 ???" bit. That doesn't seem
right, given:
#define GIN_SEGMENT_UNMODIFIED 0 /* no action (not used in
WAL records) */

I've checked GIN code. Have no idea of how such wal record could be
generated...

I encountered the same issue when executing the following queries and
running pg_xlogdump.

ISTM that the cause of this issue is that gin_desc() uses XLogRecGetData() to
extract ginxlogVacuumDataLeafPage data from XLOG_GIN_VACUUM_DATA_LEAF_PAGE
record. Since it's registered by XLogRegisterBufData() in
ginVacuumPostingTreeLeaf(),
XLogRecGetBlockData() should be used, instead. Patch attached. Thought?

BTW, in REDO side, ginRedoVacuumDataLeafPage() uses XLogRecGetBlockData()
to extract ginxlogVacuumDataLeafPage data.

Regards,

--
Fujii Masao

tgl@sss.pgh.pa.us

over 9 years ago

In reply to: Fujii Masao (#4)

Re: GIN logging GIN_SEGMENT_UNMODIFIED actions?

Fujii Masao <masao.fujii@gmail.com> writes:

ISTM that the cause of this issue is that gin_desc() uses XLogRecGetData() to
extract ginxlogVacuumDataLeafPage data from XLOG_GIN_VACUUM_DATA_LEAF_PAGE
record. Since it's registered by XLogRegisterBufData() in
ginVacuumPostingTreeLeaf(),
XLogRecGetBlockData() should be used, instead. Patch attached. Thought?

I think we probably have more issues than that. See for example
/messages/by-id/20160826072658.15676.7628@wrigleys.postgresql.org

which clearly shows that the replay logic is seeing something wrong too:

2016-08-26 06:01:50 UTC FATAL: unexpected GIN leaf action: 0
2016-08-26 06:01:50 UTC CONTEXT: xlog redo Insert item, node:
1663/16387/33108 blkno: 6622 isdata: T isleaf: T 3 segments: 2 (add 0 items)
0 unknown action 0 ???

If it were just a matter of gin_desc() being wrong, we'd not have
gotten such a failure. (Which is not to say that gin_desc() isn't
wrong; it may well be.)

regards, tom lane

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

masao.fujii@gmail.com

over 9 years ago

In reply to: Tom Lane (#5)

Re: GIN logging GIN_SEGMENT_UNMODIFIED actions?

On Tue, Aug 30, 2016 at 3:39 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Fujii Masao <masao.fujii@gmail.com> writes:

ISTM that the cause of this issue is that gin_desc() uses XLogRecGetData() to
extract ginxlogVacuumDataLeafPage data from XLOG_GIN_VACUUM_DATA_LEAF_PAGE
record. Since it's registered by XLogRegisterBufData() in
ginVacuumPostingTreeLeaf(),
XLogRecGetBlockData() should be used, instead. Patch attached. Thought?

I think we probably have more issues than that. See for example
/messages/by-id/20160826072658.15676.7628@wrigleys.postgresql.org

which clearly shows that the replay logic is seeing something wrong too:

2016-08-26 06:01:50 UTC FATAL: unexpected GIN leaf action: 0
2016-08-26 06:01:50 UTC CONTEXT: xlog redo Insert item, node:
1663/16387/33108 blkno: 6622 isdata: T isleaf: T 3 segments: 2 (add 0 items)
0 unknown action 0 ???

If it were just a matter of gin_desc() being wrong, we'd not have
gotten such a failure. (Which is not to say that gin_desc() isn't
wrong; it may well be.)

Yeah, I got the pg_xlogdump issue while I was trying to reproduce
the above reported problem. Fixing pg_xlogdump would be helpful for
the analysis of that problem.

Regards,

--
Fujii Masao

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

masao.fujii@gmail.com

over 9 years ago

In reply to: Fujii Masao (#6)

Re: GIN logging GIN_SEGMENT_UNMODIFIED actions?

On Tue, Aug 30, 2016 at 3:13 PM, Fujii Masao <masao.fujii@gmail.com> wrote:

On Tue, Aug 30, 2016 at 3:39 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Fujii Masao <masao.fujii@gmail.com> writes:

ISTM that the cause of this issue is that gin_desc() uses XLogRecGetData() to
extract ginxlogVacuumDataLeafPage data from XLOG_GIN_VACUUM_DATA_LEAF_PAGE
record. Since it's registered by XLogRegisterBufData() in
ginVacuumPostingTreeLeaf(),
XLogRecGetBlockData() should be used, instead. Patch attached. Thought?

I think we probably have more issues than that. See for example
/messages/by-id/20160826072658.15676.7628@wrigleys.postgresql.org

which clearly shows that the replay logic is seeing something wrong too:

2016-08-26 06:01:50 UTC FATAL: unexpected GIN leaf action: 0
2016-08-26 06:01:50 UTC CONTEXT: xlog redo Insert item, node:
1663/16387/33108 blkno: 6622 isdata: T isleaf: T 3 segments: 2 (add 0 items)
0 unknown action 0 ???

If it were just a matter of gin_desc() being wrong, we'd not have
gotten such a failure. (Which is not to say that gin_desc() isn't
wrong; it may well be.)

Yeah, I got the pg_xlogdump issue while I was trying to reproduce
the above reported problem. Fixing pg_xlogdump would be helpful for
the analysis of that problem.

Attached is the updated version of the patch.

I found that pg_xlogdump code for XLOG_GIN_INSERT record with
GIN_INSERT_ISLEAF flag has the same issue, i.e.,
"unknown action 0" error is thrown for that record.
The latest patch fixes this.

Regards,

--
Fujii Masao

tgl@sss.pgh.pa.us

over 9 years ago

In reply to: Fujii Masao (#7)

Re: GIN logging GIN_SEGMENT_UNMODIFIED actions?

Fujii Masao <masao.fujii@gmail.com> writes:

I found that pg_xlogdump code for XLOG_GIN_INSERT record with
GIN_INSERT_ISLEAF flag has the same issue, i.e.,
"unknown action 0" error is thrown for that record.
The latest patch fixes this.

Hmm, comparing gin_desc() to ginRedoInsert() makes me think there are more
problems there than that one. Aren't the references to "payload" wrong
in all three branches of that "if" construct, not just the middle one?
I'm inclined to suspect we should restructure this more like

{
ginxlogInsert *xlrec = (ginxlogInsert *) rec;
- char *payload = rec + sizeof(ginxlogInsert);

appendStringInfo(buf, "isdata: %c isleaf: %c",
(xlrec->flags & GIN_INSERT_ISDATA) ? 'T' : 'F',
(xlrec->flags & GIN_INSERT_ISLEAF) ? 'T' : 'F');
if (!(xlrec->flags & GIN_INSERT_ISLEAF))
{
+ char *payload = rec + sizeof(ginxlogInsert);
BlockNumber leftChildBlkno;
BlockNumber rightChildBlkno;

                    leftChildBlkno = BlockIdGetBlockNumber((BlockId) payload);
                    payload += sizeof(BlockIdData);
                    rightChildBlkno = BlockIdGetBlockNumber((BlockId) payload);
                    payload += sizeof(BlockNumber);
                    appendStringInfo(buf, " children: %u/%u",
                                     leftChildBlkno, rightChildBlkno);
                }
+               if (XLogRecHasBlockImage(record, 0))
+                   appendStringInfoString(buf, " (full page image)");
+               else
+               {
+                   char       *payload = XLogRecGetBlockData(record, 0, NULL);
+
                    if (!(xlrec->flags & GIN_INSERT_ISDATA))
                        appendStringInfo(buf, " isdelete: %c",
                        (((ginxlogInsertEntry *) payload)->isDelete) ? 'T' : 'F');
                    ... etc etc ...

regards, tom lane

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

masao.fujii@gmail.com

over 9 years ago

In reply to: Tom Lane (#8)

Re: GIN logging GIN_SEGMENT_UNMODIFIED actions?

On Wed, Aug 31, 2016 at 12:10 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Fujii Masao <masao.fujii@gmail.com> writes:

I found that pg_xlogdump code for XLOG_GIN_INSERT record with
GIN_INSERT_ISLEAF flag has the same issue, i.e.,
"unknown action 0" error is thrown for that record.
The latest patch fixes this.

Hmm, comparing gin_desc() to ginRedoInsert() makes me think there are more
problems there than that one. Aren't the references to "payload" wrong
in all three branches of that "if" construct, not just the middle one?
I'm inclined to suspect we should restructure this more like

{
ginxlogInsert *xlrec = (ginxlogInsert *) rec;
- char *payload = rec + sizeof(ginxlogInsert);

appendStringInfo(buf, "isdata: %c isleaf: %c",
(xlrec->flags & GIN_INSERT_ISDATA) ? 'T' : 'F',
(xlrec->flags & GIN_INSERT_ISLEAF) ? 'T' : 'F');
if (!(xlrec->flags & GIN_INSERT_ISLEAF))
{
+ char *payload = rec + sizeof(ginxlogInsert);
BlockNumber leftChildBlkno;
BlockNumber rightChildBlkno;
leftChildBlkno = BlockIdGetBlockNumber((BlockId) payload);
payload += sizeof(BlockIdData);
rightChildBlkno = BlockIdGetBlockNumber((BlockId) payload);
payload += sizeof(BlockNumber);
appendStringInfo(buf, " children: %u/%u",
leftChildBlkno, rightChildBlkno);
}
+               if (XLogRecHasBlockImage(record, 0))
+                   appendStringInfoString(buf, " (full page image)");
+               else
+               {
+                   char       *payload = XLogRecGetBlockData(record, 0, NULL);
+
if (!(xlrec->flags & GIN_INSERT_ISDATA))
appendStringInfo(buf, " isdelete: %c",
(((ginxlogInsertEntry *) payload)->isDelete) ? 'T' : 'F');
... etc etc ...

If we do this, the extra information like ginxlogInsertEntry->isDelete will
never be reported when the record has FPW. This is OK in terms of REDO
because REDO logic just restores FPW and doesn't see isDelete in that case.
However if gin_desc() was initially implemented to dump any information
contained in WAL record as much as possible even when it had FPW,
we should not do such restructure. Not sure the initial intention for that.

For the purpose of debugging WAL generation code, I think that it's better
to dump even information that REDO logic doesn't use.

BTW, whether the record has FPW or not is reported in other places like
XLogDumpDisplayRecord() and xlog_outrec(). So we can check whether
FPW is contained or not, from the output of pg_xlogdump, even if
gin_desc doesn't report "(full page image)".

Regards,

--
Fujii Masao

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

tgl@sss.pgh.pa.us

over 9 years ago

In reply to: Fujii Masao (#9)

Re: GIN logging GIN_SEGMENT_UNMODIFIED actions?

Fujii Masao <masao.fujii@gmail.com> writes:

On Wed, Aug 31, 2016 at 12:10 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Hmm, comparing gin_desc() to ginRedoInsert() makes me think there are more
problems there than that one. Aren't the references to "payload" wrong
in all three branches of that "if" construct, not just the middle one?

If we do this, the extra information like ginxlogInsertEntry->isDelete will
never be reported when the record has FPW.

I'm happy to have it print whatever is there, but are you sure that the
information is even there? I thought that this chunk of the WAL record
would get optimized away if we write an FPW image instead.

regards, tom lane

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

masao.fujii@gmail.com

over 9 years ago

In reply to: Tom Lane (#10)

Re: GIN logging GIN_SEGMENT_UNMODIFIED actions?

On Wed, Aug 31, 2016 at 8:32 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Fujii Masao <masao.fujii@gmail.com> writes:

On Wed, Aug 31, 2016 at 12:10 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Hmm, comparing gin_desc() to ginRedoInsert() makes me think there are more
problems there than that one. Aren't the references to "payload" wrong
in all three branches of that "if" construct, not just the middle one?

If we do this, the extra information like ginxlogInsertEntry->isDelete will
never be reported when the record has FPW.

I'm happy to have it print whatever is there, but are you sure that the
information is even there? I thought that this chunk of the WAL record
would get optimized away if we write an FPW image instead.

I was thinking that optimization logic was changed for logical decoding.
This understanding is right for heap, but not right for GIN, i.e., you're right,
such data chunk for GIN would be removed from WAL record if FPW is taken.
I applied your suggested changes into the patch. Patch attached.

Regards,

--
Fujii Masao

tgl@sss.pgh.pa.us

over 9 years ago

In reply to: Fujii Masao (#11)

Re: GIN logging GIN_SEGMENT_UNMODIFIED actions?

Fujii Masao <masao.fujii@gmail.com> writes:

I applied your suggested changes into the patch. Patch attached.

That looks pretty sane to me (but I just eyeballed it, didn't test).

One further minor improvement would be to rearrange the
XLOG_GIN_VACUUM_DATA_LEAF_PAGE case so that we don't bother calling
XLogRecGetBlockData() if there's a full-page image.

regards, tom lane

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

masao.fujii@gmail.com

over 9 years ago

In reply to: Tom Lane (#12)

Re: GIN logging GIN_SEGMENT_UNMODIFIED actions?

On Thu, Sep 1, 2016 at 10:24 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Fujii Masao <masao.fujii@gmail.com> writes:

I applied your suggested changes into the patch. Patch attached.

That looks pretty sane to me (but I just eyeballed it, didn't test).

One further minor improvement would be to rearrange the
XLOG_GIN_VACUUM_DATA_LEAF_PAGE case so that we don't bother calling
XLogRecGetBlockData() if there's a full-page image.

Pushed the patch with this improvement. Thanks!

Regards,

--
Fujii Masao

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers