Обсуждение: Problem with PITR Past Particular WAL File

Craig McElroy <craig.mcelroy@contegix.com> writes:
>    Now, if I include one more WAL file in the recovery, ...

>> Oct 23 22:22:29 db01b postgres[92]: [ID 748848 local0.info]
>> [5706-1] LOG:  archive recovery complete
>> Oct 23 22:27:06 db01b postgres[91]: [ID 748848 local0.info] [1-1]
>> LOG:  startup process (PID 92) was terminated by signal 11

Can you get a stack trace from the core dump reported here?
It looks like a bug in post-replay cleanup, but there's not
enough detail to say more.

            regards, tom lane

Tom:
  Certainly, how can that be obtained?

Cheers,
-craig

---
Craig McElroy
Contegix
Beyond Managed Hosting(r) for Your Enterprise

On Oct 24, 2007, at 7:12 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

> Craig McElroy <craig.mcelroy@contegix.com> writes:
>>  Now, if I include one more WAL file in the recovery, ...
>
>>> Oct 23 22:22:29 db01b postgres[92]: [ID 748848 local0.info]
>>> [5706-1] LOG:  archive recovery complete
>>> Oct 23 22:27:06 db01b postgres[91]: [ID 748848 local0.info] [1-1]
>>> LOG:  startup process (PID 92) was terminated by signal 11
>
> Can you get a stack trace from the core dump reported here?
> It looks like a bug in post-replay cleanup, but there's not
> enough detail to say more.
>
>           regards, tom lane
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 1: if posting/reading through Usenet, please send an appropriate
>      subscribe-nomail command to majordomo@postgresql.org so that your
>      message can get through to the mailing list cleanly

Craig McElroy <craig.mcelroy@contegix.com> writes:
>> Can you get a stack trace from the core dump reported here?

>   Certainly, how can that be obtained?

$ gdb /path/to/postgres-executable /path/to/core-file
gdb> bt
gdb> quit

If you don't find a corefile in $PGDATA (or wherever your system puts
core files) then you probably need to restart the postmaster with
"ulimit -c unlimited" to allow producing a core.

If the "bt" output is just numbers and no symbols then it won't be of
any use; in that case you'll need to find or build non-stripped Postgres
executables.

            regards, tom lane

Craig McElroy wrote:
> Tom:
>   Thanks for your help on this.  The trace details are as follows:
>
> Core was generated by `/usr/local/pgsql/bin/postgres -D /pgdata01/data'.
> Program terminated with signal 11, Segmentation fault.
>
> #0  0x080b8ee0 in entrySplitPage ()
> #1  0x080baccf in ginInsertValue ()
> #2  0x080b81b7 in gin_xlog_cleanup ()

So it looks like a bug in the gin xlog code, which makes sense because
it's new.

Can you please execute in that gdb session the command "bt full" and
send the output?

--
Alvaro Herrera                        http://www.advogato.org/person/alvherre
"La realidad se compone de muchos sueños, todos ellos diferentes,
pero en cierto aspecto, parecidos..." (Yo, hablando de sueños eróticos)

Craig McElroy wrote:
> Alvaro:
>   I just tried, but I only get "No symbol table info available." after each
> line of the trace.

Well, we have two possibilities:

1. you send us a complete, reproducible test case,

2. you recompile with debugging enabled (configure --enable-debug) to
get a more useful backtrace

--
Alvaro Herrera                                http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.

Craig McElroy <craig.mcelroy@contegix.com> writes:
> Core was generated by `/usr/local/pgsql/bin/postgres -D /pgdata01/data'.
> Program terminated with signal 11, Segmentation fault.

> #0  0x080b8ee0 in entrySplitPage ()
> #1  0x080baccf in ginInsertValue ()
> #2  0x080b81b7 in gin_xlog_cleanup ()
> #3  0x080af4ce in StartupXLOG ()
> #4  0x080c04ca in BootstrapMain ()
> #5  0x08186b2f in StartChildProcess ()
> #6  0x081889eb in PostmasterMain ()
> #7  0x0814ee9e in main ()

Hm, I wonder if this is explained by a bug already fixed in 8.2.5:

2007-06-04 11:59  teodor

    * src/backend/access/gin/: gindatapage.c, ginentrypage.c, ginget.c,
    ginvacuum.c, ginxlog.c (REL8_2_STABLE): Fix bundle bugs of GIN: -
    Fix possible deadlock between UPDATE and VACUUM queries. Bug never
    was   observed in 8.2, but it still exist there. HEAD is more
    sensitive to   bug after recent "ring" of buffer improvements.    -
    Fix WAL creation: if parent page is stored as is after split then
    incomplete split isn't removed during replay. This happens rather
    rare, only   on large tables with a lot of updates/inserts.  - Fix
    WAL replay: there was wrong test of XLR_BKP_BLOCK_* for left   page
    after deletion of page. That causes wrong rightlink field: it
    pointed   to deleted page.  - add checking of match of clearing
    incomplete split - cleanup incomplete split list after proceeding

    All of this chages doesn't change on-disk storage, so backpatch...
    But second point may be an issue for replaying logs from previous
    version.

Teodor, can you comment on whether this stack trace looks like it could
be related to that fix?

Craig, can you retry your test scenario on 8.2.5?

            regards, tom lane

>> #0  0x080b8ee0 in entrySplitPage ()
>> #1  0x080baccf in ginInsertValue ()
Corrupted stack? gin_xlog_cleanup() doesn't call ginInsertValue() directly.

>> #2  0x080b81b7 in gin_xlog_cleanup ()
>> #3  0x080af4ce in StartupXLOG ()
>> #4  0x080c04ca in BootstrapMain ()
>> #5  0x08186b2f in StartChildProcess ()
>> #6  0x081889eb in PostmasterMain ()
>> #7  0x0814ee9e in main ()

> Teodor, can you comment on whether this stack trace looks like it could
> be related to that fix?
No, I suppose. That changes was about deadlock prevention, recognize splits and
fixes in deletion of page in a posting tree. entrySplitPage() is a split of page
of indexed values.

Hmm. I suppose, I found a reason. Real backtrace should look like:
  gin_xlog_cleanup()
    ginContinueSplit()
        prepareEntryScan(,,,NULL) // makes btree.ginstate = NULL
        ginInsertValue()
            entrySplitPage() // tries to access
                     // btree->ginstate->tupdesc in
                     // 497 line


That piece of code:
     value = index_getattr(leftrightmost, FirstOffsetNumber,
btree->ginstate->tupdesc, &isnull);
     btree->entry = GinFormTuple(btree->ginstate, value, NULL, 0);
     ItemPointerSet(&(btree->entry)->t_tid, BufferGetBlockNumber(lbuf),
InvalidOffsetNumber);

It just makes new tuple with the same value and another ItemPointer. Some later
I'll make a patch which will not call index_getattr() and GinFormTuple() - now I
know how make a test suite.

--
Teodor Sigaev                                   E-mail: teodor@sigaev.ru
                                                    WWW: http://www.sigaev.ru/

Craig McElroy wrote:
> Teodor:
>   Thanks for the followup.  We will be upgrading this system to 8.2.5 in
> the next day or so and will test it on that anyways just to be sure it
> isn't related.  Let me know if there is anything else we can provide to
> help track down the bug.  We will be keeping this base backup and WAL
> files around so that we can use them for testing.
If I'm right then 8.2.5 will not help you. Attached patch should fix your
problem, but I suppose that there is an another bug. Test specially developed
for reproduce your problem discovers another issue. The diagnostic is:
FATAL:  failed to add item to index page in 1663/10819/16460
CONTEXT:  xlog redo Insert item, node: 1663/10819/16460 blkno: 514 offset: 78
nitem: 1 isdata: F isleaf F isdelete F updateBlkno:1551

Now I'm working on fixing it.
--
Teodor Sigaev                                   E-mail: teodor@sigaev.ru
                                                    WWW: http://www.sigaev.ru/
