Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1lh06T-0002GK-Se for pgsql-hackers@arkaria.postgresql.org; Thu, 13 May 2021 01:25:30 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1lh06S-0003Kv-3q for pgsql-hackers@arkaria.postgresql.org; Thu, 13 May 2021 01:25:28 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1lh06R-0003Kn-J6 for pgsql-hackers@lists.postgresql.org; Thu, 13 May 2021 01:25:27 +0000 Received: from mail-m17670.qiye.163.com ([59.111.176.70]) by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1lh06G-0002cP-4m for pgsql-hackers@postgresql.org; Thu, 13 May 2021 01:25:24 +0000 Received: from activesync-2-hmail-entmail-virt40.dg.163.org (localhost [127.0.0.1]) by mail-m17670.qiye.163.com (Hmail) with ESMTP id F3C8D3C00B1; Thu, 13 May 2021 09:25:05 +0800 (CST) From: "Pengchengliu" To: "'Greg Nancarrow'" Cc: "'Andres Freund'" , "'PostgreSQL-development'" References: <000901d742f1$acae3ad0$060ab070$@tju.edu.cn> <20210507035510.he7e5hiu6dsi4rug@alap3.anarazel.de> <000001d7432b$33cc4a00$9b64de00$@tju.edu.cn> <000601d74604$d8af7570$8a0e6050$@tju.edu.cn> In-Reply-To: Subject: RE: Parallel scan with SubTransGetTopmostTransaction assert coredump Date: Thu, 13 May 2021 09:25:05 +0800 Message-ID: <002501d74796$ce4083c0$6ac18b40$@tju.edu.cn> MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="----=_NextPart_000_0026_01D747D9.DC657170" X-Mailer: Microsoft Outlook 16.0 Thread-Index: AQJWZzOrsYDN3Ar+nCJfWwrfcv+5KQKg04GwAjPEpnoBa3FGLQFfmMneAjZdCbCpk64cAA== Content-Language: zh-cn X-HM-Spam-Status: e1kfGhgUHx5ZQUtXWQgYFAkeWUFZS1VLWVdZKFlBSE83V1ktWUFJV1kPCR oVCBIfWUFZQx1KHlZDQ09JQklJTkgfQ0tVEwETFhoSFyQUDg9ZV1kWGg8SFR0UWUFZT0tIVUpKS0 hKTFVLWQY+ X-HM-Sender-Digest: e1kMHhlZQQ8JDh5XWRIfHhUPWUFZRzoyTTowKjpOPwlOMiNRLBEWAyMr HzAKSFVKVUpNSUtDTUJKS01IT0hVMxYaEhdVCx4VHBgTHhUcFxIOOw8RDlUeHw5VGBVFWVdZEgtZ QVlJSkNVSVVCTFVCSVlXWQgBWUFPS0tLTTcG X-HM-Tid: 0a796353c94fda5akuwsf3c8d3c00b1 List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk This is a multipart message in MIME format. ------=_NextPart_000_0026_01D747D9.DC657170 Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable Hi Andres, Thanks for you replay.=20 And If you still cannot reproduce it in 2 minitus. Could you run = pgbench longer time, such as 30 or 60 minutes. =20 This coredump, It should be from parallel scan only.=20 For normal scan(without parallel), SubTransGetTopmostTransaction = assert(HeapTupleSatisfiesMVCC->XidInMVCCSnapshot->SubTransGetTopmostTrans= action->Assert(TransactionIdFollowsOrEquals(xid, TransactionXmin))), I think this Assert is correct. As single scan get transaction = snapshot while set the TransactionXmin and Snapshot->xmin.=20 In XidInMVCCSnapshot, it will check whether xid precedes = snapshot->xmin first. If it is, XidInMVCCSnapshot will return false = directly. So in XidInMVCCSnapshot->SubTransGetTopmostTransaction, xid cannot = precede snapshot->xmin. =20 But for parallel scan, it is different. I modify the code and use the = sleep to replace the SubTransGetTopmostTransaction Assert.=20 Then we can check TransactionXmin and the snapshot from DSA. The stack is as below, when got the Assert error.=20 =20 (gdb) bt #0 0x0000149fb3d254bb in select () from /lib64/libc.so.6 #1 0x0000000000b1d3b3 in pg_usleep (microsec=3D1000000) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/port/pgsleep.= c:56 #2 0x0000000000562a3b in SubTransGetTopmostTransaction (xid=3D799225) = at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/transam/subtrans.c:164 #3 0x0000000000b04acb in XidInMVCCSnapshot (xid=3D799225, = snapshot=3D0x2af2d00) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/utils= /time/snapmgr.c:2293 #4 0x00000000004ff24c in HeapTupleSatisfiesMVCC (htup=3D0x7fffc1465f60, = snapshot=3D0x2af2d00, buffer=3D109832) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/heap/heapam_visibility.c:1073 #5 0x00000000005002f3 in HeapTupleSatisfiesVisibility = (tup=3D0x7fffc1465f60, snapshot=3D0x2af2d00, buffer=3D109832) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/heap/heapam_visibility.c:1695 #6 0x00000000004e41cb in heapgetpage (sscan=3D0x2af3118, page=3D10846) = at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/heap/heapam.c:447 #7 0x00000000004e684f in heapgettup_pagemode (scan=3D0x2af3118, = dir=3DForwardScanDirection, nkeys=3D0, key=3D0x0) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/heap/heapam.c:1077 #8 0x00000000004e6e46 in heap_getnextslot (sscan=3D0x2af3118, = direction=3DForwardScanDirection, slot=3D0x2affab0) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/heap/heapam.c:1333 #9 0x0000000000752e1a in table_scan_getnextslot (sscan=3D0x2af3118, = direction=3DForwardScanDirection, slot=3D0x2affab0) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/include/acces= s/tableam.h:906 #10 0x0000000000752ee2 in SeqNext (node=3D0x2aff538) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/nodeSeqscan.c:80 #11 0x000000000071a848 in ExecScanFetch (node=3D0x2aff538, = accessMtd=3D0x752e4e , recheckMtd=3D0x752ef3 ) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/execScan.c:133 #12 0x000000000071a8e9 in ExecScan (node=3D0x2aff538, = accessMtd=3D0x752e4e , recheckMtd=3D0x752ef3 ) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/execScan.c:199 #13 0x0000000000752f3d in ExecSeqScan (pstate=3D0x2aff538) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/nodeSeqscan.c:112 #14 0x0000000000725794 in ExecProcNode (node=3D0x2aff538) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/include/execu= tor/executor.h:248 #15 0x0000000000725c7f in fetch_input_tuple (aggstate=3D0x2afeff0) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/nodeAgg.c:589 #16 0x0000000000728f98 in agg_retrieve_direct (aggstate=3D0x2afeff0) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/nodeAgg.c:2463 #17 0x00000000007289f2 in ExecAgg (pstate=3D0x2afeff0) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/nodeAgg.c:2183 #18 0x0000000000716cbb in ExecProcNodeFirst (node=3D0x2afeff0) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/execProcnode.c:450 #19 0x000000000070b103 in ExecProcNode (node=3D0x2afeff0) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/include/execu= tor/executor.h:248 #20 0x000000000070dc0e in ExecutePlan (estate=3D0x2afeb30, = planstate=3D0x2afeff0, use_parallel_mode=3Dfalse, = operation=3DCMD_SELECT, sendTuples=3Dtrue, numberTuples=3D0,=20 direction=3DForwardScanDirection, dest=3D0x2ab0578, = execute_once=3Dtrue) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/execMain.c:1632 #21 0x000000000070b72e in standard_ExecutorRun (queryDesc=3D0x2af2c68, = direction=3DForwardScanDirection, count=3D0, execute_once=3Dtrue) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/execMain.c:350 #22 0x000000000070b55c in ExecutorRun (queryDesc=3D0x2af2c68, = direction=3DForwardScanDirection, count=3D0, execute_once=3Dtrue) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/execMain.c:294 #23 0x0000000000712ae1 in ParallelQueryMain (seg=3D0x2a0a0c8, = toc=3D0x149fb4dab000) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/execParallel.c:1448 #24 0x000000000055f69c in ParallelWorkerMain (main_arg=3D1403863538) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/transam/parallel.c:1470 #25 0x000000000086db61 in StartBackgroundWorker () at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/postm= aster/bgworker.c:879 #26 0x0000000000881238 in do_start_bgworker (rw=3D0x2a351b0) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/postm= aster/postmaster.c:5870 #27 0x00000000008815e4 in maybe_start_bgworkers () at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/postm= aster/postmaster.c:6095 #28 0x0000000000880620 in sigusr1_handler (postgres_signal_arg=3D10) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/postm= aster/postmaster.c:5255 #29 #30 0x0000149fb3d254bb in select () from /lib64/libc.so.6 #31 0x000000000087c173 in ServerLoop () at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/postm= aster/postmaster.c:1703 #32 0x000000000087bb3e in PostmasterMain (argc=3D3, argv=3D0x2a08080) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/postm= aster/postmaster.c:1412 #33 0x0000000000782d24 in main (argc=3D3, argv=3D0x2a08080) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/main/= main.c:210 (gdb) f 24 #24 0x000000000055f69c in ParallelWorkerMain (main_arg=3D1403863538) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/transam/parallel.c:1470 1470 entrypt(seg, toc); (gdb) p *ActiveSnapshot->as_snap //active snapshot from main process $18 =3D {snapshot_type =3D SNAPSHOT_MVCC, xmin =3D 799162, xmax =3D = 822061, xip =3D 0x2ab0190, xcnt =3D 169, subxip =3D 0x0, subxcnt =3D 0, = suboverflowed =3D true, takenDuringRecovery =3D false,=20 copied =3D true, curcid =3D 119, speculativeToken =3D 2139062143, = active_count =3D 1, regd_count =3D 2, ph_node =3D {first_child =3D = 0x2af2d40, next_sibling =3D 0x0, prev_or_parent =3D 0x0},=20 whenTaken =3D 0, lsn =3D 0} (gdb) p *CurrentSnapshot //transaction snapshot from main process=20 $19 =3D {snapshot_type =3D SNAPSHOT_MVCC, xmin =3D 799425, xmax =3D = 822293, xip =3D 0x2ab1c00, xcnt =3D 172, subxip =3D 0x149f29302010, = subxcnt =3D 0, suboverflowed =3D true,=20 takenDuringRecovery =3D false, copied =3D false, curcid =3D 119, = speculativeToken =3D 0, active_count =3D 0, regd_count =3D 0, ph_node = =3D {first_child =3D 0x0, next_sibling =3D 0x0,=20 prev_or_parent =3D 0x0}, whenTaken =3D 0, lsn =3D 0} (gdb) f 4 #4 0x00000000004ff24c in HeapTupleSatisfiesMVCC (htup=3D0x7fffc1465f60, = snapshot=3D0x2af2d00, buffer=3D109832) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/heap/heapam_visibility.c:1073 1073 = XidInMVCCSnapshot(HeapTupleHeaderGetRawXmin(tuple), snapshot)) (gdb) p *snapshot //ative snap shot from main process for scan $20 =3D {snapshot_type =3D SNAPSHOT_MVCC, xmin =3D 799162, xmax =3D = 822061, xip =3D 0x2af2d68, xcnt =3D 169, subxip =3D 0x0, subxcnt =3D 0, = suboverflowed =3D true, takenDuringRecovery =3D false,=20 copied =3D true, curcid =3D 119, speculativeToken =3D 2139062143, = active_count =3D 0, regd_count =3D 1, ph_node =3D {first_child =3D 0x0, = next_sibling =3D 0xf65ca0 ,=20 prev_or_parent =3D 0x2ab0168}, whenTaken =3D 0, lsn =3D 0} (gdb) p TransactionXmin $21 =3D 799425 (gdb) f 3 #3 0x0000000000b04acb in XidInMVCCSnapshot (xid=3D799225, = snapshot=3D0x2af2d00) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/utils= /time/snapmgr.c:2293 2293 xid =3D = SubTransGetTopmostTransaction(xid); (gdb) p xid $22 =3D 799225 =20 The main process: 1, Main process get the transaction snapshot(xmin 799162, xmax = 822061) and push the active snapshot first. And set this active snapshot = to QueryDesc in CreateQueryDesc. 2, Main process collect active snapshot(xmin 799162, xmax 82206) and = get the newer transaction snapshot(xmin 799425, xmax 822293). And use = the parameter PARALLEL_KEY_TRANSACTION_SNAPSHOT, = PARALLEL_KEY_ACTIVE_SNAPSHOT store transaction snapshot and active snapshot. 3, Main process = ExecGather->ExecInitParallelPlan->ExecParallelInitializeDSM->ExecSeqScanI= nitializeDSM->table_parallelscan_initialize, send active snapshot(xmin = 799162, xmax 82206) with plan id to parallel work process. 4, lauch parallel work process. =20 The parallel work process: 1, Get Snapshot and set TransactionXmin itself, in = ParallelWorkerMain->BackgroundWorkerInitializeConnectionByOid->GetTransac= tionSnapshot->GetSnapshotData. 2, Acooding PARALLEL_KEY_TRANSACTION_SNAPSHOT(xmin 799425, xmax 82229) = from main process, and set TransactionXmin 799425 in = ParallelWorkerMain->RestoreTransactionSnapshot->SetTransactionSnapshot->P= rocArrayInstallRestoredXmin. 3, = ExecParallelInitializeWorker->ExecSeqScanInitializeWorker->table_beginsca= n_parallel get the active snapshot(xmin 799162, xmax 82206) from main = process, and set this snapshot to scan->rs_base.rs_snapshot. 4, parallel scan begin, with active snapshot(xmin 799162, xmax 82206) = and TransactionXmin(799425),when scan tuple(xmin 799225) = SubTransGetTopmostTransaction assert got.=20 In = HeapTupleSatisfiesMVCC->XidInMVCCSnapshot->SubTransGetTopmostTransaction.= =20 As main process gets the active snapshot (xmin 799162, xmax 822061) = which is earlier than transaction snapshot(xmin 799425, xmax 822293). = Parallel work process set TransactionXmin with transaction snapshot(xmin = 799425, xmax 822293). But scan tuple with active snapshot (xmin 799162, xmax 822061). Thanks Pengcheng =20 =20 =20 =20 =20 -----Original Message----- From: Greg Nancarrow =20 Sent: 2021=E5=B9=B45=E6=9C=8811=E6=97=A5 19:08 To: Pengchengliu Cc: Andres Freund ; PostgreSQL-development = Subject: Re: Parallel scan with SubTransGetTopmostTransaction assert = coredump =20 On Tue, May 11, 2021 at 11:28 AM Pengchengliu < = pengchengliu@tju.edu.cn> wrote: >=20 > Hi Andres, > Reproduce steps. >=20 > 1, Modify and adjust NUM_SUBTRANS_BUFFERS to 128 from 32 in the file = "src/include/access/subtrans.h" line number 15. > 2, configure with enable assert and build it. > 3, init a new database cluster. > 4, modify postgres.conf and add some parameters as below. As the = coredump from parallel scan, so we adjust parallel setting, make it easy = to reproduce. >=20 > max_connections =3D 2000 >=20 > parallel_setup_cost=3D0 > parallel_tuple_cost=3D0 > min_parallel_table_scan_size=3D0 > max_parallel_workers_per_gather=3D8 > max_parallel_workers =3D 32 >=20 > 5, start the database cluster. > 6, use the script init_test.sql in attachment to create tables. > 7, use pgbench with script sub_120.sql in attachment to test it. Try = it sometimes, you should get the coredump file. > pgbench -d postgres -p 33550 -n -r -f sub_120.sql -c 200 -j = 200 -T 120 >=20 =20 Hi, =20 I had a go at reproducing your reported issue, making sure to follow all = your steps. Unfortunately, your script seemed to run OK with pgbench and no = crash/coredump occurred for me (and yes, I definitely had asserts = enabled). I tried with both the 13.2 source code (3fb4c75e857adee3da4386e947ba58a75f3e74b7), running through the script = with pgbench twice to completion, and also did the same using the latest = Postgres source code. =20 Will be interesting to see if anyone is able to reproduce your issue. =20 Regards, Greg Nancarrow Fujitsu Australia ------=_NextPart_000_0026_01D747D9.DC657170 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable

