Re:Re: Connections hang indefinitely while taking a gin index's LWLock buffer_content lock

From: chenhj <chjischj(at)163(dot)com>
To: "Peter Geoghegan" <pg(at)bowt(dot)ie>
Cc: "Teodor Sigaev" <teodor(at)sigaev(dot)ru>, "PostgreSQL Hackers" <pgsql-hackers(at)lists(dot)postgresql(dot)org>
Subject: Re:Re: Connections hang indefinitely while taking a gin index's LWLock buffer_content lock
Date: 2018-11-11 17:33:17
Message-ID: 47384c2e.297.16703d5b958.Coremail.chjischj@163.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers

Hi

Before we only discussed the connection hang on the primary, the connection hang on the standby database should be another problem.
When the recovery process replays the gin's delete WAL record, the order of get lwlock is not the same as the select process,
resulting in a deadlock. Accord infomation form gcore, the details are as follows:

## select process

2246(rootBlkno=2246)
|
3254(1. Held buffer=366260,LWLock=0x2aaaad50e2e4) --rightlink--> 483(2. Acquire buffer=2201739,LWLock=0x2aaab45158a4)

The ginStepRight() function in select process gets the lwlock in the order of left to right.

## recovey process

2246(2. Held buffer=7034160,LWLock=0x2aaac6c081e4,rootBlkno)
|
3254(3. Acquire buffer=366260,LWLock=0x2aaaad50e2e4) --rightlink--> 483(1. Held buffer=2201739,LWLock=0x2aaab45158a4)

But, the ginRedoDeletePage() function in recovery process gets the lwlock in the order of current to parent and to left.
So, i think inconsistent lock order in ginRedoDeletePage() is the reason for hang in the standby.

static void
ginRedoDeletePage(XLogReaderState *record)
{
XLogRecPtrlsn = record->EndRecPtr;
ginxlogDeletePage *data = (ginxlogDeletePage *) XLogRecGetData(record);
Bufferdbuffer;
Bufferpbuffer;
Bufferlbuffer;
Pagepage;

if (XLogReadBufferForRedo(record, 0, &dbuffer) == BLK_NEEDS_REDO)
{
page = BufferGetPage(dbuffer);
Assert(GinPageIsData(page));
GinPageGetOpaque(page)->flags = GIN_DELETED;
PageSetLSN(page, lsn);
MarkBufferDirty(dbuffer);
}

if (XLogReadBufferForRedo(record, 1, &pbuffer) == BLK_NEEDS_REDO)
{
page = BufferGetPage(pbuffer);
Assert(GinPageIsData(page));
Assert(!GinPageIsLeaf(page));
GinPageDeletePostingItem(page, data->parentOffset);
PageSetLSN(page, lsn);
MarkBufferDirty(pbuffer);
}

if (XLogReadBufferForRedo(record, 2, &lbuffer) == BLK_NEEDS_REDO)
{
page = BufferGetPage(lbuffer);
Assert(GinPageIsData(page));
GinPageGetOpaque(page)->rightlink = data->rightLink;
PageSetLSN(page, lsn);
MarkBufferDirty(lbuffer);
}

if (BufferIsValid(lbuffer))
UnlockReleaseBuffer(lbuffer);
if (BufferIsValid(pbuffer))
UnlockReleaseBuffer(pbuffer);
if (BufferIsValid(dbuffer))
UnlockReleaseBuffer(dbuffer);
}

The order of get lwlock in ginRedoDeletePage() may should be change from "dbuffer->pbuffer->lbuffer" to "lbuffer->dbuffer->pbuffer" . Is this right?

## How to reproduct this issue

1. modify ginxlog.c and build(add "sleep(60)" )

if (XLogReadBufferForRedo(record, 1, &pbuffer) == BLK_NEEDS_REDO)
{
page = BufferGetPage(pbuffer);
Assert(GinPageIsData(page));
Assert(!GinPageIsLeaf(page));
GinPageDeletePostingItem(page, data->parentOffset);
PageSetLSN(page, lsn);
MarkBufferDirty(pbuffer);
}
==>
if (XLogReadBufferForRedo(record, 1, &pbuffer) == BLK_NEEDS_REDO)
{
page = BufferGetPage(pbuffer);
Assert(GinPageIsData(page));
Assert(!GinPageIsLeaf(page));
GinPageDeletePostingItem(page, data->parentOffset);
PageSetLSN(page, lsn);
MarkBufferDirty(pbuffer);
sleep(60);//add for debug
}

2. run test SQL on the primary

