Re: CREATE INDEX CONCURRENTLY does not index prepared xact's data

Andrey Borodin <x4mmm@yandex-team.ru>

View thread

From: Andrey Borodin <x4mmm@yandex-team.ru>

To: Noah Misch <noah@leadboat.com>

Cc: Michael Paquier <michael@paquier.xyz>, Tom Lane <tgl@sss.pgh.pa.us>, pgsql-bugs@lists.postgresql.org

Date: 2021-07-29T12:30:56Z

Lists: pgsql-bugs

Attachments

v6-0001-Introduce-TAP-test-for-2PC-with-CIC-behavior.patch (application/octet-stream) patch v6-0001
v6-0002-Fix-CREATE-INDEX-CONCURRENTLY-in-precence-of-vxid.patch (application/octet-stream) patch v6-0002
v6-0003-Various-debug-stuff-and-fix-in-xidlist.xid.patch (application/octet-stream) patch v6-0003


> 27 июля 2021 г., в 17:50, Andrey Borodin <x4mmm@yandex-team.ru> написал(а):
> 
> 
> 3. It still breaks the fix and I have no idea why.

I'm still coping with the bug. I have a stable reproduction, but to the date unable to identify roots of the problem.
Here's the sample trace:
2021-07-29 17:14:28.996 +05 [61148] 002_cic_2pc.pl LOG:  statement: REINDEX INDEX CONCURRENTLY idx;
2021-07-29 17:14:28.996 +05 [61148] 002_cic_2pc.pl WARNING:  Phase 1
2021-07-29 17:14:28.997 +05 [61148] 002_cic_2pc.pl WARNING:  Phase 2
2021-07-29 17:14:28.997 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: VirtualXactLock vxid -1/3493
2021-07-29 17:14:28.997 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: PreparedXactLock xid 3493, vxid -1/3493
2021-07-29 17:14:28.997 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: VirtualXactLock vxid -1/3490
2021-07-29 17:14:28.997 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: PreparedXactLock xid 3490, vxid -1/3490
2021-07-29 17:14:28.997 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: VirtualXactLock vxid -1/3492
2021-07-29 17:14:28.997 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: PreparedXactLock xid 3492, vxid -1/3492
2021-07-29 17:14:28.999 +05 [61148] 002_cic_2pc.pl WARNING:  Phase 3
2021-07-29 17:14:28.999 +05 [61148] 002_cic_2pc.pl WARNING:  Phase 4
2021-07-29 17:14:29.000 +05 [61148] 002_cic_2pc.pl WARNING:  Phase 5
2021-07-29 17:14:29.005 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: VirtualXactLock vxid -1/3512
2021-07-29 17:14:29.005 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: PreparedXactLock xid 3512, vxid -1/3512
2021-07-29 17:14:29.006 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: VirtualXactLock vxid -1/3513
2021-07-29 17:14:29.006 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: PreparedXactLock xid 3513, vxid -1/3513
2021-07-29 17:14:29.006 +05 [61148] 002_cic_2pc.pl WARNING:  Phase 6
2021-07-29 17:14:29.006 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: VirtualXactLock vxid -1/3516
2021-07-29 17:14:29.006 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: PreparedXactLock xid 3516, vxid -1/3516
2021-07-29 17:14:29.006 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: VirtualXactLock vxid -1/3515
2021-07-29 17:14:29.007 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: PreparedXactLock xid 3515, vxid -1/3515
2021-07-29 17:14:29.007 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: VirtualXactLock vxid -1/3517
2021-07-29 17:14:29.007 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: PreparedXactLock xid 3517, vxid -1/3517
2021-07-29 17:14:29.007 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: VirtualXactLock vxid 4/1002
2021-07-29 17:14:29.007 +05 [61148] 002_cic_2pc.pl WARNING:  Backend is doing something else
2021-07-29 17:14:29.007 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: PreparedXactLock xid 0, vxid 4/1002
2021-07-29 17:14:29.007 +05 [61148] 002_cic_2pc.pl WARNING:  XXX: Sucessfully found xid by vxid 0
2021-07-29 17:14:29.007 +05 [61148] 002_cic_2pc.pl WARNING:  Phase Final
2021-07-29 17:14:29.007 +05 [61148] 002_cic_2pc.pl LOG:  statement: SELECT bt_index_check('idx',true);
2021-07-29 17:14:29.009 +05 [61148] 002_cic_2pc.pl ERROR:  heap tuple (18,74) from table "tbl" lacks matching index tuple within index "idx" xmin 3504 xmax 0
2021-07-29 17:14:29.009 +05 [61148] 002_cic_2pc.pl STATEMENT:  SELECT bt_index_check('idx',true);

Rogue tuple was committed by xid 3504 which was never returned by GetLockConflicts(). I'm attaching patch set just for the reference of the trace, not expecting code review now.

I've fixed unrelated bug in previous patchset.
-                       SET_LOCKTAG_TRANSACTION(tag, xid);
+                       SET_LOCKTAG_TRANSACTION(tag, xidlist.xid);
                        lar = LockAcquire(&tag, ShareLock, false, !wait);
                        if (lar != LOCKACQUIRE_NOT_AVAIL)
                                LockRelease(&tag, ShareLock, false);
-                       return lar != LOCKACQUIRE_NOT_AVAIL;
+                       if (lar == LOCKACQUIRE_NOT_AVAIL)
+                               return false;

But it does not help. Maybe I've broken something by my fix...Searching further.

Thanks for reading! Would be happy to hear any ideas why xid was not locked by GetLockConflicts() bug committed a tuple which was not indexed.

Best regards, Andrey Borodin.

Commits

Same data as JSON: GET /api/v1/messages/:b64id/commits the thread's linked commits as JSON, with link sources. API reference →

Improve contrib/amcheck's tests for CREATE INDEX CONCURRENTLY.
- b1f943d2aa7e 14.1 landed
- 7f580aa5d88a 15.0 landed
- 5a4b8a8a720c 13.5 landed
- 141cd0ef0b0b 12.9 landed
Fix minor memory leaks in pg_dump.
- 70bef494000e 15.0 cited
Avoid race in RelationBuildDesc() affecting CREATE INDEX CONCURRENTLY.
- e428699cb3be 9.6.24 landed
- db86746fd11e 10.19 landed
- 5141e471b36a 11.14 landed
- dde966efb286 14.1 landed
- 2e33b43599ad 13.5 landed
- 0869e53d3a07 12.9 landed
- fdd965d074d4 15.0 landed
Fix CREATE INDEX CONCURRENTLY for the newest prepared transactions.
- df6158139f64 11.14 landed
- 560124a37c2f 10.19 landed
- 5184932432b4 9.6.24 landed
- fe5d44a1d38f 12.9 landed
- a9d0a5409415 13.5 landed
- a5b9a0000e14 14.1 landed
- 3cd9c3b92197 15.0 landed
Add -w back to the flags for pg_ctl (re)start in PostgresNode
- b33259e261ae 15.0 cited
Fix CREATE INDEX CONCURRENTLY for simultaneous prepared transactions.
- 77a0e14f0b21 9.5.25 landed
- d683d6528dba 9.6.21 landed
- 179775135b41 10.16 landed
- d1ab4bf6ed2d 11.11 landed
- be843ce29737 12.6 landed
- 86a5b309c933 13.2 landed
- 8a54e12a38d1 14.0 landed