Hi Andres,

=C2=A0 Thanks for you replay.

=C2=A0=C2=A0And If you still cannot reproduce it in = 2 minitus. Could you run pgbench longer time, such as 30 or 60 = minutes.

 

=C2=A0 This coredump, It should be from parallel = scan only.

=C2=A0=C2=A0For normal = scan(without parallel), SubTransGetTopmostTransaction = assert(HeapTupleSatisfiesMVCC->XidInMVCCSnapshot->SubTransGetTopmos= tTransaction->Assert(TransactionIdFollowsOrEquals(xid, = TransactionXmin))),

=C2=A0 I think = this Assert is correct. As single scan get transaction snapshot while = set the TransactionXmin and Snapshot->xmin.

=C2=A0=C2=A0In XidInMVCCSnapshot, it will check = whether xid precedes snapshot->xmin first. If it is, = XidInMVCCSnapshot will return false directly.

=C2=A0 So in = XidInMVCCSnapshot->SubTransGetTopmostTransaction, xid cannot precede = snapshot->xmin.

=C2=A0 =

=C2=A0=C2=A0But for parallel = scan, it is different. I modify the code and use the sleep to replace = the=C2=A0 SubTransGetTopmostTransaction Assert.

=C2=A0=C2=A0Then we can check TransactionXmin and = the snapshot from DSA.

