Okay ... Chris was kind enough to let me examine the WAL logs and
postmaster stderr log for his recent problem, and I believe that
I have now achieved a full understanding of what happened.  The true
bug is indeed somewhere else than slru.c, and we would not have found
it if slru.c had had less-paranoid error checking.

The WAL log shows that checkpoints were happening every five minutes
up to 2004-01-23 10:13:10, but no checkpoint completion record appears
after that.  However, the system remained up, with plenty of activity,
until 10:45:24, when it was finally taken down by a panic.  The last
transaction commit records in the WAL log are

commit: 14286807 at 2004-01-23 10:45:23 
commit: 14286811 at 2004-01-23 10:45:24 
commit: 14286814 at 2004-01-23 10:45:24 
commit: 14286824 at 2004-01-23 10:45:24 
commit: 14286825 at 2004-01-23 10:45:24 
commit: 14286836 at 2004-01-23 10:45:24 
commit: 14286838 at 2004-01-23 10:45:24 
commit: 14286850 at 2004-01-23 10:45:24 
commit: 14286851 at 2004-01-23 10:45:24 

Over in the postmaster log, the first sign of trouble is

Jan 23 10:18:07 canaveral postgres[20039]: [879-1] LOG:  could not close temporary statistics file "/usr/local/pgsql/data/global/pgstat.tmp.20035": No space left on device

and there is a steady stream of transactions failing with out-of-space
errors over the next half hour, but none of the failures are worse than
a transaction abort.  Finally we see

Jan 23 10:45:24 canaveral postgres[57237]: [17-1] ERROR:  could not access status of transaction 0
Jan 23 10:45:24 canaveral postgres[57237]: [17-2] DETAIL:  could not write to file "/usr/local/pgsql/data/pg_clog/000D" at offset 147456: No space left on device
Jan 23 10:45:24 canaveral postgres[57237]: [18-1] WARNING:  AbortTransaction and not in in-progress state
Jan 23 10:45:24 canaveral postgres[57237]: [19-1] PANIC:  could not access status of transaction 0
Jan 23 10:45:24 canaveral postgres[57237]: [19-2] DETAIL:  could not write to file "/usr/local/pgsql/data/pg_clog/000D" at offset 147456: No space left on device
Jan 23 10:45:24 canaveral postgres[20035]: [5-1] LOG:  server process (PID 57237) was terminated by signal 6
Jan 23 10:45:24 canaveral postgres[20035]: [6-1] LOG:  terminating any other active server processes

after which the postmaster's recovery attempts fail, as Chris already
detailed.  (Note: the reference to "transaction 0" is not significant;
that just happens because SimpleLruWritePage doesn't have a specific
transaction number to blame its write failures on.)

Those are the observed facts, what's the interpretation?  I think it
shows that Postgres is pretty darn robust, actually.  We were able to
stay up and do useful work for quite a long time with zero free space;
what's more, we lost no transactions that were successfully committed.
The data was successfully stored in preallocated WAL space.  (If things
had gone on this way for awhile longer, we would have panicked for lack
of WAL space, but Chris was actually not anywhere near there; he'd only
filled about two WAL segments in the half hour of operations.)  Note
also that checkpoints were attempted several times during that interval,
and they all failed gracefully --- no panic, no incorrect WAL update.

But why did this panic finally happen?  The key observation is that
the first nonexistent page of pg_clog was the page beginning with
transaction 14286848.  Neither this xact nor the following one have any
commit or abort record in WAL, but we do see entries for 14286850 and
14286851.  It is also notable that there is no WAL entry for extension
of pg_clog to include this page --- normally a WAL entry is made each
time a page of zeroes is added to pg_clog.  My interpretation of the
sequence of events is:

Transaction 14286848 started, and since it was the first for its pg_clog
page, it tried to do ZeroCLOGPage() for that page (see ExtendCLOG).  This
required making room in the in-memory clog buffers, which required
dumping one of the previously-buffered clog pages, which failed for lack
of disk space, leading to this log entry:

Jan 23 10:45:24 canaveral postgres[57237]: [17-1] ERROR:  could not access status of transaction 0
Jan 23 10:45:24 canaveral postgres[57237]: [17-2] DETAIL:  could not write to file "/usr/local/pgsql/data/pg_clog/000D" at offset 147456: No space left on device
Jan 23 10:45:24 canaveral postgres[57237]: [18-1] WARNING:  AbortTransaction and not in in-progress state

(Note: page offset 147456 is the page two before the one containing xid
14286848.  This page had been allocated in clog buffers but never yet
successfully written to disk.  Ditto for the page in between.)  The next
thing that happened was that transaction xids 14286849 and 14286850 were
assigned (ie, those xacts started), and then 14286850 tried to commit.
This again led to a failed attempt to write out a clog page, but this
time the error was promoted to a panic because it happened inside the
transaction commit critical section:

