Horton

Thread

Commits

  1. Make multixact error message more explicit

  2. Fix visibility check when XID is committed in CLOG but not in procarray.

  1. Fix for visibility check on 14.5 fails on tpcc with high concurrency

    Dimos Stamatakis <dimos.stamatakis@servicenow.com> — 2022-11-22T11:38:14Z

    Hi hackers,

When running tpcc on sysbench with high concurrency (96 threads, scale factor 5) we realized that a fix for visibility check (introduced in PG-14.5) causes sysbench to fail in 1 out of 70 runs.
The error is the following:

SQL error, errno = 0, state = 'XX000': new multixact has more than one updating member

And it is caused by the following statement:

UPDATE warehouse1
          SET w_ytd = w_ytd + 234
          WHERE w_id = 3;

The commit that fixes the visibility check is the following:
https://github.com/postgres/postgres/commit/e24615a0057a9932904317576cf5c4d42349b363

We reverted this commit and tpcc does not fail anymore, proving that this change is problematic.
Steps to reproduce:
1. Install sysbench
  https://github.com/akopytov/sysbench
2. Install percona sysbench TPCC
  https://github.com/Percona-Lab/sysbench-tpcc
3. Run percona sysbench -- prepare
  # sysbench-tpcc/tpcc.lua --pgsql-host=localhost --pgsql-port=5432 --pgsql-user={USER} --pgsql-password={PASSWORD} --pgsql-db=test_database --db-driver=pgsql --tables=1 --threads=96 --scale=5 --time=60 prepare
4. Run percona sysbench -- run
  # sysbench-tpcc/tpcc.lua --pgsql-host=localhost --pgsql-port=5432 --pgsql-user={USER} --pgsql-password={PASSWORD} --pgsql-db=test_database --db-driver=pgsql --tables=1 --report-interval=1 --rand-seed=1 --threads=96 --scale=5 --time=60 run

We tested on a machine with 2 NUMA nodes, 16 physical cores per node, and 2 threads per core, resulting in 64 threads total. The total memory is 376GB.
Attached please find the configuration file we used (postgresql.conf).

This commit was supposed to fix a race condition during the visibility check. Please let us know whether you are aware of this issue and if there is a quick fix.
Any input is highly appreciated.

Thanks,
Dimos
[ServiceNow]

  2. Re: Fix for visibility check on 14.5 fails on tpcc with high concurrency

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2022-11-23T09:18:13Z

    Hello Dimos

On 2022-Nov-22, Dimos Stamatakis wrote:

> When running tpcc on sysbench with high concurrency (96 threads, scale
> factor 5) we realized that a fix for visibility check (introduced in
> PG-14.5) causes sysbench to fail in 1 out of 70 runs.
> The error is the following:
> 
> SQL error, errno = 0, state = 'XX000': new multixact has more than one updating member

Ouch.

I did not remember any reports of this.  Searching I found this recent
one:
https://postgr.es/m/17518-04e368df5ad7f2ee@postgresql.org

However, the reporter there says they're using 12.10, and according to
src/tools/git_changelog the commit appeared only in 12.12:

Author: Heikki Linnakangas <heikki.linnakangas@iki.fi>
Branch: master Release: REL_15_BR [adf6d5dfb] 2022-06-27 08:21:08 +0300
Branch: REL_14_STABLE Release: REL_14_5 [e24615a00] 2022-06-27 08:24:30 +0300
Branch: REL_13_STABLE Release: REL_13_8 [7ba325fd7] 2022-06-27 08:24:35 +0300
Branch: REL_12_STABLE Release: REL_12_12 [af530898e] 2022-06-27 08:24:36 +0300
Branch: REL_11_STABLE Release: REL_11_17 [b49889f3c] 2022-06-27 08:24:37 +0300
Branch: REL_10_STABLE Release: REL_10_22 [4822b4627] 2022-06-27 08:24:38 +0300

    Fix visibility check when XID is committed in CLOG but not in procarray.
    [...]


Thinking further, one problem in tracking this down is that at this
point the multixact in question is *being created*, so we don't have a
WAL trail we could trace through.