*** ./src/backend/access/gin.orig/ginentrypage.c    Thu Oct 25 22:11:56 2007
--- ./src/backend/access/gin/ginentrypage.c    Thu Oct 25 22:43:17 2007
***************
*** 404,409 ****
--- 404,434 ----
  }

  /*
+  * Returns new tuple with copied value from source tuple.
+  * New tuple will not store posting list
+  */
+ static IndexTuple
+ copyIndexTuple(IndexTuple itup, Page page)
+ {
+     IndexTuple    nitup;
+
+     if (GinPageIsLeaf(page) && !GinIsPostingTree(itup))
+     {
+         nitup = (IndexTuple) palloc(MAXALIGN(GinGetOrigSizePosting(itup)));
+         memcpy(nitup, itup, GinGetOrigSizePosting(itup));
+         nitup->t_info &= ~INDEX_SIZE_MASK;
+         nitup->t_info |= GinGetOrigSizePosting(itup);
+     }
+     else
+     {
+         nitup = (IndexTuple) palloc(MAXALIGN(IndexTupleSize(itup)));
+         memcpy(nitup, itup, IndexTupleSize(itup));
+     }
+
+     return nitup;
+ }
+
+ /*
   * Place tuple and split page, original buffer(lbuf) leaves untouched,
   * returns shadow page of lbuf filled new data.
   * Tuples are distributed between pages by equal size on its, not
***************
*** 424,431 ****
      IndexTuple    itup,
                  leftrightmost = NULL;
      static ginxlogSplit data;
-     Datum        value;
-     bool        isnull;
      Page        page;
      Page        lpage = GinPageGetCopyPage(BufferGetPage(lbuf));
      Page        rpage = BufferGetPage(rbuf);
--- 449,454 ----
***************
*** 494,502 ****
          ptr += MAXALIGN(IndexTupleSize(itup));
      }

!     value = index_getattr(leftrightmost, FirstOffsetNumber, btree->ginstate->tupdesc, &isnull);
!     btree->entry = GinFormTuple(btree->ginstate, value, NULL, 0);
      ItemPointerSet(&(btree->entry)->t_tid, BufferGetBlockNumber(lbuf), InvalidOffsetNumber);
      btree->rightblkno = BufferGetBlockNumber(rbuf);

      data.node = btree->index->rd_node;
--- 517,525 ----
          ptr += MAXALIGN(IndexTupleSize(itup));
      }

!     btree->entry = copyIndexTuple(leftrightmost, lpage);
      ItemPointerSet(&(btree->entry)->t_tid, BufferGetBlockNumber(lbuf), InvalidOffsetNumber);
+
      btree->rightblkno = BufferGetBlockNumber(rbuf);

      data.node = btree->index->rd_node;
***************
*** 533,552 ****
      Page        page = BufferGetPage(buf);

      itup = getRightMostTuple(page);
!     if (GinPageIsLeaf(page) && !GinIsPostingTree(itup))
!     {
!         nitup = (IndexTuple) palloc(MAXALIGN(GinGetOrigSizePosting(itup)));
!         memcpy(nitup, itup, GinGetOrigSizePosting(itup));
!         nitup->t_info &= ~INDEX_SIZE_MASK;
!         nitup->t_info |= GinGetOrigSizePosting(itup);
!     }
!     else
!     {
!         nitup = (IndexTuple) palloc(MAXALIGN(IndexTupleSize(itup)));
!         memcpy(nitup, itup, IndexTupleSize(itup));
!     }
!
      ItemPointerSet(&nitup->t_tid, BufferGetBlockNumber(buf), InvalidOffsetNumber);
      return nitup;
  }

--- 556,564 ----
      Page        page = BufferGetPage(buf);

      itup = getRightMostTuple(page);
!     nitup = copyIndexTuple(itup, page);
      ItemPointerSet(&nitup->t_tid, BufferGetBlockNumber(buf), InvalidOffsetNumber);
+
      return nitup;
  }

Thank you a lot for your report. Bug fixed and fixes are committed in CVS.

>   Thanks for the followup.  We will be upgrading this system to 8.2.5 in
> the next day or so and will test it on that anyways just to be sure it
> isn't related.  Let me know if there is anything else we can provide to
> help track down the bug.  We will be keeping this base backup and WAL
> files around so that we can use them for testing.
--
Teodor Sigaev                                   E-mail: teodor@sigaev.ru
                                                    WWW: http://www.sigaev.ru/

Teodor:
   That's great news.  Thanks for the followup.

Cheers,
-craig

---
Craig A. McElroy
Contegix
Beyond Managed Hosting(r) for Your Enterprise


On Oct 29, 2007, at 2:29 PM, Teodor Sigaev wrote:

> Thank you a lot for your report. Bug fixed and fixes are committed
> in CVS.
>
>>  Thanks for the followup.  We will be upgrading this system to
>> 8.2.5 in the next day or so and will test it on that anyways just
>> to be sure it isn't related.  Let me know if there is anything else
>> we can provide to help track down the bug.  We will be keeping this
>> base backup and WAL files around so that we can use them for testing.
> --
> Teodor Sigaev                                   E-mail: teodor@sigaev.ru
>                                                   WWW: http://www.sigaev.ru/
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 3: Have you checked our extensive FAQ?
>
>              http://www.postgresql.org/docs/faq