Thread: ERROR: attempted to delete invisible tuple

On Mon, Aug 17, 2009 at 4:23 PM, Bryan Murphy<bmurphy1976@gmail.com> wrote:
>  I've identified 82 bad records.  When I try to query for the records,
> we get the following:
> ERROR:  missing chunk number 0 for toast value 25692661 in pg_toast_25497233
> That's fine.  I've run into that in a few other tables and have just been
> deleting the offending records.  However, in this particular table, when I
> try and delete the records, I get the following error message:
> ERROR:  attempted to delete invisible tuple
> I'm at a loss what to do next.

Can you select xmin,xmax,ctid from the bad tuples?

And also the output of pg_resetxlog -n. I suspect you may have failed
to restore properly and have tuples from the "future" in your
database. Perhaps you're missing at the last WAL file in your
recovery?

If that's the case you may be able to get out of it with pg_resetxlog
and then cleaning up but it would be good to see the data first before
changing things.

--
greg
http://mit.edu/~gsstark/resume.pdf

Bryan Murphy <bmurphy1976@gmail.com> writes:
> Here's the xmin/xmax/ctid for three problematic records:

> prodpublic=# select xmin,xmax,ctid from items_extended where id in
> ('34537ed90d7546d78f2c172fc8eed687', '3e1d99b7124742b7aaf2f869f7637b0e',
> '499b464f141a48619c5ce0475cbe9150');
>    xmin    |   xmax    |    ctid
> -----------+-----------+------------
>  262232659 | 308810030 | (689496,3)
>  262629744 | 308810034 | (692765,1)
>  262643188 | 308810035 | (692920,9)
> (3 rows)

Hm, what's your current XID counter?  (pg_controldata would give an
approximate answer.)  I'm wondering if the xmax's are marked committed
but are in the future ...

            regards, tom lane

Bryan Murphy <bmurphy1976@gmail.com> writes:
> On Mon, Aug 17, 2009 at 12:17 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> Hm, what's your current XID counter?  (pg_controldata would give an
>> approximate answer.)  I'm wondering if the xmax's are marked committed
>> but are in the future ...

> Latest checkpoint's NextXID:          0/308829887

Hmm, well, they're in the past *now*, but by less than 20000
transactions.  You said this was a production DB so that might not
represent very much elapsed time.  Does the DELETE still fail?

            regards, tom lane

On Mon, Aug 17, 2009 at 6:17 PM, Tom Lane<tgl@sss.pgh.pa.us> wrote:
> Bryan Murphy <bmurphy1976@gmail.com> writes:
>> Here's the xmin/xmax/ctid for three problematic records:
>
>> prodpublic=# select xmin,xmax,ctid from items_extended where id in
>> ('34537ed90d7546d78f2c172fc8eed687', '3e1d99b7124742b7aaf2f869f7637b0e',
>> '499b464f141a48619c5ce0475cbe9150');
>>    xmin    |   xmax    |    ctid
>> -----------+-----------+------------
>>  262232659 | 308810030 | (689496,3)
>>  262629744 | 308810034 | (692765,1)
>>  262643188 | 308810035 | (692920,9)

Hm, perhaps I should have asked for xvac as well, as that can also
trigger an "invisible" status. You can't select xvac directly but if
you query cmin it might be possible to tell what's going on.

--
greg
http://mit.edu/~gsstark/resume.pdf

On Mon, Aug 17, 2009 at 6:17 PM, Tom Lane<tgl@sss.pgh.pa.us> wrote:
> Hm, what's your current XID counter?  (pg_controldata would give an
> approximate answer.)  I'm wondering if the xmax's are marked committed
> but are in the future ...
>

FWIW that doesn't look right. That would result in
HeapTupleBeingUpdated. The only case where it could result in
"invisible" is if it's our own xid.

Excluding the cases where our own xid is in the tuple I think the
relevant cases are either

xmin aborted or in progress (or in future)
MOVED_OFF and xvac committed
MOVED_IN and xvac aborted or is in progress (or in future)

--
greg
http://mit.edu/~gsstark/resume.pdf

Greg Stark <gsstark@mit.edu> writes:
> Excluding the cases where our own xid is in the tuple I think the
> relevant cases are either

> xmin aborted or in progress (or in future)
> MOVED_OFF and xvac committed
> MOVED_IN and xvac aborted or is in progress (or in future)

Ah.  I hadn't bothered to check the code in detail before asking about
the current XID.  Given subsequent data, it seems that current XID must
have moved past xvac while we were wondering about it.  This could mean
either corrupted xvac values, or that the crash caused current XID to go
backwards (suggesting loss of both the current pg_control and a big
chunk of WAL).  Since multiple tuples on different pages were involved,
I'm inclined to believe the second theory.

            regards, tom lane

On Mon, Aug 17, 2009 at 7:59 PM, Tom Lane<tgl@sss.pgh.pa.us> wrote:
> Greg Stark <gsstark@mit.edu> writes:
>> Excluding the cases where our own xid is in the tuple I think the
>> relevant cases are either
>
>> xmin aborted or in progress (or in future)
>> MOVED_OFF and xvac committed
>> MOVED_IN and xvac aborted or is in progress (or in future)
>
> Ah.  I hadn't bothered to check the code in detail before asking about
> the current XID.  Given subsequent data, it seems that current XID must
> have moved past xvac while we were wondering about it.  This could mean
> either corrupted xvac values, or that the crash caused current XID to go
> backwards (suggesting loss of both the current pg_control and a big
> chunk of WAL).  Since multiple tuples on different pages were involved,
> I'm inclined to believe the second theory.

I would think xmin would be the fewest entities possibility but we'll
never know.

For what it's worth at EDB I dealt with another case like this and I
imagine others have too. I think it's too easy to do things in the
wrong order or miss a step and end up with these kinds of problems.

I would really like to know what happened here which caused the
problem. Do you have records of how you created the slave? When you
took the initial image, did you use a cold backup or a hot backup? Did
you use pg_start_backup()/pg_stop_backup()?

When you failed over was there anything special happening? Was it
because of a failure on the master? Was a vacuum full running?

When the slave came up do you have the log messages saying it was
starting recovery and when it was finishing recovery and starting
normal operations?

--
greg
http://mit.edu/~gsstark/resume.pdf