Received: from maia.hub.org (maia-2.hub.org [200.46.204.251]) by mail.postgresql.org (Postfix) with ESMTP id 2BF17B5DE98 for ; Wed, 26 Oct 2011 12:44:21 -0300 (ADT) Received: from mail.postgresql.org ([200.46.204.86]) by maia.hub.org (mx1.hub.org [200.46.204.251]) (amavisd-maia, port 10024) with ESMTP id 21757-01-4 for ; Wed, 26 Oct 2011 15:44:15 +0000 (UTC) X-Greylist: from auto-whitelisted by SQLgrey-1.8.0-rc2 Received: from master.phlo.org (master.phlo.org [213.47.213.180]) by mail.postgresql.org (Postfix) with ESMTP id 6CAFDB5DE05 for ; Wed, 26 Oct 2011 12:43:55 -0300 (ADT) Received: (qmail 11195 invoked by uid 0); 26 Oct 2011 13:57:13 -0000 Received: from chello062178190165.2.15.vie.surfer.at (HELO [192.168.1.31]) (fgp@[62.178.190.165]) (envelope-sender ) by imap.phlo.org (qmail-ldap-1.03) with SMTP for ; 26 Oct 2011 13:57:12 -0000 Subject: Re: Hot Backup with rsync fails at pg_clog if under load Mime-Version: 1.0 (Apple Message framework v1084) Content-Type: text/plain; charset=us-ascii From: Florian Pflug In-Reply-To: Date: Wed, 26 Oct 2011 15:57:12 +0200 Cc: Aidan Van Dyk , Daniel Farina , Chris Redekop , PostgreSQL-development Content-Transfer-Encoding: quoted-printable Message-Id: References: <213AEFBF-479C-4F9E-B0CA-24AAB2C9F4DD@phlo.org> <1A94CE1A-C3E5-4923-B677-623D41BC273F@phlo.org> <6C3D7EDA-573E-46DC-9047-5FEB92876DA8@phlo.org> To: Simon Riggs X-Mailer: Apple Mail (2.1084) X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=-2.404 tagged_above=-5 required=5 tests=BAYES_00=-1.9, RP_MATCHES_RCVD=-0.504 X-Spam-Level: X-Archive-Number: 201110/1386 X-Sequence-Number: 197192 On Oct26, 2011, at 15:12 , Simon Riggs wrote: > On Wed, Oct 26, 2011 at 12:54 PM, Aidan Van Dyk = wrote: >=20 >> The read fails because their is no data at the location it's trying = to >> read from, because clog hasn't been extended yet by recovery. >=20 > You don't actually know that, though I agree it seems a reasonable > guess and was my first thought also. The actual error message also supports that theory. Here's the relevant snippet from the OP's log (Found in = CA9FD2FE.1D8D2%linas.virbalas@continuent.com) 2011-09-21 13:41:05 CEST FATAL: could not access status of transaction = 1188673 2011-09-21 13:41:05 CEST DETAIL: Could not read from file = "pg_clog/0001" at offset 32768: Success. Note that it says "Success" at the end of the second log entry. That can only happen, I think, if we're trying to read the page adjacent to the last page in the file. The seek would be successfull, and the = subsequent read() would indicate EOF by returning zero bytes. None of the calls = would set errno. If there was a real IO error, read() would set errno, and if = the page wasn't adjacent to the last page in the file, seek() would set = errno. In both cases we'd see the corresponding error messag, not "Success". > The error is very specifically referring to 22811359, which is the > nextxid from pg_control and updated by checkpoint. Where does that XID come from? The reference to that XID in the archives that I can find is in your message CA+U5nMKUUoA8kRG=3DitfsO5nZuE3x_KDJz78EaUN3_FKmq-uMJA@mail.gmail.com > 22811359 is mid-way through a clog page, so prior xids will already > have been allocated, pages extended and then those pages fsyncd before > the end of pg_start_backup(). So it shouldn't be possible for that > page to be absent from the base backup, unless the base backup was > taken without a preceding checkpoint, which seems is not the case from > the script output. Or unless the nextId we store in the checkpoint is for some reason = higher than it should be. Or unless nextId somehow gets mangled during = recovery. Or unless there's some interaction between VACUUM and CHECKPOINTS that we're overlooking... > Note that if you are correct, then the solution is to extend clog, > which Florian disagrees with as a solution. That's not what I said. As you said, the CLOG page corresponding to = nextId *should* always be accessible at the start of recovery (Unless whole = file has been removed by VACUUM, that is). So we shouldn't need to extends = CLOG. Yet the error suggest that the CLOG is, in fact, too short. What I said is that we shouldn't apply any fix (for the CLOG problem) before we = understand the reason for that apparent contradiction. Doing it nevertheless to get rid of this seems dangerous. What happens, = for example, to the CLOG state of transactions earlier than the checkpoint's nextId? There COMMIT record may very well lie before the checkpoint's = REDO pointer, so the CLOG we copied better contained their correct state. Yet = if it does, then why isn't the nextId's CLOG page accessible? best regards, Florian Pflug