Re: panic on 7.3

On Jan 20, 2006, at 6:02 PM, Tom Lane wrote:

> Rick Gigger <rick(at)alpinenetworking(dot)com> writes:
>> Postgres version 7.3.4
>
> You realize of course that that's pretty old ...
>
>> That is right now. Right after it started up it went up to 0292.
>
> So it was the latest file eh? I thought maybe you had some problem
> with a corrupted XID leading to trying to touch a clog file
> out-of-order, but that seems ruled out.
>
>>> 2006-01-20 11:50:51 PANIC: creation of file /var/lib/pgsql/data/
>>> pg_clog/0292 failed: File exists
>
> Digging in the 7.3 sources, it seems that error message could only
> have
> come from here:
>
> fd = BasicOpenFile(path, O_RDWR | PG_BINARY, S_IRUSR | S_IWUSR);
> if (fd < 0)
> {
> if (errno != ENOENT)
> elog(PANIC, "open of %s failed: %m", path);
> fd = BasicOpenFile(path, O_RDWR | O_CREAT | O_EXCL |
> PG_BINARY,
> S_IRUSR | S_IWUSR);
> if (fd < 0)
> elog(PANIC, "creation of file %s failed: %m", path);
> }
>
> AFAICS, it is simply not possible for the second open() to fail with
> that errno, *unless* someone else created the same file in the
> microseconds between the two open calls.
>
> The code doing this has a lock on the particular clog buffer it's
> trying
> to write out, so no-one else could be trying to write the same buffer;
> but now that I look at it, it's entirely legal for someone else to be
> trying to write a different clog buffer. This leads to the following
> theory:
>
> 1. The clog page that would be first in the 0292 segment got
> created in
> clog buffers, but there was no reason to write it out for awhile. (In
> normal operation, only a checkpoint would be cause to write out the
> frontmost page of clog.)
>
> 2. More than 2K transactions elapsed, so the page that would be second
> in the 0292 segment also got set up in clog buffers. (Rick, is the
> load
> on your machine such that several thousand transactions might have
> elapsed between checkpoints?) Perhaps there were even enough
> transactions so that more than two pages were dirty and pending write
> in the clog buffers, yet the file hadn't been created yet.

So what I think I'm getting killed on right now are the disk writes.
So I was thinking of changing away from the default checkpoint
settings. My load is going to continue to go up so 2000+
transactions are going to start happening pretty fast. I have lots
of disk space so I was going to increase the time between
checkpoints. Will that increase the chances of this happening again
or was this such a strange freak of nature coincidence that it can't
really even happen again. Also I've decided to upgrade all the way
to the latest 8.1 code.

> 3. Two different backends decided to try to write different clog pages
> concurrently. Probably one was writing the frontmost page because it
> was doing a checkpoint, and another needed to read in an older clog
> page
> so it had to swap out one of the other dirty buffers.
>
> 4. Kaboom.
>
> If this theory is correct, the bug has been there since the clog code
> was first written. But the conditions for having it happen are narrow
> enough that it's not too surprising we haven't seen it before.
>
> I think that a sufficient fix might just be to remove the O_EXCL flag
> from the second open() call --- ie, if someone else creates the file
> in this narrow window, it should be considered OK. Comments?
>
> regards, tom lane
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 6: explain analyze is your friend
>