I suggest that we could improve that elog() so that it includes the
members of the multixact in question, which could help us better
understand what is going on.

> This commit was supposed to fix a race condition during the visibility
> check. Please let us know whether you are aware of this issue and if
> there is a quick fix.

I don't think so.

-- 
Álvaro Herrera         PostgreSQL Developer  —  https://www.EnterpriseDB.com/

  3. Re: Fix for visibility check on 14.5 fails on tpcc with high concurrency

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2022-11-23T10:53:51Z

    On 2022-Nov-23, Alvaro Herrera wrote:

> I suggest that we could improve that elog() so that it includes the
> members of the multixact in question, which could help us better
> understand what is going on.

Something like the attached.  It would result in output like this:
WARNING:  new multixact has more than one updating member: 0 2[17378 (keysh), 17381 (nokeyupd)]

Then it should be possible to trace (in pg_waldump output) the
operations of each of the transactions that have any status in the
multixact that includes some form of "upd".

-- 
Álvaro Herrera               48°01'N 7°57'E  —  https://www.EnterpriseDB.com/
"Just treat us the way you want to be treated + some extra allowance
 for ignorance."                                    (Michael Brusser)

  4. Re: Fix for visibility check on 14.5 fails on tpcc with high concurrency

    Peter Geoghegan <pg@bowt.ie> — 2022-11-23T16:14:08Z

    On Wed, Nov 23, 2022 at 2:54 AM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
> Something like the attached.  It would result in output like this:
> WARNING:  new multixact has more than one updating member: 0 2[17378 (keysh), 17381 (nokeyupd)]
>
> Then it should be possible to trace (in pg_waldump output) the
> operations of each of the transactions that have any status in the
> multixact that includes some form of "upd".

That seems very useful.

Separately, I wonder if it would make sense to add additional
defensive checks to FreezeMultiXactId() for this. There is an
assertion that should catch the presence of multiple updaters in a
single Multi when it looks like we have to generate a new Multi to
carry the XID members forward (typically something we only need to do
during a VACUUM FREEZE). We could at least make that
"Assert(!TransactionIdIsValid(update_xid));" line into a defensive
"can't happen" ereport(). It couldn't hurt, at least -- we already
have a similar relfrozenxid check nearby, added after the "freeze the
dead" bug was fixed.

-- 
Peter Geoghegan

  5. Re: Fix for visibility check on 14.5 fails on tpcc with high concurrency

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2022-11-24T09:49:48Z

    On 2022-Nov-23, Peter Geoghegan wrote:

> On Wed, Nov 23, 2022 at 2:54 AM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
> > Something like the attached.  It would result in output like this:
> > WARNING:  new multixact has more than one updating member: 0 2[17378 (keysh), 17381 (nokeyupd)]
> >
> > Then it should be possible to trace (in pg_waldump output) the
> > operations of each of the transactions that have any status in the
> > multixact that includes some form of "upd".
> 
> That seems very useful.

Okay, pushed to all branches.

> Separately, I wonder if it would make sense to add additional
> defensive checks to FreezeMultiXactId() for this. There is an
> assertion that should catch the presence of multiple updaters in a
> single Multi when it looks like we have to generate a new Multi to
> carry the XID members forward (typically something we only need to do
> during a VACUUM FREEZE). We could at least make that
> "Assert(!TransactionIdIsValid(update_xid));" line into a defensive
> "can't happen" ereport(). It couldn't hurt, at least -- we already
> have a similar relfrozenxid check nearby, added after the "freeze the
> dead" bug was fixed.

Hmm, agreed.  I'll see about that separately.

-- 
Álvaro Herrera         PostgreSQL Developer  —  https://www.EnterpriseDB.com/
"I'm always right, but sometimes I'm more right than other times."
                                                  (Linus Torvalds)

  6. Re: Fix for visibility check on 14.5 fails on tpcc with high concurrency

    Dimos Stamatakis <dimos.stamatakis@servicenow.com> — 2022-11-24T14:23:33Z

    Thanks for your feedback!
I applied the patch to print more information about the error. Here’s what I got:

2022-11-23 20:33:03 UTC [638 test_database]: [5458] ERROR:  new multixact has more than one updating member: 0 2[248477 (nokeyupd), 248645 (nokeyupd)]
2022-11-23 20:33:03 UTC [638 test_database]: [5459] STATEMENT:  UPDATE warehouse1
                          SET w_ytd = w_ytd + 498
                        WHERE w_id = 5

I then inspected the WAL and I found the log records for these 2 transactions:

…
rmgr: MultiXact   len (rec/tot):     54/    54, tx:     248477, lsn: 0/66DB82A8, prev 0/66DB8260, desc: CREATE_ID 133 offset 265 nmembers 2: 248477 (nokeyupd) 248500 (keysh)
rmgr: Heap        len (rec/tot):     70/    70, tx:     248477, lsn: 0/66DB82E0, prev 0/66DB82A8, desc: HOT_UPDATE off 20 xmax 133 flags 0x20 IS_MULTI EXCL_LOCK ; new off 59 xmax 132, blkref #0: rel 1663/16384/16385 blk 422
rmgr: Transaction len (rec/tot):     34/    34, tx:     248477, lsn: 0/66DBA710, prev 0/66DBA6D0, desc: ABORT 2022-11-23 20:33:03.712298 UTC
…
rmgr: Transaction len (rec/tot):     34/    34, tx:     248645, lsn: 0/66DBB060, prev 0/66DBB020, desc: ABORT 2022-11-23 20:33:03.712388 UTC

Attached please find the relevant portion of the WAL.
Thanks for your help on this!

Dimos
[ServiceNow]


From: Alvaro Herrera <alvherre@alvh.no-ip.org>
Date: Thursday, 24. November 2022 at 10:49
To: Peter Geoghegan <pg@bowt.ie>
Cc: Dimos Stamatakis <dimos.stamatakis@servicenow.com>, pgsql-hackers@lists.postgresql.org <pgsql-hackers@lists.postgresql.org>
Subject: Re: Fix for visibility check on 14.5 fails on tpcc with high concurrency
[External Email]

On 2022-Nov-23, Peter Geoghegan wrote:

> On Wed, Nov 23, 2022 at 2:54 AM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
> > Something like the attached. It would result in output like this:
> > WARNING: new multixact has more than one updating member: 0 2[17378 (keysh), 17381 (nokeyupd)]
> >
> > Then it should be possible to trace (in pg_waldump output) the
> > operations of each of the transactions that have any status in the
> > multixact that includes some form of "upd".
>
> That seems very useful.

Okay, pushed to all branches.

> Separately, I wonder if it would make sense to add additional
> defensive checks to FreezeMultiXactId() for this. There is an
> assertion that should catch the presence of multiple updaters in a
> single Multi when it looks like we have to generate a new Multi to
> carry the XID members forward (typically something we only need to do
> during a VACUUM FREEZE). We could at least make that
> "Assert(!TransactionIdIsValid(update_xid));" line into a defensive
> "can't happen" ereport(). It couldn't hurt, at least -- we already
> have a similar relfrozenxid check nearby, added after the "freeze the
> dead" bug was fixed.

Hmm, agreed. I'll see about that separately.

--
Álvaro Herrera PostgreSQL Developer — https://www.EnterpriseDB.com/<https://www.EnterpriseDB.com>
"I'm always right, but sometimes I'm more right than other times."
(Linus Torvalds)

  7. Re: Fix for visibility check on 14.5 fails on tpcc with high concurrency

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2022-11-24T17:34:49Z

    On 2022-Nov-24, Dimos Stamatakis wrote:

> Thanks for your feedback!
> I applied the patch to print more information about the error. Here’s what I got:
> 
> 2022-11-23 20:33:03 UTC [638 test_database]: [5458] ERROR:  new multixact has more than one updating member: 0 2[248477 (nokeyupd), 248645 (nokeyupd)]
> 2022-11-23 20:33:03 UTC [638 test_database]: [5459] STATEMENT:  UPDATE warehouse1
>                           SET w_ytd = w_ytd + 498
>                         WHERE w_id = 5
> 
> I then inspected the WAL and I found the log records for these 2 transactions:
> 
> …
> rmgr: MultiXact   len (rec/tot):     54/    54, tx:     248477, lsn: 0/66DB82A8, prev 0/66DB8260, desc: CREATE_ID 133 offset 265 nmembers 2: 248477 (nokeyupd) 248500 (keysh)
> rmgr: Heap        len (rec/tot):     70/    70, tx:     248477, lsn: 0/66DB82E0, prev 0/66DB82A8, desc: HOT_UPDATE off 20 xmax 133 flags 0x20 IS_MULTI EXCL_LOCK ; new off 59 xmax 132, blkref #0: rel 1663/16384/16385 blk 422
> rmgr: Transaction len (rec/tot):     34/    34, tx:     248477, lsn: 0/66DBA710, prev 0/66DBA6D0, desc: ABORT 2022-11-23 20:33:03.712298 UTC
> …
> rmgr: Transaction len (rec/tot):     34/    34, tx:     248645, lsn: 0/66DBB060, prev 0/66DBB020, desc: ABORT 2022-11-23 20:33:03.712388 UTC

Ah, it seems clear enough: the transaction that aborted after having
updated the tuple, is still considered live when doing the second
update.  That sounds wrong.

-- 
Álvaro Herrera        Breisgau, Deutschland  —  https://www.EnterpriseDB.com/
"Puedes vivir sólo una vez, pero si lo haces bien, una vez es suficiente"

  8. Re: Fix for visibility check on 14.5 fails on tpcc with high concurrency

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2022-11-24T18:23:59Z

    On 2022-Nov-24, Alvaro Herrera wrote:

> On 2022-Nov-24, Dimos Stamatakis wrote:
> 
> > rmgr: MultiXact   len (rec/tot):     54/    54, tx:     248477, lsn: 0/66DB82A8, prev 0/66DB8260, desc: CREATE_ID 133 offset 265 nmembers 2: 248477 (nokeyupd) 248500 (keysh)
> > rmgr: Heap        len (rec/tot):     70/    70, tx:     248477, lsn: 0/66DB82E0, prev 0/66DB82A8, desc: HOT_UPDATE off 20 xmax 133 flags 0x20 IS_MULTI EXCL_LOCK ; new off 59 xmax 132, blkref #0: rel 1663/16384/16385 blk 422
> > rmgr: Transaction len (rec/tot):     34/    34, tx:     248477, lsn: 0/66DBA710, prev 0/66DBA6D0, desc: ABORT 2022-11-23 20:33:03.712298 UTC
> > …
> > rmgr: Transaction len (rec/tot):     34/    34, tx:     248645, lsn: 0/66DBB060, prev 0/66DBB020, desc: ABORT 2022-11-23 20:33:03.712388 UTC
> 
> Ah, it seems clear enough: the transaction that aborted after having
> updated the tuple, is still considered live when doing the second
> update.  That sounds wrong.

Hmm, if a transaction is aborted but its Xid is after latestCompletedXid,
it would be reported as still running.  AFAICS that is only modified
with ProcArrayLock held in exclusive mode, and only read with it held in
share mode, so this should be safe.

I can see nothing else ATM.

-- 
Álvaro Herrera        Breisgau, Deutschland  —  https://www.EnterpriseDB.com/
"I must say, I am absolutely impressed with what pgsql's implementation of
VALUES allows me to do. It's kind of ridiculous how much "work" goes away in
my code.  Too bad I can't do this at work (Oracle 8/9)."       (Tom Allison)
           http://archives.postgresql.org/pgsql-general/2007-06/msg00016.php

  9. Re: Fix for visibility check on 14.5 fails on tpcc with high concurrency

    Dimos Stamatakis <dimos.stamatakis@servicenow.com> — 2022-11-25T15:46:08Z

    So does this mean there is no race condition in this case and that this error is redundant?

Thanks,
Dimos
[ServiceNow]