=

=C2=A0=C2=A0The stack is as = below, when got the Assert error.

 

(gdb) = bt

#0=C2=A0 0x0000149fb3d254bb in = select () from /lib64/libc.so.6

#1=C2=A0 0x0000000000b1d3b3 in pg_usleep = (microsec=3D1000000) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/port/pgsleep.= c:56

#2=C2=A0 0x0000000000562a3b = in SubTransGetTopmostTransaction (xid=3D799225) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/transam/subtrans.c:164

#3=C2=A0 = 0x0000000000b04acb in XidInMVCCSnapshot (xid=3D799225, = snapshot=3D0x2af2d00) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/utils= /time/snapmgr.c:2293

#4=C2=A0 = 0x00000000004ff24c in HeapTupleSatisfiesMVCC (htup=3D0x7fffc1465f60, = snapshot=3D0x2af2d00, buffer=3D109832)

=C2=A0=C2=A0=C2=A0 at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/heap/heapam_visibility.c:1073

#5=C2=A0 0x00000000005002f3 in = HeapTupleSatisfiesVisibility (tup=3D0x7fffc1465f60, = snapshot=3D0x2af2d00, buffer=3D109832)

=C2=A0=C2=A0=C2=A0 at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/heap/heapam_visibility.c:1695

#6=C2=A0 0x00000000004e41cb in heapgetpage = (sscan=3D0x2af3118, page=3D10846) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/heap/heapam.c:447

