Message-ID: <4D710ABD.5090103@enterprisedb.com>
Date: Fri, 04 Mar 2011 17:52:29 +0200
From: Heikki Linnakangas <heikki.linnakangas@enterprisedb.com>
User-Agent: Mozilla/5.0 (X11; U; Linux x86_64; fi-FI;
	rv:1.9.1.16) Gecko/20101226 Icedove/3.0.11
MIME-Version: 1.0
To: daveg <daveg@sonic.net>
CC: PostgreSQL-development <pgsql-hackers@postgresql.org>
Subject: Re: Re: PD_ALL_VISIBLE flag was incorrectly set happend
	during repeatable vacuum
References: <AANLkTino+Gc2vvOVdzCPRRXW-N7R5=ikYMnNKT5W=mk1@mail.gmail.com>
	<AANLkTikw==USr3+4Mt+w97P3ymux-Bhn0G7Ad0ZJHbqG@mail.gmail.com>
	<4D2D6A56.9060808@enterprisedb.com>
	<20110228212832.GH26397@sonic.net>
	<1B3CCBDD-4AC6-404A-9E26-DB4CA2554228@endpoint.com>
	<AANLkTi=xq4SV6jwA7txvrbEWocyeiU6XiTG=-zVy+7Dq@mail.gmail.com>
	<AANLkTi=Ye7AoF7_uVQfPVn-ok2VOp65mi0xU3H7kCke3@mail.gmail.com>
	<20110303071208.GA4053@sonic.net>
	<4D6F4E5D.6080507@enterprisedb.com>
	<20110304090031.GE4053@sonic.net>
In-Reply-To: <20110304090031.GE4053@sonic.net>
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit

On 04.03.2011 11:00, daveg wrote:
> Thanks, I've applied both patches to one host. I'll probably have to back
> down on the debugging logging soon, as the output is pretty voluminious,
> it is producing 100MB of message log every few minutes. I'll try Merlins
> patch to get the case setting the bit first though.
>
> Anyway, here is a snippit of log with the setting and unsetting of the
> bit on one page. Unfortunately, we don't know which of a dozen odd databases
> the page belongs to, but the timestamps are so close it seems likely to be
> the same one. I've added dbname to the patch and will get that next time
> I can switch binaries.
>
> 2011-03-03 23:28:34.170 PST  2039  WARNING:  debugging: setting PD_ALL_VISIBLE in relation "pg_statistic" on page 5963 (OldestXmin 331848998)
> ...
> /cv/logs/production_03-20110303_232519.log.gz:2011-03-03 23:29:34.194 PST  2115  WARNING:  PD_ALL_VISIBLE flag was incorrectly set in relation "pg_statistic" page 5963 (OldestXmin 331677178)
> ...
> 2011-03-03 23:42:38.323 PST  2808  WARNING:  debugging: setting PD_ALL_VISIBLE in relation "pg_attribute" on page 5963 (OldestXmin 331677178)

Hmm, if these all came from the same database, then it looks OldestXmin 
has moved backwards. That would explain the warnings. First one vacuum 
determines that all the tuples are visible to everyone and sets the 
flag. Then another vacuum runs with an older OldestXmin, and determines 
that there's a tuple on the page with an xmin that is not yet visible to 
everyone, hence it thinks that the flag should not have been set yet.

Looking at the code, I don't see how that situation could arise, though. 
The value calculated by GetOldestXmin() should never move backwards. And 
GetOldestXmin() is called in lazy_vacuum_rel(), after it has acquired a 
lock on the table, which should protect from a race condition where two 
vacuums could run on the table one after another, in a way where the 
later vacuum runs with an OldestXmin calculated before the first vacuum.

Hmm, fiddling with vacuum_defer_cleanup_age on the fly could cause that, 
though. You don't do that, do you?

> Also, I've attached the relevent page image.

Thanks. There seems to be two tuples on the page, both of were HOT 
updated at some point, but now there's only one version of each left:

postgres=# SELECT lp, lp_off, lp_flags, lp_len, t_xmin, t_xmax,
   t_ctid, t_infomask, t_infomask2, t_hoff
FROM heap_page_items(loread(lo_open(29924, 262144), 8192)) WHERE 
lp_flags <> 0;
  lp | lp_off | lp_flags | lp_len |  t_xmin   | t_xmax |  t_ctid  | 
t_infomask | t_infomask2 | t_hoff
----+--------+----------+--------+-----------+--------+----------+------------+-------------+--------
   1 |   7608 |        1 |    580 | 331250141 |      0 | (5963,1) | 
  10499 |      -32747 |     32
   3 |      1 |        2 |      0 |           |        |          | 
        |             |
   4 |   7528 |        1 |     76 | 331735553 |      0 | (5963,4) | 
  10497 |      -32747 |     32
  19 |      4 |        2 |      0 |           |        |          | 
        |             |
(4 rows)

Deciphering those infomasks, the first tuple at lp 1 has these flags set:
HEAP_UPDATED | HEAP_XMAX_INVALID | HEAP_XMIN_COMMITTED | HEAP_HASNULL | 
HEAP_HASVARWIDTH

And the 2nd one at lp 4:
HEAP_UPDATED | HEAP_XMAX_INVALID | HEAP_XMIN_COMMITTED | HEAP_HASNULL

So, both of those tuples are live.

-- 
   Heikki Linnakangas
   EnterpriseDB   http://www.enterprisedb.com