Jan 23 10:45:24 canaveral postgres[57237]: [19-1] PANIC:  could not access status of transaction 0
Jan 23 10:45:24 canaveral postgres[57237]: [19-2] DETAIL:  could not write to file "/usr/local/pgsql/data/pg_clog/000D" at offset 147456: No space left on device

The final commit record in WAL, from xid 14286851, must have come from a
different backend that was able to get that far in its commit sequence
before hearing the all-hands-abandon-ship signal from the postmaster.
(AFAICT it was just chance that the same backend process was responsible
for both 14286848 and 14286850.  Presumably 14286849 was taken out by
yet another backend that hadn't gotten as far as trying to commit.)

After Chris had freed some disk space, WAL replay was able to create the
clog page at offset 147456, because there was a clog-extension WAL entry
for it within the WAL entries since the last successful checkpoint.  It
was also able to correctly fill that page using the transaction commit
data in WAL.  Likewise for the page after that.  But when it got to the
commit record for 14286850, the error checks in slru.c barfed because
there was no such page, thus exposing the real problem: there wasn't a
clog extension WAL record for that page.

In short, the bug is in GetNewTransactionId(), which shorn of extraneous
details looks like

    LWLockAcquire(XidGenLock, LW_EXCLUSIVE);

    xid = ShmemVariableCache->nextXid;

    TransactionIdAdvance(ShmemVariableCache->nextXid);

    ExtendCLOG(xid);

    LWLockRelease(XidGenLock);

and the correct fix is to swap the order of the TransactionIdAdvance and
ExtendCLOG lines.  Because these lines are out of order, a failure
occurring down inside ExtendCLOG leaves the shared-memory copy of
nextXid already advanced, and so subsequent transactions coming through
this bit of code will see that they are not the first transaction in
their page and conclude that they need not do any work to extend clog.
With the operations in the correct order, ExtendCLOG failure will leave
the counter unchanged, so every subsequent transaction will try to do
ExtendCLOG and will fail until some disk space becomes available.  (Note
that this code is *not* in a critical section, indeed it's not yet
inside a transaction at all, and so failure here does not mean a panic.)

If you like you can think of the real problem with this code as being
that it violates the basic WAL rule: "make a WAL entry before making
permanent changes".  nextXid isn't on disk, but it's persistent
shared-memory state, and it mustn't be updated until any WAL entries
associated with that action have been made.

Any questions?

			regards, tom lane

Mon, 26 Jan 2004 00:00:37 -0500
Tom Lane <tgl@sss.pgh.pa.us>
Re: Disaster! 
Tom,

I don't know if the 'canaveral' prompt had anything to do with it 
(maybe it was just the subject line), but I kept thinking of shuttle 
disasters, o-rings, and plane crashes reading through this. I won't 
claim to understand everything in huge detail, but from this newbie's 
point of view, well explained! I enjoyed reading it.

Ever thought of working for the NTSB? :)

Michael Glaesemann
grzm myrealbox com


Mon, 26 Jan 2004 14:52:58 +0900
Michael Glaesemann <grzm@myrealbox.com>
Re: Disaster! 
Awesome Tom :)

I'm glad I happened to have all the data required on hand to fully analyze
the problem.   Let's hope this make this failure condition go away for all
future postgresql users :)

Chris

On Mon, 26 Jan 2004, Tom Lane wrote:

> Okay ... Chris was kind enough to let me examine the WAL logs and
> postmaster stderr log for his recent problem, and I believe that
> I have now achieved a full understanding of what happened.  The true
> bug is indeed somewhere else than slru.c, and we would not have found
> it if slru.c had had less-paranoid error checking.

<snip>


Mon, 26 Jan 2004 17:04:09 +0800 (WST)
Christopher Kings-Lynne <chriskl@familyhealth.com.au>
Re: Disaster! 

Excellent analysis.  Thanks.  Are there any other cases like this?

---------------------------------------------------------------------------