#7=C2=A0 = 0x00000000004e684f in heapgettup_pagemode (scan=3D0x2af3118, = dir=3DForwardScanDirection, nkeys=3D0, key=3D0x0)

=C2=A0=C2=A0=C2=A0 at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/heap/heapam.c:1077

#8=C2=A0 = 0x00000000004e6e46 in heap_getnextslot (sscan=3D0x2af3118, = direction=3DForwardScanDirection, slot=3D0x2affab0)

=C2=A0=C2=A0=C2=A0 at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/heap/heapam.c:1333

#9=C2=A0 = 0x0000000000752e1a in table_scan_getnextslot (sscan=3D0x2af3118, = direction=3DForwardScanDirection, slot=3D0x2affab0)

=C2=A0=C2=A0=C2=A0 at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/include/acces= s/tableam.h:906

#10 = 0x0000000000752ee2 in SeqNext (node=3D0x2aff538) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/nodeSeqscan.c:80

#11 = 0x000000000071a848 in ExecScanFetch (node=3D0x2aff538, = accessMtd=3D0x752e4e <SeqNext>, recheckMtd=3D0x752ef3 = <SeqRecheck>)

=C2=A0=C2=A0=C2=A0 at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/execScan.c:133

#12 = 0x000000000071a8e9 in ExecScan (node=3D0x2aff538, accessMtd=3D0x752e4e = <SeqNext>, recheckMtd=3D0x752ef3 = <SeqRecheck>)

