cannot freeze committed xmax

Started by Konstantin Knizhnikabout 5 years ago7 messages
#1Konstantin Knizhnik
k.knizhnik@postgrespro.ru

Hi hackers,

The following error was encountered by our customers:
Them have  very huge catalog (size of pg_class relation is more than
30Gb)  blowned by temporary relations.
When them try to vacuum it, the following error is reported:

vacuum full analyze pg_catalog.pg_class;
ERROR:  cannot freeze committed xmax 596099954

The following records are present in pg_class:

(standard input)-10436009-<Data> ------
(standard input)-10436010- Item   1 -- Length:  229  Offset: 7936
(0x1f00)  Flags: NORMAL
(standard input):10436011:  XMIN: 596098791  XMAX: 596099954 CID|XVAC:
1  OID: 930322390
(standard input)-10436012-  Block Id: 108700  linp Index: 17 Attributes:
33   Size: 32
(standard input)-10436013-  infomask: 0x290b
(HASNULL|HASVARWIDTH|HASOID|XMIN_COMMITTED|XMAX_INVALID|UPDATED)
(standard input)-10436014-  t_bits: [0]: 0xff [1]: 0xff [2]: 0xff [3]: 0x7f
(standard input)-10436015-          [4]: 0x00
(standard input)-10436016-
(standard input)-10436017- Item   2 -- Length:  184  Offset: 7752
(0x1e48)  Flags: NORMAL
(standard input):10436018:  XMIN: 596098791  XMAX: 596099954 CID|XVAC:
2  OID: 930322393
(standard input)-10436019-  Block Id: 108700  linp Index: 18 Attributes:
33   Size: 32
(standard input)-10436020-  infomask: 0x2909
(HASNULL|HASOID|XMIN_COMMITTED|XMAX_INVALID|UPDATED)
(standard input)-10436021-  t_bits: [0]: 0xff [1]: 0xff [2]: 0xff [3]: 0x3f
(standard input)-10436022-          [4]: 0x00
(standard input)-10436023-
(standard input)-10436024- Item   3 -- Length:  184  Offset: 7568
(0x1d90)  Flags: NORMAL
(standard input):10436025:  XMIN: 596098791  XMAX: 596099954 CID|XVAC:
3  OID: 930322395
(standard input)-10436026-  Block Id: 108700  linp Index: 19 Attributes:
33   Size: 32
(standard input)-10436027-  infomask: 0x2909
(HASNULL|HASOID|XMIN_COMMITTED|XMAX_INVALID|UPDATED)
(standard input)-10436028-  t_bits: [0]: 0xff [1]: 0xff [2]: 0xff [3]: 0x3f
(standard input)-10436029-          [4]: 0x00

This error is reported in heap_prepare_freeze_tuple:

    /*
     * Process xmax.  To thoroughly examine the current Xmax value we
need to
     * resolve a MultiXactId to its member Xids, in case some of them are
     * below the given cutoff for Xids.  In that case, those values
might need
     * freezing, too.  Also, if a multi needs freezing, we cannot
simply take
     * it out --- if there's a live updater Xid, it needs to be kept.
     *
     * Make sure to keep heap_tuple_needs_freeze in sync with this.
     */
    xid = HeapTupleGetRawXmax(htup);

    if (tuple->t_infomask & HEAP_XMAX_IS_MULTI)
    {
          ...

    }
    else if (TransactionIdIsNormal(xid))
    {

        ...

        if (TransactionIdPrecedes(xid, cutoff_xid))
        {
            /*
             * If we freeze xmax, make absolutely sure that it's not an XID
             * that is important.  (Note, a lock-only xmax can be removed
             * independent of committedness, since a committed lock
holder has
             * released the lock).
             */
            if (!HEAP_XMAX_IS_LOCKED_ONLY(tuple->t_infomask) &&
                TransactionIdDidCommit(xid))
                ereport(ERROR,
                        (errcode(ERRCODE_DATA_CORRUPTED),
                         errmsg_internal("cannot freeze committed xmax
" XID_FMT,
                                         xid)));
            freeze_xmax = true;
        }
        else
            freeze_xmax = false;
       ...
    }
    else if ((tuple->t_infomask & HEAP_XMAX_INVALID) ||
             !TransactionIdIsValid(HeapTupleGetRawXmax(htup)))
    {
        freeze_xmax = false;
        xmax_already_frozen = true;
    }