Tom Lane wrote:
> Okay ... Chris was kind enough to let me examine the WAL logs and
> postmaster stderr log for his recent problem, and I believe that
> I have now achieved a full understanding of what happened.  The true
> bug is indeed somewhere else than slru.c, and we would not have found
> it if slru.c had had less-paranoid error checking.
> 
> The WAL log shows that checkpoints were happening every five minutes
> up to 2004-01-23 10:13:10, but no checkpoint completion record appears
> after that.  However, the system remained up, with plenty of activity,
> until 10:45:24, when it was finally taken down by a panic.  The last
> transaction commit records in the WAL log are
> 
> commit: 14286807 at 2004-01-23 10:45:23 
> commit: 14286811 at 2004-01-23 10:45:24 
> commit: 14286814 at 2004-01-23 10:45:24 
> commit: 14286824 at 2004-01-23 10:45:24 
> commit: 14286825 at 2004-01-23 10:45:24 
> commit: 14286836 at 2004-01-23 10:45:24 
> commit: 14286838 at 2004-01-23 10:45:24 
> commit: 14286850 at 2004-01-23 10:45:24 
> commit: 14286851 at 2004-01-23 10:45:24 
> 
> Over in the postmaster log, the first sign of trouble is
> 
> Jan 23 10:18:07 canaveral postgres[20039]: [879-1] LOG:  could not close temporary statistics file "/usr/local/pgsql/data/global/pgstat.tmp.20035": No space left on device
> 
> and there is a steady stream of transactions failing with out-of-space
> errors over the next half hour, but none of the failures are worse than
> a transaction abort.  Finally we see
> 
> Jan 23 10:45:24 canaveral postgres[57237]: [17-1] ERROR:  could not access status of transaction 0
> Jan 23 10:45:24 canaveral postgres[57237]: [17-2] DETAIL:  could not write to file "/usr/local/pgsql/data/pg_clog/000D" at offset 147456: No space left on device
> Jan 23 10:45:24 canaveral postgres[57237]: [18-1] WARNING:  AbortTransaction and not in in-progress state
> Jan 23 10:45:24 canaveral postgres[57237]: [19-1] PANIC:  could not access status of transaction 0
> Jan 23 10:45:24 canaveral postgres[57237]: [19-2] DETAIL:  could not write to file "/usr/local/pgsql/data/pg_clog/000D" at offset 147456: No space left on device
> Jan 23 10:45:24 canaveral postgres[20035]: [5-1] LOG:  server process (PID 57237) was terminated by signal 6
> Jan 23 10:45:24 canaveral postgres[20035]: [6-1] LOG:  terminating any other active server processes
> 
> after which the postmaster's recovery attempts fail, as Chris already
> detailed.  (Note: the reference to "transaction 0" is not significant;
> that just happens because SimpleLruWritePage doesn't have a specific
> transaction number to blame its write failures on.)
> 
> Those are the observed facts, what's the interpretation?  I think it
> shows that Postgres is pretty darn robust, actually.  We were able to
> stay up and do useful work for quite a long time with zero free space;
> what's more, we lost no transactions that were successfully committed.
> The data was successfully stored in preallocated WAL space.  (If things
> had gone on this way for awhile longer, we would have panicked for lack
> of WAL space, but Chris was actually not anywhere near there; he'd only
> filled about two WAL segments in the half hour of operations.)  Note
> also that checkpoints were attempted several times during that interval,
> and they all failed gracefully --- no panic, no incorrect WAL update.
> 
> But why did this panic finally happen?  The key observation is that
> the first nonexistent page of pg_clog was the page beginning with
> transaction 14286848.  Neither this xact nor the following one have any
> commit or abort record in WAL, but we do see entries for 14286850 and
> 14286851.  It is also notable that there is no WAL entry for extension
> of pg_clog to include this page --- normally a WAL entry is made each
> time a page of zeroes is added to pg_clog.  My interpretation of the
> sequence of events is:
> 
> Transaction 14286848 started, and since it was the first for its pg_clog
> page, it tried to do ZeroCLOGPage() for that page (see ExtendCLOG).  This
> required making room in the in-memory clog buffers, which required
> dumping one of the previously-buffered clog pages, which failed for lack
> of disk space, leading to this log entry:
> 
> Jan 23 10:45:24 canaveral postgres[57237]: [17-1] ERROR:  could not access status of transaction 0
> Jan 23 10:45:24 canaveral postgres[57237]: [17-2] DETAIL:  could not write to file "/usr/local/pgsql/data/pg_clog/000D" at offset 147456: No space left on device
> Jan 23 10:45:24 canaveral postgres[57237]: [18-1] WARNING:  AbortTransaction and not in in-progress state
> 
> (Note: page offset 147456 is the page two before the one containing xid
> 14286848.  This page had been allocated in clog buffers but never yet
> successfully written to disk.  Ditto for the page in between.)  The next
> thing that happened was that transaction xids 14286849 and 14286850 were
> assigned (ie, those xacts started), and then 14286850 tried to commit.
> This again led to a failed attempt to write out a clog page, but this
> time the error was promoted to a panic because it happened inside the
> transaction commit critical section:
> 
> Jan 23 10:45:24 canaveral postgres[57237]: [19-1] PANIC:  could not access status of transaction 0
> Jan 23 10:45:24 canaveral postgres[57237]: [19-2] DETAIL:  could not write to file "/usr/local/pgsql/data/pg_clog/000D" at offset 147456: No space left on device
> 
> The final commit record in WAL, from xid 14286851, must have come from a
> different backend that was able to get that far in its commit sequence
> before hearing the all-hands-abandon-ship signal from the postmaster.
> (AFAICT it was just chance that the same backend process was responsible
> for both 14286848 and 14286850.  Presumably 14286849 was taken out by
> yet another backend that hadn't gotten as far as trying to commit.)
> 
> After Chris had freed some disk space, WAL replay was able to create the
> clog page at offset 147456, because there was a clog-extension WAL entry
> for it within the WAL entries since the last successful checkpoint.  It
> was also able to correctly fill that page using the transaction commit
> data in WAL.  Likewise for the page after that.  But when it got to the
> commit record for 14286850, the error checks in slru.c barfed because
> there was no such page, thus exposing the real problem: there wasn't a
> clog extension WAL record for that page.
> 
> In short, the bug is in GetNewTransactionId(), which shorn of extraneous
> details looks like
> 
>     LWLockAcquire(XidGenLock, LW_EXCLUSIVE);
> 
>     xid = ShmemVariableCache->nextXid;
> 
>     TransactionIdAdvance(ShmemVariableCache->nextXid);
> 
>     ExtendCLOG(xid);
> 
>     LWLockRelease(XidGenLock);
> 
> and the correct fix is to swap the order of the TransactionIdAdvance and
> ExtendCLOG lines.  Because these lines are out of order, a failure
> occurring down inside ExtendCLOG leaves the shared-memory copy of
> nextXid already advanced, and so subsequent transactions coming through
> this bit of code will see that they are not the first transaction in
> their page and conclude that they need not do any work to extend clog.
> With the operations in the correct order, ExtendCLOG failure will leave
> the counter unchanged, so every subsequent transaction will try to do
> ExtendCLOG and will fail until some disk space becomes available.  (Note
> that this code is *not* in a critical section, indeed it's not yet
> inside a transaction at all, and so failure here does not mean a panic.)
> 
> If you like you can think of the real problem with this code as being
> that it violates the basic WAL rule: "make a WAL entry before making
> permanent changes".  nextXid isn't on disk, but it's persistent
> shared-memory state, and it mustn't be updated until any WAL entries
> associated with that action have been made.
> 
> Any questions?
> 
> 			regards, tom lane
> 
> ---------------------------(end of broadcast)---------------------------
> TIP 9: the planner will ignore your desire to choose an index scan if your
>       joining column's datatypes do not match
> 

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073

Mon, 26 Jan 2004 13:23:09 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: Disaster!
On Mon, Jan 26, 2004 at 02:52:58PM +0900, Michael Glaesemann wrote:

> I don't know if the 'canaveral' prompt had anything to do with it 
> (maybe it was just the subject line), but I kept thinking of shuttle 
> disasters, o-rings, and plane crashes reading through this. I won't 
> claim to understand everything in huge detail, but from this newbie's 
> point of view, well explained! I enjoyed reading it.

Just for the record, the Canaveral you are thinking about is derived
from the spanish word "Caï¿½averal", which is a place where "caï¿½as" grow
(canes or stems, according to my dictionary -- some sort of vegetal
living form anyway).  I suppose Cape Kennedy was filled with those
plants and that's what the name comes from.

I dunno if Chris' machine's name derives from that or not; Merriam
Webster does not list any other meaning for that word.

-- 
Alvaro Herrera (<alvherre[a]dcc.uchile.cl>)
"The Gord often wonders why people threaten never to come back after they've
been told never to return" (www.actsofgord.com)

Mon, 26 Jan 2004 15:42:19 -0300
Alvaro Herrera <alvherre@dcc.uchile.cl>
Re: Disaster!
> Just for the record, the Canaveral you are thinking about is derived
> from the spanish word "Caï¿½averal", which is a place where "caï¿½as" grow
> (canes or stems, according to my dictionary -- some sort of vegetal
> living form anyway).  I suppose Cape Kennedy was filled with those
> plants and that's what the name comes from.
> 
> I dunno if Chris' machine's name derives from that or not; Merriam
> Webster does not list any other meaning for that word.

All our server machines are named after launch sites/space centres.  It 
might have been a bit of a mistake, since we're starting to run out of 
names now, and the Japanese names are just too much of a mouthful :)

Chris


Tue, 27 Jan 2004 08:25:48 +0800
Christopher Kings-Lynne <chriskl@familyhealth.com.au>
Re: Disaster!
Tom Lane wrote:

> Okay ... Chris was kind enough to let me examine the WAL logs and
> postmaster stderr log for his recent problem, and I believe that
> I have now achieved a full understanding of what happened.  The true
> bug is indeed somewhere else than slru.c, and we would not have found
> it if slru.c had had less-paranoid error checking.


[SNIP]

Clap. Clap.


Regards
Gaetano Mendola




Wed, 28 Jan 2004 02:20:40 +0100
Gaetano Mendola <mendola@bigfoot.com>
Re: Disaster!