=C2=A0=C2=A0=C2=A0 at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/execScan.c:199

#13 = 0x0000000000752f3d in ExecSeqScan (pstate=3D0x2aff538) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/nodeSeqscan.c:112

#14 = 0x0000000000725794 in ExecProcNode (node=3D0x2aff538) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/include/execu= tor/executor.h:248

#15 = 0x0000000000725c7f in fetch_input_tuple (aggstate=3D0x2afeff0) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/nodeAgg.c:589

#16 = 0x0000000000728f98 in agg_retrieve_direct (aggstate=3D0x2afeff0) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/nodeAgg.c:2463

#17 = 0x00000000007289f2 in ExecAgg (pstate=3D0x2afeff0) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/nodeAgg.c:2183

#18 = 0x0000000000716cbb in ExecProcNodeFirst (node=3D0x2afeff0) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/execProcnode.c:450

#19 = 0x000000000070b103 in ExecProcNode (node=3D0x2afeff0) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/include/execu= tor/executor.h:248

#20 = 0x000000000070dc0e in ExecutePlan (estate=3D0x2afeb30, = planstate=3D0x2afeff0, use_parallel_mode=3Dfalse, = operation=3DCMD_SELECT, sendTuples=3Dtrue, numberTuples=3D0, =

=C2=A0=C2=A0=C2=A0=C2=A0direction=3DForwardScanDirec= tion, dest=3D0x2ab0578, execute_once=3Dtrue) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/execMain.c:1632