create table tb1(id int);
create index ON tb1 using gin(id);
insert into tb1 select 1 from generate_series(1,1000000)id;
delete from tb1;

3. check recovery process in standby had enter "sleep()" branch

$ ps -ef|grep reco
postgres 13418 13417 0 22:23 ? 00:00:00 postgres: startup process recovering 00000001000000000000005E
postgres 13425 31505 0 22:23 pts/8 00:00:00 grep --color=auto reco
$ pstack 13418
#0 0x00007f2166d39650 in __nanosleep_nocancel () from /lib64/libc.so.6
#1 0x00007f2166d39504 in sleep () from /lib64/libc.so.6
#2 0x000000000048614f in ginRedoDeletePage (record=0x127cbe8) at ginxlog.c:480
#3 gin_redo (record=0x127cbe8) at ginxlog.c:732
#4 0x00000000004efec3 in StartupXLOG ()
#5 0x0000000000697c51 in StartupProcessMain ()
#6 0x00000000004fd22a in AuxiliaryProcessMain ()
#7 0x0000000000694e49 in StartChildProcess ()
#8 0x0000000000697665 in PostmasterMain ()
#9 0x00000000004766e1 in main ()

4. execute select SQL

set enable_seqscan = false;
select count(*) from tb1 where id =2;

5. check result

recovery process block in LWLock

$ pstack 13418
#0 0x00007f216775779b in do_futex_wait.constprop.1 () from /lib64/libpthread.so.0
#1 0x00007f216775782f in __new_sem_wait_slow.constprop.0 () from /lib64/libpthread.so.0
#2 0x00007f21677578cb in sem_wait@@GLIBC_2.2.5 () from /lib64/libpthread.so.0
#3 0x0000000000685df2 in PGSemaphoreLock ()
#4 0x00000000006edd64 in LWLockAcquire ()
#5 0x00000000004fa66a in XLogReadBufferForRedoExtended ()
#6 0x0000000000486161 in ginRedoDeletePage (record=0x127cbe8) at ginxlog.c:483
#7 gin_redo (record=0x127cbe8) at ginxlog.c:732
#8 0x00000000004efec3 in StartupXLOG ()
#9 0x0000000000697c51 in StartupProcessMain ()
#10 0x00000000004fd22a in AuxiliaryProcessMain ()
#11 0x0000000000694e49 in StartChildProcess ()
#12 0x0000000000697665 in PostmasterMain ()
#13 0x00000000004766e1 in main ()

and select also block in LWLock(deadlock ocuurs)

postgres=# select pid,wait_event_type,wait_event,state,query from pg_stat_activity where state<>'idle';
pid | wait_event_type | wait_event | state | query
-------+-----------------+----------------+--------+----------------------------------------------------------------------------------------------
13472 | LWLock | buffer_content | active | select count(*) from tb1 where id =1;
13526 | | | active | select pid,wait_event_type,wait_event,state,query from pg_stat_activity where state<>'idle';
(2 rows)