So, as you can see, in all this records HEAP_XMAX_INVALID is set, but
xmax is normal transaction id.
This is why we produce error before check for HEAP_XMAX_INVALID in the
subsequent if.
I do not know value of cutoff_xid, because do not have access to the
debugger at customer site.

I will be please or any help how to localize the source of the problem.

Looks like there is no assumption that xmax should be set to
InvalidTransactionId when HEAP_XMAX_INVALID bit is set.
And I didn't find any check  preventing cutoff_xid to be greater than
XID of some transaction which was aborted long time ago.

So is there some logical error that xmax is compared with cutoff_xid
before HEAP_XMAX_INVALID bit is checked?
Otherwise, where this constraint most likely be violated?

It is PG 11.7 version of Postgres.
Thanks is advance,

--
Konstantin Knizhnik
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

#2Mark Dilger
mark.dilger@enterprisedb.com
In reply to: Konstantin Knizhnik (#1)
Re: cannot freeze committed xmax

On Oct 28, 2020, at 6:44 AM, Konstantin Knizhnik <k.knizhnik@postgrespro.ru> wrote:

Looks like there is no assumption that xmax should be set to InvalidTransactionId when HEAP_XMAX_INVALID bit is set.
And I didn't find any check preventing cutoff_xid to be greater than XID of some transaction which was aborted long time ago.

Nothing in your example suggests that cutoff_xid is wrong, so I'd assume that part is probably working ok.

Your data shows that HEAP_XMAX_INVALID and HEAP_UPDATED flags are both set. That should only happen if the updating transaction aborted. But the query of clog is saying that it committed. Something is wrong with that. How did the hint bits get set to HEAP_XMAX_INVALID if the transaction did commit. Either some process is setting that hint bit when it shouldn't, or your clog is corrupted and returning a bogus answer about the xmax having been committed. Either way, you've got corruption.

Your question "preventing cutoff_xid to be greater than XID of some transaction which was aborted long time ago" seems to be ignoring that TransactionIdDidCommit(xid) is returning true, suggesting the transaction did not abort.


Mark Dilger
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

#3Konstantin Knizhnik
k.knizhnik@postgrespro.ru
In reply to: Mark Dilger (#2)
Re: cannot freeze committed xmax

On 28.10.2020 18:25, Mark Dilger wrote:

On Oct 28, 2020, at 6:44 AM, Konstantin Knizhnik <k.knizhnik@postgrespro.ru> wrote:

Looks like there is no assumption that xmax should be set to InvalidTransactionId when HEAP_XMAX_INVALID bit is set.
And I didn't find any check preventing cutoff_xid to be greater than XID of some transaction which was aborted long time ago.

Nothing in your example suggests that cutoff_xid is wrong, so I'd assume that part is probably working ok.

Your data shows that HEAP_XMAX_INVALID and HEAP_UPDATED flags are both set. That should only happen if the updating transaction aborted. But the query of clog is saying that it committed. Something is wrong with that. How did the hint bits get set to HEAP_XMAX_INVALID if the transaction did commit. Either some process is setting that hint bit when it shouldn't, or your clog is corrupted and returning a bogus answer about the xmax having been committed. Either way, you've got corruption.

Your question "preventing cutoff_xid to be greater than XID of some transaction which was aborted long time ago" seems to be ignoring that TransactionIdDidCommit(xid) is returning true, suggesting the transaction did not abort.


Mark Dilger
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Yes, I forgot to say that transaction is treated as committed
(txid_status() returns "committed").
Also database was previously upgraded from 11.5 to 11.7
Certainly the hypothesis of CLOG corruption explains everything.
I wonder if there can be some other scenario (upgrade, multixacts,
previous freeze attempt...) which can cause such combination of flags?
I have inspected all cases where HEAP_XMAX_INVALID is set, but have not
found any one which can explain it.

--
Konstantin Knizhnik
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

#4Mark Dilger
mark.dilger@enterprisedb.com
In reply to: Konstantin Knizhnik (#3)
Re: cannot freeze committed xmax

On Oct 28, 2020, at 8:56 AM, Konstantin Knizhnik <k.knizhnik@postgrespro.ru> wrote:

On 28.10.2020 18:25, Mark Dilger wrote:

On Oct 28, 2020, at 6:44 AM, Konstantin Knizhnik <k.knizhnik@postgrespro.ru> wrote:

Looks like there is no assumption that xmax should be set to InvalidTransactionId when HEAP_XMAX_INVALID bit is set.
And I didn't find any check preventing cutoff_xid to be greater than XID of some transaction which was aborted long time ago.

Nothing in your example suggests that cutoff_xid is wrong, so I'd assume that part is probably working ok.

Your data shows that HEAP_XMAX_INVALID and HEAP_UPDATED flags are both set. That should only happen if the updating transaction aborted. But the query of clog is saying that it committed. Something is wrong with that. How did the hint bits get set to HEAP_XMAX_INVALID if the transaction did commit. Either some process is setting that hint bit when it shouldn't, or your clog is corrupted and returning a bogus answer about the xmax having been committed. Either way, you've got corruption.

Your question "preventing cutoff_xid to be greater than XID of some transaction which was aborted long time ago" seems to be ignoring that TransactionIdDidCommit(xid) is returning true, suggesting the transaction did not abort.


Mark Dilger
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Yes, I forgot to say that transaction is treated as committed (txid_status() returns "committed").
Also database was previously upgraded from 11.5 to 11.7
Certainly the hypothesis of CLOG corruption explains everything.
I wonder if there can be some other scenario (upgrade, multixacts, previous freeze attempt...) which can cause such combination of flags?
I have inspected all cases where HEAP_XMAX_INVALID is set, but have not found any one which can explain it.

The other possibillity is that this tuple is erroneously marked as HEAP_UPDATED. heap_update() sets that, which makes sense. rewrite_heap_tuple() copies the old tuple's bits to the new tuple and then does some work to resolve update chains. I guess you could look at whether that logic might leave things in an invalid state. I don't have any theory about that.

Looking at the git logs, it seems 699bf7d05c68734f800052829427c20674eb2c6b introduced the check that is ereporting, and did so along with commit 9c2f0a6c3cc8bb85b78191579760dbe9fb7814ec, which cleaned up some corruption bugs. I wonder if you're just unlucky enough to have had one of these corruptions, and now you're bumping into the ereport which is intended to prevent the corruption from spreading further?


Mark Dilger
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

#5Andrey M. Borodin
x4mmm@yandex-team.ru
In reply to: Mark Dilger (#4)
1 attachment(s)
Re: cannot freeze committed xmax

On 28 Oct 2020, at 21:21, Mark Dilger <mark.dilger@enterprisedb.com> wrote:

The other possibillity is that this tuple is erroneously marked as HEAP_UPDATED. heap_update() sets that, which makes sense. rewrite_heap_tuple() copies the old tuple's bits to the new tuple and then does some work to resolve update chains. I guess you could look at whether that logic might leave things in an invalid state. I don't have any theory about that.

Hi Mark and Konstantin!

Recently (Oct 15, 2024) I've observed this kind of problem on one of our production clusters: an old tuple version had come to life.
# select ctid,* from skipped where ctid = '(16488,13)' or ctid = '(21597,16)';
-[ RECORD 1 ]+-------------------------------------
ctid | (16488,13)
id | 1121skipped
date_created | 2023-08-16 03:31:36.306466+03
date_updated | 2023-08-16 03:31:36.306481+03
-[ RECORD 2 ]+-------------------------------------
ctid | (21597,16)
id | 1121skipped
date_created | 2023-08-16 03:31:36.306466+03
date_updated | 2024-09-06 14:10:47.926007+03

Freezing was failing with "cannot freeze committed xmax". xmax of old version == xmin of new one. I have no idea what is semantics of date_created and date_updated.
The server was running vanilla 14 regularly updated.
I suggested
delete from skipped where ctid = '(16488,13)';
and it worked, monitoring issue was resolved. I found no other problems in logs, heapcheck, amcheck etc. And found no violations of id uniqueness.

What was bothering me was that amcheck verify_heap() was quite about this table.
Let's add some checks to detect such conditions?
PFA the patch doing so.

Thanks!

Best regards, Andrey Borodin.

Attachments:

0001-Detect-hintbit-contradictions-to-commit-log.patchapplication/octet-stream; name=0001-Detect-hintbit-contradictions-to-commit-log.patch; x-unix-mode=0644Download
From 4098435b1805d8ab0b59990bdde8a25f0560b2b5 Mon Sep 17 00:00:00 2001
From: Andrey Borodin <amborodin@acm.org>
Date: Wed, 20 Nov 2024 17:03:19 +0500
Subject: [PATCH] Detect hintbit contradictions to commit log

Currently, under some corruption stated freezing can emit ereports
like "cannot freeze committed xmax". This change helps to detect such
conditions.
---
 contrib/amcheck/verify_heapam.c | 14 ++++++++++++++
 1 file changed, 14 insertions(+)

diff --git a/contrib/amcheck/verify_heapam.c b/contrib/amcheck/verify_heapam.c
index 9c74daacee..dc037d774a 100644
--- a/contrib/amcheck/verify_heapam.c
+++ b/contrib/amcheck/verify_heapam.c
@@ -1224,6 +1224,12 @@ check_tuple_visibility(HeapCheckContext *ctx, bool *xmin_commit_status_ok,
 			return false;
 		}
 	}
+	else if (xmin_status != XID_COMMITTED)
+	{
+		report_corruption(ctx,
+				psprintf("uncommitted xmin %u while tuple has HEAP_XMIN_COMMITTED flag",
+				xmin));
+	}
 
 	/*
 	 * Okay, the inserter committed, so it was good at some point.  Now what
@@ -1285,6 +1291,14 @@ check_tuple_visibility(HeapCheckContext *ctx, bool *xmin_commit_status_ok,
 		 * toast cannot be vacuumed out from under us.
 		 */
 		ctx->tuple_could_be_pruned = false;
+
+		if (xmax_status == XID_COMMITTED && (tuphdr->t_infomask & HEAP_UPDATED))
+		{
+			report_corruption(ctx,
+					psprintf("committed xmax %u while tuple has HEAP_XMAX_INVALID and HEAP_UPDATED flags",
+					xmax));
+		}
+
 		return true;
 	}
 
-- 
2.39.5 (Apple Git-154)

#6Andrey M. Borodin
x4mmm@yandex-team.ru
In reply to: Andrey M. Borodin (#5)
Re: cannot freeze committed xmax

On 20 Nov 2024, at 15:58, Andrey M. Borodin <x4mmm@yandex-team.ru> wrote:

PFA the patch doing so.

Ugh. The patch is simply dysfunctional, sorry. xmax_status is being checked uninitiated.
But, well, it highlights the idea: make verify_heapam() aware of such corruptions.
What do you think?

Best regards, Andrey Borodin.

#7Mark Dilger
mark.dilger@enterprisedb.com
In reply to: Andrey M. Borodin (#6)
Re: cannot freeze committed xmax

On Nov 20, 2024, at 6:39 AM, Andrey M. Borodin <x4mmm@yandex-team.ru> wrote:

On 20 Nov 2024, at 15:58, Andrey M. Borodin <x4mmm@yandex-team.ru> wrote:

PFA the patch doing so.

Ugh. The patch is simply dysfunctional, sorry. xmax_status is being checked uninitiated.
But, well, it highlights the idea: make verify_heapam() aware of such corruptions.
What do you think?

I like the idea of increasing the corruption checking coverage. The worry with these patches is that we'll overlook some legitimate use case of the status bits and call it corruption when it isn't. Indeed, that appears to be the case with this patch, assuming I initialized the xmax_status field in the way you had in mind, and that applying it to REL_17_STABLE is ok. (Maybe this would work differently on HEAD?)

+               get_xid_status(xmax, ctx, &xmax_status);
+               if (xmax_status == XID_COMMITTED && (tuphdr->t_infomask & HEAP_UPDATED))
+               {
+                       report_corruption(ctx,
+                                       psprintf("committed xmax %u while tuple has HEAP_XMAX_INVALID and HEAP_UPDATED flags",
+                                       xmax));
+               }

That results in TAP test failures on a uncorrupted but frozen table:

# +++ tap check in contrib/amcheck +++
t/001_verify_heapam.pl ......... 74/?
# Failed test 'all-frozen not corrupted table'
# at t/001_verify_heapam.pl line 53.
# got: '30|117||committed xmax 2 while tuple has HEAP_XMAX_INVALID and HEAP_UPDATED flags'
# expected: ''
t/001_verify_heapam.pl ......... 257/? # Looks like you failed 1 test of 272.
t/001_verify_heapam.pl ......... Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/272 subtests

The first part of your patch which checks the xmin_status seems ok at first glance.


Mark Dilger
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company