#21 = 0x000000000070b72e in standard_ExecutorRun (queryDesc=3D0x2af2c68, = direction=3DForwardScanDirection, count=3D0, = execute_once=3Dtrue)

=C2=A0=C2=A0=C2=A0 at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/execMain.c:350

#22 = 0x000000000070b55c in ExecutorRun (queryDesc=3D0x2af2c68, = direction=3DForwardScanDirection, count=3D0, = execute_once=3Dtrue)

=C2=A0=C2=A0=C2=A0 at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/execMain.c:294

#23 = 0x0000000000712ae1 in ParallelQueryMain (seg=3D0x2a0a0c8, = toc=3D0x149fb4dab000) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/execu= tor/execParallel.c:1448

#24 = 0x000000000055f69c in ParallelWorkerMain (main_arg=3D1403863538) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/transam/parallel.c:1470

#25 = 0x000000000086db61 in StartBackgroundWorker () at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/postm= aster/bgworker.c:879

#26 = 0x0000000000881238 in do_start_bgworker (rw=3D0x2a351b0) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/postm= aster/postmaster.c:5870

#27 = 0x00000000008815e4 in maybe_start_bgworkers () at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/postm= aster/postmaster.c:6095

#28 = 0x0000000000880620 in sigusr1_handler (postgres_signal_arg=3D10) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/postm= aster/postmaster.c:5255

#29 = <signal handler called>

#30 = 0x0000149fb3d254bb in select () from /lib64/libc.so.6

#31 0x000000000087c173 in ServerLoop () at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/postm= aster/postmaster.c:1703

#32 = 0x000000000087bb3e in PostmasterMain (argc=3D3, argv=3D0x2a08080) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/postm= aster/postmaster.c:1412

#33 = 0x0000000000782d24 in main (argc=3D3, argv=3D0x2a08080) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/main/= main.c:210

(gdb) f = 24

#24 0x000000000055f69c in = ParallelWorkerMain (main_arg=3D1403863538) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/transam/parallel.c:1470

1470=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0 entrypt(seg, toc);

(gdb) p *ActiveSnapshot->as_snap=C2=A0 //active snapshot from = main process

$18 =3D = {snapshot_type =3D SNAPSHOT_MVCC, xmin =3D 799162, xmax = =3D 822061, xip =3D 0x2ab0190, xcnt =3D 169, subxip =3D 0x0, = subxcnt =3D 0, suboverflowed =3D true, takenDuringRecovery =3D false, =

=C2=A0=C2=A0copied =3D true, = curcid =3D 119, speculativeToken =3D 2139062143, active_count =3D 1, = regd_count =3D 2, ph_node =3D {first_child =3D 0x2af2d40, next_sibling = =3D 0x0, prev_or_parent =3D 0x0},

=C2=A0=C2=A0whenTaken =3D 0, lsn =3D = 0}