## appendix
### select process gcore analysis
---------------------------------------------------------------
[New LWP 14468]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `postgres: lma lma 10.246.5.80(54684) SELECT'.
#0 0x00007f7aaf72a79b in do_futex_wait.constprop.1 () from /lib64/libpthread.so.0
Missing separate debuginfos, use: debuginfo-install audit-libs-2.6.5-3.el7.x86_64 bzip2-libs-1.0.6-13.el7.x86_64 cyrus-sasl-lib-2.1.26-20.el7_2.x86_64 elfutils-libelf-0.166-2.el7.x86_64 elfutils-libs-0.166-2.el7.x86_64 glibc-2.17-157.el7.x86_64 keyutils-libs-1.5.8-3.el7.x86_64 krb5-libs-1.14.1-26.el7.x86_64 libattr-2.4.46-12.el7.x86_64 libcap-2.22-8.el7.x86_64 libcap-ng-0.7.5-4.el7.x86_64 libcom_err-1.42.9-9.el7.x86_64 libcurl-7.29.0-35.el7.centos.x86_64 libgcc-4.8.5-11.el7.x86_64 libgcrypt-1.5.3-12.el7_1.1.x86_64 libgpg-error-1.12-3.el7.x86_64 libicu-50.1.2-15.el7.x86_64 libidn-1.28-4.el7.x86_64 libselinux-2.5-6.el7.x86_64 libssh2-1.4.3-10.el7_2.1.x86_64 libstdc++-4.8.5-11.el7.x86_64 libxml2-2.9.1-6.el7_2.3.x86_64 nspr-4.11.0-1.el7_2.x86_64 nss-3.21.0-17.el7.x86_64 nss-softokn-freebl-3.16.2.3-14.4.el7.x86_64 nss-util-3.21.0-2.2.el7_2.x86_64 openldap-2.4.40-13.el7.x86_64 openssl-libs-1.0.1e-60.el7.x86_64 pam-1.1.8-18.el7.x86_64 pcre-8.32-15.el7_2.1.x86_64 systemd-libs-219-30.el7.x86_64 xz-libs-5.2.2-1.el7.x86_64 zlib-1.2.7-17.el7.x86_64
(gdb) bt
#0 0x00007f7aaf72a79b in do_futex_wait.constprop.1 () from /lib64/libpthread.so.0
#1 0x00007f7aaf72a82f in __new_sem_wait_slow.constprop.0 () from /lib64/libpthread.so.0
#2 0x00007f7aaf72a8cb in sem_wait@@GLIBC_2.2.5 () from /lib64/libpthread.so.0
#3 0x000000000069d362 in PGSemaphoreLock (sema=0x2aaaaac072d8) at pg_sema.c:310
#4 0x00000000007095ac in LWLockAcquire (lock=0x2aaab45158a4, mode=LW_SHARED) at lwlock.c:1233
#5 0x0000000000490a32 in ginStepRight (buffer=366260, index=<optimized out>, lockmode=lockmode(at)entry=1) at ginbtree.c:174
#6 0x000000000049253c in entryLoadMoreItems (ginstate=0x1da3ad0, snapshot=0x167c798, advancePast=..., entry=0x159e218) at ginget.c:677
#7 entryGetItem (ginstate=ginstate(at)entry=0x1da3ad0, entry=entry(at)entry=0x159e218, advancePast=..., snapshot=snapshot(at)entry=0x167c798) at ginget.c:867
#8 0x0000000000493f21 in keyGetItem (snapshot=0x167c798, advancePast=..., key=<optimized out>, tempCtx=0x107ea68, ginstate=<optimized out>) at ginget.c:953
#9 scanGetItem (scan=<optimized out>, scan=<optimized out>, recheck=<synthetic pointer>, item=0x7fff550db820, advancePast=...) at ginget.c:1222
#10 gingetbitmap (scan=<optimized out>, tbm=<optimized out>) at ginget.c:1837
#11 0x00000000004c245a in index_getbitmap (scan=scan(at)entry=0x2236168, bitmap=bitmap(at)entry=0x2240f08) at indexam.c:726
#12 0x0000000000600c52 in MultiExecBitmapIndexScan (node=0x22358e8) at nodeBitmapIndexscan.c:104
#13 0x00000000005f40b9 in MultiExecProcNode (node=<optimized out>) at execProcnode.c:490
#14 0x00000000006004c7 in BitmapHeapNext (node=node(at)entry=0x1ec9788) at nodeBitmapHeapscan.c:117
#15 0x00000000005f5094 in ExecScanFetch (recheckMtd=0x5ff990 <BitmapHeapRecheck>, accessMtd=0x5ffa20 <BitmapHeapNext>, node=0x1ec9788) at execScan.c:97
#16 ExecScan (node=0x1ec9788, accessMtd=0x5ffa20 <BitmapHeapNext>, recheckMtd=0x5ff990 <BitmapHeapRecheck>) at execScan.c:164
#17 0x000000000060e10c in ExecProcNode (node=0x1ec9788) at ../../../src/include/executor/executor.h:250
#18 ExecNestLoop (pstate=0x1ec73c0) at nodeNestloop.c:160
#19 0x000000000060e05f in ExecProcNode (node=0x1ec73c0) at ../../../src/include/executor/executor.h:250
#20 ExecNestLoop (pstate=0x1ec7200) at nodeNestloop.c:109
#21 0x0000000000610636 in ExecProcNode (node=0x1ec7200) at ../../../src/include/executor/executor.h:250
#22 ExecSort (pstate=0x1ec6f90) at nodeSort.c:106
#23 0x00000000005fad89 in ExecProcNode (node=0x1ec6f90) at ../../../src/include/executor/executor.h:250
#24 fetch_input_tuple (aggstate=aggstate(at)entry=0x1ec6948) at nodeAgg.c:695
#25 0x00000000005fcf27 in agg_retrieve_direct (aggstate=0x1ec6948) at nodeAgg.c:2347
#26 ExecAgg (pstate=0x1ec6948) at nodeAgg.c:2158
#27 0x00000000005faa42 in ExecProcNode (node=0x1ec6948) at ../../../src/include/executor/executor.h:250
#28 ExecAppend (pstate=0x20843e8) at nodeAppend.c:222
#29 0x000000000060eee9 in ExecProcNode (node=0x20843e8) at ../../../src/include/executor/executor.h:250
#30 ExecResult (pstate=0x2084178) at nodeResult.c:115
#31 0x0000000000610636 in ExecProcNode (node=0x2084178) at ../../../src/include/executor/executor.h:250
#32 ExecSort (pstate=0x2083f08) at nodeSort.c:106
#33 0x0000000000607cfd in ExecProcNode (node=0x2083f08) at ../../../src/include/executor/executor.h:250
#34 ExecLimit (pstate=0x2083798) at nodeLimit.c:95
#35 0x00000000005ef612 in ExecProcNode (node=0x2083798) at ../../../src/include/executor/executor.h:250
#36 ExecutePlan (execute_once=<optimized out>, dest=0x10e34f8, direction=<optimized out>, numberTuples=0, sendTuples=1 '\001', operation=CMD_SELECT, use_parallel_mode=<optimized out>,
planstate=0x2083798, estate=0x20834e8) at execMain.c:1722
#37 standard_ExecutorRun (queryDesc=0x197b6e0, direction=<optimized out>, count=0, execute_once=<optimized out>) at execMain.c:363
---Type <return> to continue, or q <return> to quit---
#38 0x00007f7aa028415d in pgss_ExecutorRun (queryDesc=0x197b6e0, direction=ForwardScanDirection, count=0, execute_once=<optimized out>) at pg_stat_statements.c:889
#39 0x000000000071a28b in PortalRunSelect (portal=portal(at)entry=0x1112198, forward=forward(at)entry=1 '\001', count=0, count(at)entry=9223372036854775807, dest=dest(at)entry=0x10e34f8) at pquery.c:932
#40 0x000000000071b63f in PortalRun (portal=<optimized out>, count=9223372036854775807, isTopLevel=<optimized out>, run_once=<optimized out>, dest=0x10e34f8, altdest=0x10e34f8,
completionTag=0x7fff550dc220 "") at pquery.c:773
#41 0x0000000000718f84 in PostgresMain (argc=<optimized out>, argv=<optimized out>, dbname=<optimized out>, username=<optimized out>) at postgres.c:1984
#42 0x000000000047ad3c in BackendRun (port=0x106a590) at postmaster.c:4405
#43 BackendStartup (port=0x106a590) at postmaster.c:4077
#44 ServerLoop () at postmaster.c:1755
#45 0x00000000006afacf in PostmasterMain (argc=argc(at)entry=1, argv=argv(at)entry=0x101ba20) at postmaster.c:1363
#46 0x000000000047bb6f in main (argc=1, argv=0x101ba20) at main.c:228
(gdb) p num_held_lwlocks
$1 = 1
(gdb) p held_lwlocks
$2 = {{lock = 0x2aaaad50e2e4, mode = LW_SHARED}, {lock = 0x2aaaaac09e80, mode = LW_SHARED}, {lock = 0x2aaaaac09280, mode = LW_EXCLUSIVE}, {lock = 0x2aaaaac09280, mode = LW_EXCLUSIVE}, {
lock = 0x0, mode = LW_EXCLUSIVE} <repeats 196 times>}
(gdb) f 5
#5 0x0000000000490a32 in ginStepRight (buffer=366260, index=<optimized out>, lockmode=lockmode(at)entry=1) at ginbtree.c:174
174LockBuffer(nextbuffer, lockmode);
(gdb) p ((LWLock*) (&((&BufferDescriptors[(366260 - 1)].bufferdesc))->content_lock))
$3 = (LWLock *) 0x2aaaad50e2e4
(gdb) p nextbuffer
$4 = 2201739
(gdb) p ((LWLock*) (&((&BufferDescriptors[(2201739 - 1)].bufferdesc))->content_lock))
$5 = (LWLock *) 0x2aaab45158a4
#6 0x000000000049253c in entryLoadMoreItems (ginstate=0x1da3ad0, snapshot=0x167c798, advancePast=..., entry=0x159e218) at ginget.c:677
677entry->buffer = ginStepRight(entry->buffer,
(gdb) p *entry
$2 = {queryKey = 20181026, queryCategory = 0 '\000', isPartialMatch = 0 '\000', extra_data = 0x159e170 "\003", strategy = 3, searchMode = 0, attnum = 1,
buffer = 366260, curItem = {ip_blkid = {bi_hi = 0, bi_lo = 0}, ip_posid = 0}, matchBitmap = 0x0, matchIterator = 0x0, matchResult = 0x0, list = 0x0, nlist = 0,
offset = 0, isFinished = 0 '\000', reduceResult = 0 '\000', predictNumberResult = 0, btree = {findChildPage = 0x48d890 <dataLocateItem>,
getLeftMostChild = 0x48db40 <dataGetLeftMostPage>, isMoveRight = 0x48d830 <dataIsMoveRight>, findItem = 0x0, findChildPtr = 0x48da10 <dataFindChildPtr>,
beginPlaceToPage = 0x48e320 <dataBeginPlaceToPage>, execPlaceToPage = 0x48f4c0 <dataExecPlaceToPage>, prepareDownlink = 0x48dfd0 <dataPrepareDownlink>,
fillRoot = 0x48f420 <ginDataFillRoot>, isData = 1 '\001', index = 0x11f1b08, rootBlkno = 2246, ginstate = 0x0, fullScan = 1 '\001', isBuild = 0 '\000',
entryAttnum = 0, entryKey = 0, entryCategory = 0 '\000', itemptr = {ip_blkid = {bi_hi = 0, bi_lo = 0}, ip_posid = 0}}}
---------------------------------------------------------------

### recovery process gcore analysis
---------------------------------------------------------------
[New LWP 37811]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `postgres: startup process recovering 000000040001042900000050'.
#0 0x00007f7aaf72a79b in do_futex_wait.constprop.1 () from /lib64/libpthread.so.0
Missing separate debuginfos, use: debuginfo-install audit-libs-2.6.5-3.el7.x86_64 bzip2-libs-1.0.6-13.el7.x86_64 cyrus-sasl-lib-2.1.26-20.el7_2.x86_64 elfutils-libelf-0.166-2.el7.x86_64 elfutils-libs-0.166-2.el7.x86_64 glibc-2.17-157.el7.x86_64 keyutils-libs-1.5.8-3.el7.x86_64 krb5-libs-1.14.1-26.el7.x86_64 libattr-2.4.46-12.el7.x86_64 libcap-2.22-8.el7.x86_64 libcap-ng-0.7.5-4.el7.x86_64 libcom_err-1.42.9-9.el7.x86_64 libcurl-7.29.0-35.el7.centos.x86_64 libgcc-4.8.5-11.el7.x86_64 libgcrypt-1.5.3-12.el7_1.1.x86_64 libgpg-error-1.12-3.el7.x86_64 libicu-50.1.2-15.el7.x86_64 libidn-1.28-4.el7.x86_64 libselinux-2.5-6.el7.x86_64 libssh2-1.4.3-10.el7_2.1.x86_64 libstdc++-4.8.5-11.el7.x86_64 libxml2-2.9.1-6.el7_2.3.x86_64 nspr-4.11.0-1.el7_2.x86_64 nss-3.21.0-17.el7.x86_64 nss-softokn-freebl-3.16.2.3-14.4.el7.x86_64 nss-util-3.21.0-2.2.el7_2.x86_64 openldap-2.4.40-13.el7.x86_64 openssl-libs-1.0.1e-60.el7.x86_64 pam-1.1.8-18.el7.x86_64 pcre-8.32-15.el7_2.1.x86_64 systemd-libs-219-30.el7.x86_64 xz-libs-5.2.2-1.el7.x86_64 zlib-1.2.7-17.el7.x86_64
(gdb) bt
#0 0x00007f7aaf72a79b in do_futex_wait.constprop.1 () from /lib64/libpthread.so.0
#1 0x00007f7aaf72a82f in __new_sem_wait_slow.constprop.0 () from /lib64/libpthread.so.0
#2 0x00007f7aaf72a8cb in sem_wait@@GLIBC_2.2.5 () from /lib64/libpthread.so.0
#3 0x000000000069d362 in PGSemaphoreLock (sema=0x2aaaaac07ff8) at pg_sema.c:310
#4 0x00000000007095ac in LWLockAcquire (lock=0x2aaaad50e2e4, mode=LW_EXCLUSIVE) at lwlock.c:1233
#5 0x0000000000503c1a in XLogReadBufferForRedoExtended (record=record(at)entry=0x105ce58, block_id=block_id(at)entry=2 '\002', mode=mode(at)entry=RBM_NORMAL,
get_cleanup_lock=get_cleanup_lock(at)entry=0 '\000', buf=buf(at)entry=0x7fff550d93c0) at xlogutils.c:399
#6 0x0000000000503d00 in XLogReadBufferForRedo (record=record(at)entry=0x105ce58, block_id=block_id(at)entry=2 '\002', buf=buf(at)entry=0x7fff550d93c0) at xlogutils.c:293
#7 0x000000000048bcd5 in ginRedoDeletePage (record=0x105ce58) at ginxlog.c:482
#8 gin_redo (record=0x105ce58) at ginxlog.c:731
#9 0x00000000004f8b83 in StartupXLOG () at xlog.c:7183
#10 0x00000000006b0091 in StartupProcessMain () at startup.c:217
#11 0x000000000050689a in AuxiliaryProcessMain (argc=argc(at)entry=2, argv=argv(at)entry=0x7fff550dcbe0) at bootstrap.c:426
#12 0x00000000006ad160 in StartChildProcess (type=StartupProcess) at postmaster.c:5361
#13 0x00000000006afaab in PostmasterMain (argc=argc(at)entry=1, argv=argv(at)entry=0x101ba20) at postmaster.c:1355
#14 0x000000000047bb6f in main (argc=1, argv=0x101ba20) at main.c:228
(gdb) p num_held_lwlocks
$1 = 2
(gdb) p held_lwlocks
$2 = {{lock = 0x2aaab45158a4, mode = LW_EXCLUSIVE}, {lock = 0x2aaac6c081e4, mode = LW_EXCLUSIVE}, {lock = 0x2aaaaac0a780, mode = LW_SHARED}, {lock = 0x2aaabf16e7e4, mode = LW_EXCLUSIVE}, {
lock = 0x2aaaaac08a00, mode = LW_EXCLUSIVE}, {lock = 0x0, mode = LW_EXCLUSIVE} <repeats 195 times>}
(gdb) f 7
#7 0x000000000048bcd5 in ginRedoDeletePage (record=0x105ce58) at ginxlog.c:482
482if (XLogReadBufferForRedo(record, 2, &lbuffer) == BLK_NEEDS_REDO)
(gdb) p *record
$6 = {read_page = 0x4f40f0 <XLogPageRead>, system_identifier = 6605939872368807293, private_data = 0x7fff550d94a0, ReadRecPtr = 286050462744944, EndRecPtr = 286050462745016,
decoded_record = 0x105dfd8, main_data = 0x11026f8 "\002", main_data_len = 8, main_data_bufsz = 53792, record_origin = 0, blocks = {{in_use = 1 '\001', rnode = {spcNode = 1663,
dbNode = 16400, relNode = 2079769372}, forknum = MAIN_FORKNUM, blkno = 483, flags = 0 '\000', has_image = 0 '\000', apply_image = 0 '\000', bkp_image = 0x105e7d5 "\232\204",
hole_offset = 256, hole_length = 7680, bimg_len = 222, bimg_info = 7 '\a', has_data = 0 '\000', data = 0x1084ea8 "", data_len = 0, data_bufsz = 8100}, {in_use = 1 '\001', rnode = {
spcNode = 1663, dbNode = 16400, relNode = 2079769372}, forknum = MAIN_FORKNUM, blkno = 2246, flags = 128 '\200', has_image = 0 '\000', apply_image = 0 '\000',
bkp_image = 0x10b9168 "", hole_offset = 4084, hole_length = 4100, bimg_len = 4092, bimg_info = 5 '\005', has_data = 0 '\000', data = 0x1081a58 "\001", data_len = 0,
data_bufsz = 4496}, {in_use = 1 '\001', rnode = {spcNode = 1663, dbNode = 16400, relNode = 2079769372}, forknum = MAIN_FORKNUM, blkno = 3253, flags = 128 '\200', has_image = 0 '\000',
apply_image = 0 '\000',
bkp_image = 0x10b943f "\001\351\017\021\203\020\361\017\201\020\377\017\374\017\n\003\003\002\210\020\345\037\025\003\352\017\227\020\364\037\361\037\233\020\362\017\022\200\020\354\037\t\360/\027\351\017\002\016\203\020\370\017\001\001\367\017\021\001\361\017\r\364\017\020\365\017\003\200\020\003\205\020\357\017\374\017", hole_offset = 500, hole_length = 60,
bimg_len = 1421, bimg_info = 7 '\a', has_data = 0 '\000', data = 0x1083da8 "\234\001", data_len = 0, data_bufsz = 16}, {in_use = 0 '\000', rnode = {spcNode = 1663, dbNode = 16400,
relNode = 2080872819}, forknum = MAIN_FORKNUM, blkno = 6758, flags = 192 '\300', has_image = 0 '\000', apply_image = 0 '\000', bkp_image = 0x0, hole_offset = 0, hole_length = 0,
bimg_len = 0, bimg_info = 0 '\000', has_data = 0 '\000', data = 0x0, data_len = 0, data_bufsz = 0}, {in_use = 0 '\000', rnode = {spcNode = 1663, dbNode = 16400, relNode = 2080872819},
forknum = MAIN_FORKNUM, blkno = 6780, flags = 192 '\300', has_image = 0 '\000', apply_image = 0 '\000', bkp_image = 0x0, hole_offset = 0, hole_length = 0, bimg_len = 0,
bimg_info = 0 '\000', has_data = 0 '\000', data = 0x10e7038 "\017\001", data_len = 0, data_bufsz = 16}, {in_use = 0 '\000', rnode = {spcNode = 1663, dbNode = 16400,
relNode = 2080872819}, forknum = MAIN_FORKNUM, blkno = 6781, flags = 192 '\300', has_image = 0 '\000', apply_image = 0 '\000', bkp_image = 0x0, hole_offset = 0, hole_length = 0,
bimg_len = 0, bimg_info = 0 '\000', has_data = 0 '\000', data = 0x0, data_len = 0, data_bufsz = 0}, {in_use = 0 '\000', rnode = {spcNode = 1663, dbNode = 16400, relNode = 2080872819},
forknum = MAIN_FORKNUM, blkno = 6792, flags = 192 '\300', has_image = 0 '\000', apply_image = 0 '\000', bkp_image = 0x0, hole_offset = 0, hole_length = 0, bimg_len = 0,
bimg_info = 0 '\000', has_data = 0 '\000', data = 0x0, data_len = 0, data_bufsz = 0}, {in_use = 0 '\000', rnode = {spcNode = 1663, dbNode = 16400, relNode = 2080872819},
forknum = MAIN_FORKNUM, blkno = 6824, flags = 192 '\300', has_image = 0 '\000', apply_image = 0 '\000', bkp_image = 0x0, hole_offset = 0, hole_length = 0, bimg_len = 0,
bimg_info = 0 '\000', has_data = 0 '\000', data = 0x0, data_len = 0, data_bufsz = 0}, {in_use = 0 '\000', rnode = {spcNode = 1663, dbNode = 16400, relNode = 2080872819},
forknum = MAIN_FORKNUM, blkno = 6832, flags = 192 '\300', has_image = 0 '\000', apply_image = 0 '\000', bkp_image = 0x0, hole_offset = 0, hole_length = 0, bimg_len = 0,
bimg_info = 0 '\000', has_data = 0 '\000', data = 0x0, data_len = 0, data_bufsz = 0}, {in_use = 0 '\000', rnode = {spcNode = 1663, dbNode = 16400, relNode = 2080872819},
forknum = MAIN_FORKNUM, blkno = 6833, flags = 192 '\300', has_image = 0 '\000', apply_image = 0 '\000', bkp_image = 0x0, hole_offset = 0, hole_length = 0, bimg_len = 0,
bimg_info = 0 '\000', has_data = 0 '\000', data = 0x0, data_len = 0, data_bufsz = 0}, {in_use = 0 '\000', rnode = {spcNode = 1663, dbNode = 16400, relNode = 2080872819},
forknum = MAIN_FORKNUM, blkno = 6903, flags = 192 '\300', has_image = 0 '\000', apply_image = 0 '\000', bkp_image = 0x0, hole_offset = 0, hole_length = 0, bimg_len = 0,
bimg_info = 0 '\000', has_data = 0 '\000', data = 0x0, data_len = 0, data_bufsz = 0}, {in_use = 0 '\000', rnode = {spcNode = 1663, dbNode = 16400, relNode = 2080872819},
forknum = MAIN_FORKNUM, blkno = 262, flags = 192 '\300', has_image = 0 '\000', apply_image = 0 '\000', bkp_image = 0x0, hole_offset = 0, hole_length = 0, bimg_len = 0,
bimg_info = 0 '\000', has_data = 0 '\000', data = 0x0, data_len = 0, data_bufsz = 0}, {in_use = 0 '\000', rnode = {spcNode = 1663, dbNode = 16400, relNode = 2080872819},
forknum = MAIN_FORKNUM, blkno = 8759, flags = 192 '\300', has_image = 0 '\000', apply_image = 0 '\000', bkp_image = 0x0, hole_offset = 0, hole_length = 0, bimg_len = 0,
bimg_info = 0 '\000', has_data = 0 '\000', data = 0x0, data_len = 0, data_bufsz = 0}, {in_use = 0 '\000', rnode = {spcNode = 1663, dbNode = 16400, relNode = 2080872819},
forknum = MAIN_FORKNUM, blkno = 8766, flags = 192 '\300', has_image = 0 '\000', apply_image = 0 '\000', bkp_image = 0x0, hole_offset = 0, hole_length = 0, bimg_len = 0,
bimg_info = 0 '\000', has_data = 0 '\000', data = 0x0, data_len = 0, data_bufsz = 0}, {in_use = 0 '\000', rnode = {spcNode = 1663, dbNode = 16400, relNode = 2080872819},
forknum = MAIN_FORKNUM, blkno = 8927, flags = 192 '\300', has_image = 0 '\000', apply_image = 0 '\000', bkp_image = 0x0, hole_offset = 0, hole_length = 0, bimg_len = 0,
bimg_info = 0 '\000', has_data = 0 '\000', data = 0x0, data_len = 0, data_bufsz = 0}, {in_use = 0 '\000', rnode = {spcNode = 1663, dbNode = 16400, relNode = 2080872819},
forknum = MAIN_FORKNUM, blkno = 8941, flags = 192 '\300', has_image = 0 '\000', apply_image = 0 '\000', bkp_image = 0x0, hole_offset = 0, hole_length = 0, bimg_len = 0,
bimg_info = 0 '\000', has_data = 0 '\000', data = 0x0, data_len = 0, data_bufsz = 0}, {in_use = 0 '\000', rnode = {spcNode = 1663, dbNode = 16400, relNode = 2080872819},
forknum = MAIN_FORKNUM, blkno = 9207, flags = 192 '\300', has_image = 0 '\000', apply_image = 0 '\000', bkp_image = 0x0, hole_offset = 0, hole_length = 0, bimg_len = 0,
bimg_info = 0 '\000', has_data = 0 '\000', data = 0x0, data_len = 0, data_bufsz = 0}, {in_use = 0 '\000', rnode = {spcNode = 0, dbNode = 0, relNode = 0}, forknum = MAIN_FORKNUM,
---Type <return> to continue, or q <return> to quit---
blkno = 0, flags = 0 '\000', has_image = 0 '\000', apply_image = 0 '\000', bkp_image = 0x0, hole_offset = 0, hole_length = 0, bimg_len = 0, bimg_info = 0 '\000', has_data = 0 '\000',
data = 0x0, data_len = 0, data_bufsz = 0} <repeats 16 times>}, max_block_id = 2, readBuf = 0x105de68 "\227\320\005", readLen = 8192, readSegNo = 17049936, readOff = 3686400,
readPageTLI = 4, latestPagePtr = 286050462744576, latestPageTLI = 4, currRecPtr = 286050462744944, currTLI = 0, currTLIValidUntil = 0, nextTLI = 0, readRecordBuf = 0x10b80f8 "F",
readRecordBufSize = 57344, errormsg_buf = 0x105fe78 ""}
#7 0x000000000048bcd5 in ginRedoDeletePage (record=0x105ce58) at ginxlog.c:482
482if (XLogReadBufferForRedo(record, 2, &lbuffer) == BLK_NEEDS_REDO)
(gdb) p dbuffer
$1 = 2201739
(gdb) p pbuffer
$2 = 7034160
(gdb) p lbuffer
$3 = 366260
(gdb) p ((LWLock*) (&((&BufferDescriptors[(2201739 - 1)].bufferdesc))->content_lock))
$4 = (LWLock *) 0x2aaab45158a4
(gdb) p ((LWLock*) (&((&BufferDescriptors[(7034160 - 1)].bufferdesc))->content_lock))
$5 = (LWLock *) 0x2aaac6c081e4
(gdb) p ((LWLock*) (&((&BufferDescriptors[(366260 - 1)].bufferdesc))->content_lock))
$6 = (LWLock *) 0x2aaaad50e2e4
---------------------------------------------------------------

Regard,
Chen Huajun

In response to

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Kuntal Ghosh 2018-11-11 18:24:51 Re: zheap: a new storage format for PostgreSQL
Previous Message chenhj 2018-11-11 17:10:32 Re:Re: Connections hang indefinitely while taking a gin index's LWLock buffer_content lock