From: Alvaro Herrera <alvherre@alvh.no-ip.org>
Date: Thursday, 24. November 2022 at 19:24
To: Dimos Stamatakis <dimos.stamatakis@servicenow.com>
Cc: Peter Geoghegan <pg@bowt.ie>, simon.riggs@enterprisedb.com <simon.riggs@enterprisedb.com>, pgsql-hackers@lists.postgresql.org <pgsql-hackers@lists.postgresql.org>
Subject: Re: Fix for visibility check on 14.5 fails on tpcc with high concurrency
[External Email]

On 2022-Nov-24, Alvaro Herrera wrote:

> On 2022-Nov-24, Dimos Stamatakis wrote:
>
> > rmgr: MultiXact len (rec/tot): 54/ 54, tx: 248477, lsn: 0/66DB82A8, prev 0/66DB8260, desc: CREATE_ID 133 offset 265 nmembers 2: 248477 (nokeyupd) 248500 (keysh)
> > rmgr: Heap len (rec/tot): 70/ 70, tx: 248477, lsn: 0/66DB82E0, prev 0/66DB82A8, desc: HOT_UPDATE off 20 xmax 133 flags 0x20 IS_MULTI EXCL_LOCK ; new off 59 xmax 132, blkref #0: rel 1663/16384/16385 blk 422
> > rmgr: Transaction len (rec/tot): 34/ 34, tx: 248477, lsn: 0/66DBA710, prev 0/66DBA6D0, desc: ABORT 2022-11-23 20:33:03.712298 UTC
> > …
> > rmgr: Transaction len (rec/tot): 34/ 34, tx: 248645, lsn: 0/66DBB060, prev 0/66DBB020, desc: ABORT 2022-11-23 20:33:03.712388 UTC
>
> Ah, it seems clear enough: the transaction that aborted after having
> updated the tuple, is still considered live when doing the second
> update. That sounds wrong.

Hmm, if a transaction is aborted but its Xid is after latestCompletedXid,
it would be reported as still running. AFAICS that is only modified
with ProcArrayLock held in exclusive mode, and only read with it held in
share mode, so this should be safe.

I can see nothing else ATM.

--
Álvaro Herrera Breisgau, Deutschland — https://www.EnterpriseDB.com/<https://www.EnterpriseDB.com>
"I must say, I am absolutely impressed with what pgsql's implementation of
VALUES allows me to do. It's kind of ridiculous how much "work" goes away in
my code. Too bad I can't do this at work (Oracle 8/9)." (Tom Allison)
http://archives.postgresql.org/pgsql-general/2007-06/msg00016.php<http://archives.postgresql.org/pgsql-general/2007-06/msg00016.php>

  10. Re: Fix for visibility check on 14.5 fails on tpcc with high concurrency

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2022-11-25T19:58:19Z

    On 2022-Nov-25, Dimos Stamatakis wrote:

> So does this mean there is no race condition in this case and that
> this error is redundant?

No, it means I believe a bug exists but that I haven't spent enough time
on it to understand what it is.

Please do not top-post.
https://wiki.postgresql.org/wiki/Mailing_Lists#Email_etiquette_mechanics

-- 
Álvaro Herrera               48°01'N 7°57'E  —  https://www.EnterpriseDB.com/
"La rebeldía es la virtud original del hombre" (Arthur Schopenhauer)

  11. Re: Fix for visibility check on 14.5 fails on tpcc with high concurrency

    Dimos Stamatakis <dimos.stamatakis@servicenow.com> — 2022-11-29T18:21:54Z

    [External Email]

On 2022-Nov-25, Dimos Stamatakis wrote:

> So does this mean there is no race condition in this case and that
> this error is redundant?

No, it means I believe a bug exists but that I haven't spent enough time
on it to understand what it is.



Great! Please keep me posted and let me know if you need any more evidence to debug. 😊

Thanks,
Dimos

  12. Re: Fix for visibility check on 14.5 fails on tpcc with high concurrency

    Dimos Stamatakis <dimos.stamatakis@servicenow.com> — 2023-04-26T15:24:37Z

    Hi hackers,

I was wondering whether there are any updates on the bug in visibility check introduced in version 14.5.

Many thanks,
Dimos
[ServiceNow]