(gdb) p *CurrentSnapshot=C2=A0 = //transaction = snapshot from main process

$19 =3D {snapshot_type =3D SNAPSHOT_MVCC, xmin =3D 799425, xmax = =3D 822293, xip =3D 0x2ab1c00, xcnt =3D 172, subxip =3D = 0x149f29302010, subxcnt =3D 0, suboverflowed =3D true,

=C2=A0=C2=A0takenDuringRecovery =3D false, copied = =3D false, curcid =3D 119, speculativeToken =3D 0, active_count =3D 0, = regd_count =3D 0, ph_node =3D {first_child =3D 0x0, next_sibling =3D = 0x0,

=C2=A0=C2=A0=C2=A0=C2=A0prev_or_parent =3D 0x0}, = whenTaken =3D 0, lsn =3D 0}

(gdb) = f 4

#4=C2=A0 0x00000000004ff24c in = HeapTupleSatisfiesMVCC (htup=3D0x7fffc1465f60, snapshot=3D0x2af2d00, = buffer=3D109832)

=C2=A0=C2=A0=C2=A0 at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/acces= s/heap/heapam_visibility.c:1073

1073=C2=A0=C2=A0 = =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0= XidInMVCCSnapshot(HeapTupleHeaderGetRawXmin(tuple), = snapshot))

(gdb) p *snapshot=C2=A0 = //ative snap shot = from main process for scan

$20 =3D {snapshot_type =3D SNAPSHOT_MVCC, xmin =3D 799162, xmax = =3D 822061, xip =3D 0x2af2d68, xcnt =3D 169, subxip =3D 0x0, = subxcnt =3D 0, suboverflowed =3D true, takenDuringRecovery =3D false, =

=C2=A0=C2=A0copied =3D true, = curcid =3D 119, speculativeToken =3D 2139062143, active_count =3D 0, = regd_count =3D 1, ph_node =3D {first_child =3D 0x0, next_sibling =3D = 0xf65ca0 <CatalogSnapshotData+64>,

=C2=A0=C2=A0=C2=A0=C2=A0prev_or_parent =3D = 0x2ab0168}, whenTaken =3D 0, lsn =3D 0}

(gdb) p = TransactionXmin

$21 =3D = 799425

(gdb) f = 3

#3=C2=A0 0x0000000000b04acb in = XidInMVCCSnapshot (xid=3D799225, snapshot=3D0x2af2d00) at = /home/liupc/build/build_postgres2/../../devel/postgres2/src/backend/utils= /time/snapmgr.c:2293

2293=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 xid =3D = SubTransGetTopmostTransaction(xid);

(gdb) p xid

$22 =3D 799225

 

The = main process:

=C2=A0 1, Main = process get the transaction snapshot(xmin 799162, xmax=C2=A0 822061) and = push the active snapshot first. And set this active snapshot to = QueryDesc in CreateQueryDesc.

=C2=A0 2, Main process collect active snapshot(xmin = 799162, xmax=C2=A0 82206) and get the newer transaction snapshot(xmin = 799425, xmax 822293). And use the parameter = PARALLEL_KEY_TRANSACTION_SNAPSHOT, = PARALLEL_KEY_ACTIVE_SNAPSHOT

=C2=A0=C2=A0=C2=A0=C2=A0 store transaction snapshot = and active snapshot.

=C2=A0 3, = Main process = ExecGather->ExecInitParallelPlan->ExecParallelInitializeDSM->Exe= cSeqScanInitializeDSM->table_parallelscan_initialize, send active = snapshot(xmin 799162, xmax=C2=A0 82206) with plan id to parallel work = process.

=C2=A0 4, lauch parallel = work process.

=C2=A0 =

=C2=A0=C2=A0The parallel work = process:

=C2=A0 1, Get Snapshot = and set TransactionXmin itself, in = ParallelWorkerMain->BackgroundWorkerInitializeConnectionByOid->GetT= ransactionSnapshot->GetSnapshotData.

=C2=A0 2, Acooding = PARALLEL_KEY_TRANSACTION_SNAPSHOT(xmin 799425, xmax 82229) from main = process, and set TransactionXmin 799425 in = ParallelWorkerMain->RestoreTransactionSnapshot->SetTransactionSnaps= hot->ProcArrayInstallRestoredXmin.

=C2=A0 3, = ExecParallelInitializeWorker->ExecSeqScanInitializeWorker->table_be= ginscan_parallel get the active snapshot(xmin 799162, xmax=C2=A0 82206) = from main process, and set this snapshot to = scan->rs_base.rs_snapshot.

=C2=A0 4, parallel scan begin, with active = snapshot(xmin 799162, xmax=C2=A0 82206) and TransactionXmin(799425),when = scan tuple(xmin 799225) SubTransGetTopmostTransaction assert got. =

=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0In=C2=A0 = HeapTupleSatisfiesMVCC->XidInMVCCSnapshot->SubTransGetTopmostTransa= ction.

=C2=A0

=C2=A0=C2=A0As main process gets the active = snapshot (xmin 799162, xmax 822061) which is earlier than transaction = snapshot(xmin 799425, xmax 822293). Parallel work process set = TransactionXmin with transaction snapshot(xmin 799425, xmax = 822293).

=C2=A0 But scan tuple = with active snapshot (xmin 799162, xmax 822061).

Thanks

Pengcheng

=C2=A0

=C2=A0=C2=A0

=C2=A0=C2=A0

 

 

-----Original Message-----
From: Greg Nancarrow = <gregn4422@gmail.com>
Sent: 2021=E5=B9=B45=E6=9C=8811=E6=97=A5 = 19:08
To: Pengchengliu <pengchengliu@tju.edu.cn>
Cc: Andres = Freund <andres@anarazel.de>; PostgreSQL-development = <pgsql-hackers@postgresql.org>
Subject: Re: Parallel scan with = SubTransGetTopmostTransaction assert coredump

 

On = Tue, May 11, 2021 at 11:28 AM Pengchengliu <pengchengliu@tju.edu.cn> wrote:

> 

> Hi Andres,

>=C2=A0=C2=A0=C2=A0 Reproduce = steps.

> 

> 1, Modify and adjust NUM_SUBTRANS_BUFFERS to = 128 from 32 in the file=C2=A0 "src/include/access/subtrans.h" = line number 15.

> 2, configure = with enable assert and build it.

> 3, init a new database = cluster.

> 4, modify=C2=A0 = postgres.conf=C2=A0 and add some parameters as below. As the coredump = from parallel scan, so we adjust parallel setting, make it easy to = reproduce.

> 

>=C2=A0=C2=A0 max_connections =3D = 2000

> 

>=C2=A0=C2=A0 = parallel_setup_cost=3D0

>=C2=A0=C2=A0 = parallel_tuple_cost=3D0

>=C2=A0=C2=A0 = min_parallel_table_scan_size=3D0

>=C2=A0=C2=A0 = max_parallel_workers_per_gather=3D8

>=C2=A0=C2=A0 max_parallel_workers =3D = 32

> 

> 5, start the database = cluster.

> 6, use the script = init_test.sql=C2=A0 in attachment to create tables.

> 7, use pgbench with script sub_120.sql in = attachment to test it. Try it sometimes, you should get the coredump = file.

>=C2=A0 = =C2=A0=C2=A0=C2=A0pgbench=C2=A0 -d postgres -p 33550=C2=A0 -n -r -f = sub_120.sql=C2=A0=C2=A0 -c 200 -j 200 -T 120

> 

 

Hi,

 

I had = a go at reproducing your reported issue, making sure to follow all your = steps.

Unfortunately, your script = seemed to run OK with pgbench and no crash/coredump occurred for me (and = yes, I definitely had asserts enabled).

I tried with both the 13.2 source = code

(3fb4c75e857adee3da4386e947ba58a75f3e74b7), running = through the script with pgbench twice to completion, and also did the = same using the latest Postgres source code.

 

Will = be interesting to see if anyone is able to reproduce your = issue.

 

Regards,

Greg = Nancarrow

Fujitsu = Australia

------=_NextPart_000_0026_01D747D9.DC657170--