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

classic Classic list List threaded Threaded
23 messages Options
12
Reply | Threaded
Open this post in threaded view
|

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

chenhj
Hi,all

In our PostgreSQL 10.2 database, two sessions of insert and autovacuum of gin index blocked in LWLock:buffer_content.
This blocked checkpoint and dead tuple recycle,and we had to restart the datebase.
According to the information collected from gcore, a deadlock occurred when acquiring the buffer lock.

This system is a citus 7.2.1 cluster. It has been running for more than a year. This problem has not happened before. 
10/19 the cluster has been expanded from 8 workers to 16 workers. I don't know if it has anything to do with expansion. 
The problem happend on the coordinator node of citus, but the table is an normal table(not partition table).
And the load of this coordinator node has always been heavy.

After 10/25 this issue occurred three times in the 4 days, but we can not reproduce this problem in test environment.
3 faults are stuck on 3 different tables, but the stack is the same.

## stack of insert:Acquire lock 0x2aaab4009564 and hold 0x2aaab670dfe4, 0x2aaac587ae64
----------------------------------------------------------------------------
    (gdb) bt
    #0  0x00007fe11552379b in do_futex_wait.constprop.1 () from /lib64/libpthread.so.0
    #1  0x00007fe11552382f in __new_sem_wait_slow.constprop.0 () from /lib64/libpthread.so.0
    #2  0x00007fe1155238cb in sem_wait@@GLIBC_2.2.5 () from /lib64/libpthread.so.0
    #3  0x000000000069d362 in PGSemaphoreLock (sema=0x2aaaaac02958) at pg_sema.c:310
    #4  0x00000000007095ac in LWLockAcquire (lock=0x2aaab4009564, mode=LW_EXCLUSIVE) at lwlock.c:1233
    #5  0x0000000000490a32 in ginStepRight (buffer=6713826, index=<optimized out>, lockmode=lockmode@entry=2) at ginbtree.c:174
    #6  0x0000000000490c1c in ginFinishSplit (btree=btree@entry=0x7ffd81e4f950, stack=0x28eebf8, freestack=freestack@entry=1 '\001', buildStats=buildStats@entry=0x0) at ginbtree.c:701
    #7  0x0000000000491396 in ginInsertValue (btree=btree@entry=0x7ffd81e4f950, stack=<optimized out>, insertdata=insertdata@entry=0x7ffd81e4f940, buildStats=buildStats@entry=0x0)
        at ginbtree.c:773
    #8  0x000000000048fb42 in ginInsertItemPointers (index=<optimized out>, rootBlkno=rootBlkno@entry=644, items=items@entry=0x2916598, nitem=nitem@entry=353, buildStats=buildStats@entry=0x0)
        at gindatapage.c:1907
    #9  0x000000000048a9ea in ginEntryInsert (ginstate=ginstate@entry=0x28e7ef8, attnum=<optimized out>, key=42920440, category=<optimized out>, items=0x2916598, nitem=353, 
        buildStats=buildStats@entry=0x0) at gininsert.c:214
    #10 0x0000000000496d94 in ginInsertCleanup (ginstate=ginstate@entry=0x28e7ef8, full_clean=full_clean@entry=0 '\000', fill_fsm=fill_fsm@entry=1 '\001', 
        forceCleanup=forceCleanup@entry=0 '\000', stats=stats@entry=0x0) at ginfast.c:883
    #11 0x0000000000497727 in ginHeapTupleFastInsert (ginstate=ginstate@entry=0x28e7ef8, collector=collector@entry=0x7ffd81e4fe60) at ginfast.c:448
    #12 0x000000000048b209 in gininsert (index=<optimized out>, values=0x7ffd81e4ff40, isnull=0x7ffd81e50040 "", ht_ctid=0x280d98c, heapRel=<optimized out>, checkUnique=<optimized out>, 
        indexInfo=0x28b5aa8) at gininsert.c:522
    #13 0x00000000005ee8dd in ExecInsertIndexTuples (slot=slot@entry=0x28b5d58, tupleid=tupleid@entry=0x280d98c, estate=estate@entry=0x28b5288, noDupErr=noDupErr@entry=1 '\001', 
        specConflict=specConflict@entry=0x7ffd81e5013b "", arbiterIndexes=arbiterIndexes@entry=0x28c6dd8) at execIndexing.c:386
    #14 0x000000000060ccf5 in ExecInsert (canSetTag=1 '\001', estate=0x28b5288, onconflict=ONCONFLICT_UPDATE, arbiterIndexes=0x28c6dd8, planSlot=0x28b5d58, slot=0x28b5d58, mtstate=0x28b5628)
        at nodeModifyTable.c:564
    #15 ExecModifyTable (pstate=0x28b5628) at nodeModifyTable.c:1766
    #16 0x00000000005ef612 in standard_ExecutorRun (queryDesc=<optimized out>, direction=<optimized out>, count=<optimized out>, execute_once=<optimized out>)
        at ../../../src/include/executor/executor.h:250
    #17 0x00007fe10607d15d in pgss_ExecutorRun (queryDesc=0x28cc1d8, direction=ForwardScanDirection, count=0, execute_once=<optimized out>) at pg_stat_statements.c:889
    #18 0x000000000071a7ba in ProcessQuery (plan=<optimized out>, 
        sourceText=0x2849058 "INSERT INTO bi_dm.tdm_sncity_workorder_analytic_statistics (CITYCODE,CITYNAME,DISTRICT,DISTRICT_NAME,ZL_WERKS,ZL_WERKS_NAME,AREA_CD,AREA_NM,ZSIZE,DEPT_CD,TMALL_FLG,ORDER_DATE,DISTRIBUTE,WORKORDER,FNSH"..., params=0x28b2260, queryEnv=0x0, dest=0xc9e2a0 <donothingDR>, completionTag=0x7ffd81e507b0 "") at pquery.c:161
    #19 0x000000000071a9f7 in PortalRunMulti (portal=portal@entry=0x289fdd8, isTopLevel=isTopLevel@entry=1 '\001', setHoldSnapshot=setHoldSnapshot@entry=0 '\000', dest=0xc9e2a0 <donothingDR>, 
        dest@entry=0x284d778, altdest=0xc9e2a0 <donothingDR>, altdest@entry=0x284d778, completionTag=completionTag@entry=0x7ffd81e507b0 "") at pquery.c:1286
    #20 0x000000000071b535 in PortalRun (portal=<optimized out>, count=1, isTopLevel=<optimized out>, run_once=<optimized out>, dest=0x284d778, altdest=0x284d778, 
        completionTag=0x7ffd81e507b0 "") at pquery.c:799
    #21 0x0000000000718f84 in PostgresMain (argc=<optimized out>, argv=<optimized out>, dbname=<optimized out>, username=<optimized out>) at postgres.c:1984
    #22 0x000000000047ad3c in BackendRun (port=0x27cbc40) at postmaster.c:4405
    #23 BackendStartup (port=0x27cbc40) at postmaster.c:4077
    #24 ServerLoop () at postmaster.c:1755
    #25 0x00000000006afacf in PostmasterMain (argc=argc@entry=3, argv=argv@entry=0x277ba20) at postmaster.c:1363
    #26 0x000000000047bb6f in main (argc=3, argv=0x277ba20) at main.c:228
    (gdb) f 4
    #4  0x00000000007095ac in LWLockAcquire (lock=0x2aaab4009564, mode=LW_EXCLUSIVE) at lwlock.c:1233
    1233 PGSemaphoreLock(proc->sem);
    (gdb) p num_held_lwlocks
    $16 = 2
    (gdb) p InterruptHoldoffCount
    $17 = 3
    (gdb) p held_lwlocks
    $18 = {{lock = 0x2aaab670dfe4, mode = LW_EXCLUSIVE}, {lock = 0x2aaac587ae64, mode = LW_EXCLUSIVE}, {lock = 0x2aaaaac0a380, mode = LW_SHARED}, {lock = 0x2aaab670a2e4, mode = LW_EXCLUSIVE}, {
        lock = 0x2aaab670a2e4, mode = LW_EXCLUSIVE}, {lock = 0x2aaab670a2e4, mode = LW_EXCLUSIVE}, {lock = 0x2aaab670a2e4, mode = LW_EXCLUSIVE}, {lock = 0x2aaab670a2e4, mode = LW_EXCLUSIVE}, {
        lock = 0x2aaab670a2e4, mode = LW_EXCLUSIVE}, {lock = 0x2aaab670a2e4, mode = LW_EXCLUSIVE}, {lock = 0x2aaaaac15a80, mode = LW_EXCLUSIVE}, {lock = 0x0, 
        mode = LW_EXCLUSIVE} <repeats 189 times>}


## stack of autovacuum:Acquire lock 0x2aaab670dfe4 and hold 0x2aaab4009564
--------------------------------------
    (gdb) bt
    #0  0x00007fe11552379b in do_futex_wait.constprop.1 () from /lib64/libpthread.so.0
    #1  0x00007fe11552382f in __new_sem_wait_slow.constprop.0 () from /lib64/libpthread.so.0
    #2  0x00007fe1155238cb in sem_wait@@GLIBC_2.2.5 () from /lib64/libpthread.so.0
    #3  0x000000000069d362 in PGSemaphoreLock (sema=0x2aaaaac07eb8) at pg_sema.c:310
    #4  0x00000000007095ac in LWLockAcquire (lock=0x2aaab670dfe4, mode=LW_EXCLUSIVE) at lwlock.c:1233
    #5  0x00000000004947ef in ginScanToDelete (gvs=gvs@entry=0x7ffd81e4d0f0, blkno=701, isRoot=isRoot@entry=0 '\000', parent=parent@entry=0x7ffd81e4c790, myoff=myoff@entry=37) at ginvacuum.c:262
    #6  0x0000000000494874 in ginScanToDelete (gvs=gvs@entry=0x7ffd81e4d0f0, blkno=blkno@entry=9954, isRoot=isRoot@entry=1 '\001', parent=parent@entry=0x7ffd81e4c790, myoff=myoff@entry=0)
        at ginvacuum.c:277
    #7  0x0000000000494ed1 in ginVacuumPostingTreeLeaves (gvs=gvs@entry=0x7ffd81e4d0f0, blkno=9954, isRoot=isRoot@entry=0 '\000') at ginvacuum.c:404
    #8  0x0000000000494e21 in ginVacuumPostingTreeLeaves (gvs=gvs@entry=0x7ffd81e4d0f0, blkno=644, isRoot=isRoot@entry=1 '\001') at ginvacuum.c:372
    #9  0x0000000000495540 in ginVacuumPostingTree (rootBlkno=<optimized out>, gvs=0x7ffd81e4d0f0) at ginvacuum.c:426
    #10 ginbulkdelete (info=0x7ffd81e4f720, stats=<optimized out>, callback=<optimized out>, callback_state=<optimized out>) at ginvacuum.c:649
    #11 0x00000000005e1194 in lazy_vacuum_index (indrel=0x3146e28, stats=stats@entry=0x28ec200, vacrelstats=vacrelstats@entry=0x28ebc28) at vacuumlazy.c:1621
    #12 0x00000000005e214d in lazy_scan_heap (aggressive=<optimized out>, nindexes=<optimized out>, Irel=<optimized out>, vacrelstats=<optimized out>, options=16, onerel=0x28ec1f8)
        at vacuumlazy.c:1311
    #13 lazy_vacuum_rel (onerel=onerel@entry=0x3144fa8, options=options@entry=99, params=params@entry=0x289f270, bstrategy=<optimized out>) at vacuumlazy.c:258
    #14 0x00000000005dfc35 in vacuum_rel (relid=relid@entry=2060396948, relation=relation@entry=0x7ffd81e4fe50, options=options@entry=99, params=params@entry=0x289f270) at vacuum.c:1463
    #15 0x00000000005e0ad2 in vacuum (options=99, relation=relation@entry=0x7ffd81e4fe50, relid=<optimized out>, params=params@entry=0x289f270, va_cols=va_cols@entry=0x0, 
        bstrategy=<optimized out>, bstrategy@entry=0x289e988, isTopLevel=isTopLevel@entry=1 '\001') at vacuum.c:306
    #16 0x00000000006a01ff in autovacuum_do_vac_analyze (bstrategy=0x289e988, tab=0x289f268) at autovacuum.c:3095
    #17 do_autovacuum () at autovacuum.c:2450
    #18 0x00000000006a06a9 in AutoVacWorkerMain (argv=0x0, argc=0) at autovacuum.c:1693
    #19 0x00000000006a0f49 in StartAutoVacWorker () at autovacuum.c:1498
    #20 0x00000000006aeaea in StartAutovacuumWorker () at postmaster.c:5462
    #21 sigusr1_handler (postgres_signal_arg=<optimized out>) at postmaster.c:5159
    #22 <signal handler called>
    #23 0x00007fe11334bb83 in __select_nocancel () from /lib64/libc.so.6
    #24 0x000000000047a3a3 in ServerLoop () at postmaster.c:1719
    #25 0x00000000006afacf in PostmasterMain (argc=argc@entry=3, argv=argv@entry=0x277ba20) at postmaster.c:1363
    #26 0x000000000047bb6f in main (argc=3, argv=0x277ba20) at main.c:228
    (gdb) f 4
    #4  0x00000000007095ac in LWLockAcquire (lock=0x2aaab670dfe4, mode=LW_EXCLUSIVE) at lwlock.c:1233
    1233 PGSemaphoreLock(proc->sem);
    (gdb) 
    (gdb)  p num_held_lwlocks
    $1 = 1
    (gdb) p InterruptHoldoffCount
    $2 = 2
    (gdb)  p held_lwlocks
    $3 = {{lock = 0x2aaab4009564, mode = LW_EXCLUSIVE}, {lock = 0x2aaaaac0aa00, mode = LW_SHARED}, {lock = 0x2aaaba8da364, mode = LW_EXCLUSIVE}, {lock = 0x2aaaaac15900, mode = LW_EXCLUSIVE}, {
        lock = 0x2aaab66eb064, mode = LW_EXCLUSIVE}, {lock = 0x2aaaaac15900, mode = LW_EXCLUSIVE}, {lock = 0x2aaaaac15c80, mode = LW_EXCLUSIVE}, {lock = 0x0, 
        mode = LW_EXCLUSIVE} <repeats 193 times>}
    
# env
- CentOS 7.3 64bit
- PostgreSQL 10.2(installed via rpm download from postgresql.org)

# application SQL

begin;
delete from bi_dm.tdm_sncity_workorder_analytic_statistics where order_date between '2018-10-09' and '2018-10-09';

INSERT INTO bi_dm.tdm_sncity_workorder_analytic_statistics (CITYCODE,CITYNAME,DISTRICT,DISTRICT_NAME,ZL_WERKS,ZL_WERKS_NAME,AREA_CD,AREA_NM,ZSIZE,DEPT_CD,TMALL_FLG,ORDER_DATE,DISTRIBUTE,WORKORDER,FNSH
WORKORDER,STATISFACTION_CHILD,STATISFACTION_MOTHER,ONLYONCE_FNSH,REPLY_1H,FNSH_24H,FNSH_48H,ETL_TIME,SALE_PTY,SALE_PTY_FLAG,VBELN_TP,DEALCOUNT_3,NOT_FNSH_NUM) VALUES($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11
,$12,$13,$14,$15,$16,$17,$18,$19,$20,$21,$22,$23,$24,$25,$26,$27) ON CONFLICT(order_date,citycode,cityname,district,district_name,zl_werks,zl_werks_name,area_cd,area_nm,zsize,dept_cd,tmall_flg,sale_pty
,sale_pty_flag,vbeln_tp) DO UPDATE SET CITYCODE = excluded.CITYCODE,CITYNAME = excluded.CITYNAME,DISTRICT = excluded.DISTRICT,DISTRICT_NAME = excluded.DISTRICT_NAME,ZL_WERKS = excluded.ZL_WERKS,
ZL_WERKS_NAME = excluded.ZL_WERKS_NAME,AREA_CD = excluded.AREA_CD,AREA_NM = excluded.AREA_NM,ZSIZE = excluded.ZSIZE,DEPT_CD = excluded.DEPT_CD,TMALL_FLG = excluded.TMALL_FLG,ORDER_DATE = 
excluded.ORDER_DATE,DISTRIBUTE = excluded.DISTRIBUTE,WORKORDER = excluded.WORKORDER,FNSHWORKORDER = excluded.FNSHWORKORDER,STATISFACTION_CHILD = excluded.STATISFACTION_CHILD,STATISFACTION_MOTHER = excluded.STATISFACTIOH_24H
,FNSH_48H = excluded.FNSH_48H,ETL_TIME = excluded.ETL_TIME,SALE_PTY = excluded.SALE_PTY,SALE_PTY_FLAG = excluded.SALE_PTY_FLAG,VBELN_TP = excluded.VBELN_TP,DEALCOUNT_3 = excluded.DEALCOUNT_3,
NOT_N_MOTHER,ONLYONCE_FNSH = excluded.ONLYONCE_FNSH,REPLY_1H = excluded.REPLY_1H,FNSH_24H = excluded.FNSH_24H,FNSH_48H = excluded.FNSH_48H,ETL_TIME = excluded.ETL_TIME,SALE_PTY = excluded.SALE_PTY,
SALE_PTY_FLAG = excluded.SALE_PTY_FLAG,VBELN_TP = excluded.VBELN_TP,DEALCOUNT_3 = excluded.DEALCOUNT_3,NOT_FNSH_NUM = excluded.NOT_FNSH_NUM 

-- use jdbc batch update to execute insert

commit;

# table def
db1=# \d bi_dm.tdm_sncity_workorder_analytic_statistics
             Table "bi_dm.tdm_sncity_workorder_analytic_statistics"
        Column        |          Type          | Collation | Nullable | Default
----------------------+------------------------+-----------+----------+---------
citycode             | character varying(100) |           |          |
cityname             | character varying(100) |           |          |
district             | character varying(100) |           |          |
district_name        | character varying(100) |           |          |
zl_werks             | character varying(100) |           |          |
zl_werks_name        | character varying(100) |           |          |
area_cd              | character varying(100) |           |          |
area_nm              | character varying(100) |           |          |
zsize                | character varying(100) |           |          |
dept_cd              | character varying(100) |           |          |
tmall_flg            | character varying(100) |           |          |
order_date           | character varying(100) |           |          |
distribute           | integer                |           |          |
workorder            | integer                |           |          |
fnshworkorder        | integer                |           |          |
statisfaction_child  | integer                |           |          |
statisfaction_mother | integer                |           |          |
onlyonce_fnsh        | integer                |           |          |
reply_1h             | integer                |           |          |
fnsh_24h             | integer                |           |          |
fnsh_48h             | integer                |           |          |
etl_time             | character varying(100) |           |          |
sale_pty             | character varying(100) |           |          |
sale_pty_flag        | character varying(100) |           |
vbeln_tp             | character varying(100) |           |          |
dealcount_3          | integer                |           |          |
not_fnsh_num         | integer                |           |          |
Indexes:
    "idx1_tdm_sncity_workorder_analytic_statistics" UNIQUE, btree (order_date, citycode, cityname, district, district_name, zl_werks, zl_werks_name, area_cd, area_nm, zsize, dept_cd, tmall_flg, sale_pty, sale_pty_flag, vbeln_tp)
    "gin_tdm_sncity_workorder_analytic_statistics" gin (order_date)

# another phenomenon

The above phenomenon just happened on the primary node. The standby node hang on another stack four times.

## stack of recovery process
--------------------------------------
#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@entry=0x105ce58, block_id=block_id@entry=2 '\002', mode=mode@entry=RBM_NORMAL, get_cleanup_lock=get_cleanup_lock@entry=0 '\000', buf=buf@entry=0x7fff550d93c0) at xlogutils.c:399
#6  0x0000000000503d00 in XLogReadBufferForRedo (record=record@entry=0x105ce58, block_id=block_id@entry=2 '\002', buf=buf@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@entry=2, argv=argv@entry=0x7fff550dcbe0) at bootstrap.c:426
#12 0x00000000006ad160 in StartChildProcess (type=StartupProcess) at postmaster.c:5361
#13 0x00000000006afaab in PostmasterMain (argc=argc@entry=1, argv=argv@entry=0x101ba20) at postmaster.c:1355
#14 0x000000000047bb6f in main (argc=1, argv=0x101ba20) at main.c:228

## stack of backend process(tens of such process)
--------------------------------------
#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=0x2aaaaac074b8) at pg_sema.c:310
#4  0x00000000007095ac in LWLockAcquire (lock=0x2aaac6c081e4, mode=LW_SHARED) at lwlock.c:1233
#5  0x0000000000490943 in ginTraverseLock (buffer=7034160, searchMode=searchMode@entry=1 '\001') at ginbtree.c:40
#6  0x00000000004910e0 in ginFindLeafPage (btree=btree@entry=0x1fd6318, searchMode=searchMode@entry=1 '\001', snapshot=snapshot@entry=0x200a958) at ginbtree.c:97
#7  0x000000000048fe5b in ginScanBeginPostingTree (btree=btree@entry=0x1fd6318, index=<optimized out>, rootBlkno=rootBlkno@entry=2246, snapshot=snapshot@entry=0x200a958) at gindatapage.c:1924
#8  0x000000000049319c in startScanEntry (ginstate=ginstate@entry=0x1eade90, entry=<optimized out>, snapshot=0x200a958) at ginget.c:390
#9  0x0000000000493a92 in startScan (scan=0x1e6c348, scan=0x1e6c348) at ginget.c:543
#10 gingetbitmap (scan=0x1e6c348, tbm=0x20df978) at ginget.c:1829
#11 0x00000000004c245a in index_getbitmap (scan=scan@entry=0x1e6c348, bitmap=bitmap@entry=0x20df978) at indexam.c:726
#12 0x0000000000600c52 in MultiExecBitmapIndexScan (node=0x1ebfcd0) at nodeBitmapIndexscan.c:104
#13 0x00000000005f40b9 in MultiExecProcNode (node=<optimized out>) at execProcnode.c:490
#14 0x00000000006004c7 in BitmapHeapNext (node=node@entry=0x1a0c618) at nodeBitmapHeapscan.c:117
#15 0x00000000005f5094 in ExecScanFetch (recheckMtd=0x5ff990 <BitmapHeapRecheck>, accessMtd=0x5ffa20 <BitmapHeapNext>, node=0x1a0c618) at execScan.c:97
#16 ExecScan (node=0x1a0c618, accessMtd=0x5ffa20 <BitmapHeapNext>, recheckMtd=0x5ff990 <BitmapHeapRecheck>) at execScan.c:164
#17 0x0000000000604a3f in ExecProcNode (node=0x1a0c618) at ../../../src/include/executor/executor.h:250
#18 ExecHashJoin (pstate=0x1ebf670) at nodeHashjoin.c:145
#19 0x00000000005fad89 in ExecProcNode (node=0x1ebf670) at ../../../src/include/executor/executor.h:250
#20 fetch_input_tuple (aggstate=aggstate@entry=0x1ebef78) at nodeAgg.c:695
#21 0x00000000005fcfd3 in agg_fill_hash_table (aggstate=0x1ebef78) at nodeAgg.c:2539
#22 ExecAgg (pstate=0x1ebef78) at nodeAgg.c:2151
#23 0x0000000000610636 in ExecProcNode (node=0x1ebef78) at ../../../src/include/executor/executor.h:250
#24 ExecSort (pstate=0x1ebed08) at nodeSort.c:106
#25 0x0000000000607cfd in ExecProcNode (node=0x1ebed08) at ../../../src/include/executor/executor.h:250
#26 ExecLimit (pstate=0x1ebe0f8) at nodeLimit.c:95
#27 0x00000000005ef612 in ExecProcNode (node=0x1ebe0f8) at ../../../src/include/executor/executor.h:250
#28 ExecutePlan (execute_once=<optimized out>, dest=0x10e34f8, direction=<optimized out>, numberTuples=0, sendTuples=1 '\001', operation=CMD_SELECT, use_parallel_mode=<optimized out>, planstate=0x1ebe0f8, estate=0x1ebde98) at execMain.c:1722
#29 standard_ExecutorRun (queryDesc=0x18caf88, direction=<optimized out>, count=0, execute_once=<optimized out>) at execMain.c:363
#30 0x00007f7aa028415d in pgss_ExecutorRun (queryDesc=0x18caf88, direction=ForwardScanDirection, count=0, execute_once=<optimized out>) at pg_stat_statements.c:889
#31 0x000000000071a28b in PortalRunSelect (portal=portal@entry=0x1111d88, forward=forward@entry=1 '\001', count=0, count@entry=9223372036854775807, dest=dest@entry=0x10e34f8) at pquery.c:932
#32 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
#33 0x0000000000718f84 in PostgresMain (argc=<optimized out>, argv=<optimized out>, dbname=<optimized out>, username=<optimized out>) at postgres.c:1984
#34 0x000000000047ad3c in BackendRun (port=0x106a590) at postmaster.c:4405
#35 BackendStartup (port=0x106a590) at postmaster.c:4077
#36 ServerLoop () at postmaster.c:1755
#37 0x00000000006afacf in PostmasterMain (argc=argc@entry=1, argv=argv@entry=0x101ba20) at postmaster.c:1363
#38 0x000000000047bb6f in main (argc=1, argv=0x101ba20) at main.c:228

# Similar problem

I noticed that there were some similar bug reports before. 

- https://www.postgresql.org/message-id/CAK7KUdBjF4TN5Z2Rf0fv1MVUa%3DuqQssKMhoTXUa2y88R4PPjsg%40mail.gmail.com
- https://www.postgresql.org/message-id/[hidden email]
- https://www.postgresql-archive.org/Stalls-on-PGSemaphoreLock-td5797385.html

According to this https://www.postgresql-archive.org/Stalls-on-PGSemaphoreLock-td5797385.html, this issue may be related to the huge page. 
So we turn off the huge page, and I don't know if this problem will happen again, but it hasn't happened yet to now.

Maybe should only turn off transparent hugepage

BTW:
Related configuration of our machine is as following:

cat /sys/kernel/mm/transparent_hugepage/defrag
    [always] madvise never 
        
cat /proc/sys/kernel/sem 
250 32000 32 128

/proc/meminfo
AnonHugePages:   4446208 kB
HugePages_Total:   38912
HugePages_Free:     5907
HugePages_Rsvd:       40
HugePages_Surp:        0

Maybe we should only trun off transparent hugepage instead of huge page.

Now, I am not sure if this problem is a kernel configuration issue or a gin index implementation bug, any tips?

Regard,
Chen Huajun
Reply | Threaded
Open this post in threaded view
|

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

chenhj
Hi,all
 
I  analyzed the btree block where lwlock deadlock occurred, as follows:

## insert process(ginInsertValue())

                     644(root blkno)
                      |
     7054(2. held LWLock:0x2aaac587ae64)     ----rightlink---->    xxxx(3. Acquire LWLock:0x2aaab4009564,buffer = 2119038,blkno should be 9954)
       |
701(1. held LWLock:0x2aaab670dfe4)


The ginInsertValue() function above gets the lwlock in the order described in the README.

src/backend/access/gin/README
---------------------------------------------------------------
To avoid deadlocks, B-tree pages must always be locked in the same order:
left to right, and bottom to top.
...
-----------------------------------------------------------------


## autovacuum process(ginScanToDelete())

                     644(root blkno)
                      |
...  9954(1. held LWLock:0x2aaab4009564) ...
       |
701(2. Acquire LWLock:0x2aaab670dfe4)

note:according to autovacuum's core 701's parent is 9954;while insert's core shows 701's parent is 7054, rightlink of 7054 is 9954!

However, ginScanToDelete() depth-first scans the btree and gets the EXCLUSIVE lock, which creates a deadlock.
Is the above statement correct? If so, deadlocks should easily happen.


static bool
ginScanToDelete(GinVacuumState *gvs, BlockNumber blkno, bool isRoot,
                DataPageDeleteStack *parent, OffsetNumber myoff)
{
...
    if (!isRoot)
        LockBuffer(buffer, GIN_EXCLUSIVE);

...
        for (i = FirstOffsetNumber; i <= GinPageGetOpaque(page)->maxoff; i++)
        {
            PostingItem *pitem = GinDataPageGetPostingItem(page, i);

            if (ginScanToDelete(gvs, PostingItemGetBlockNumber(pitem), FALSE, me, i))
                i--;
        }
...
}

src/backend/access/gin/README
-----------------------------------------------------------------
The previous paragraph's reasoning only applies to searches, and only to
posting trees. To protect from inserters following a downlink to a deleted
page, vacuum simply locks out all concurrent insertions to the posting tree,
by holding a super-exclusive lock on the parent page of subtree with deletable
pages. 
...
posting tree. To exclude interference with readers vacuum takes exclusive
locks in a depth-first scan in left-to-right order of page tuples. 
...
-----------------------------------------------------------------

# stacks
## stack of insert:Acquire lock 0x2aaab4009564(blkno:9954) and hold 0x2aaab670dfe4(blkno:701), 0x2aaac587ae64(blkno:7054)
-----------------------------------------------------------------
(gdb) bt
#0  0x00007fe11552379b in do_futex_wait.constprop.1 () from /lib64/libpthread.so.0
#1  0x00007fe11552382f in __new_sem_wait_slow.constprop.0 () from /lib64/libpthread.so.0
#2  0x00007fe1155238cb in sem_wait@@GLIBC_2.2.5 () from /lib64/libpthread.so.0
#3  0x000000000069d362 in PGSemaphoreLock (sema=0x2aaaaac02958) at pg_sema.c:310
#4  0x00000000007095ac in LWLockAcquire (lock=0x2aaab4009564, mode=LW_EXCLUSIVE) at lwlock.c:1233
#5  0x0000000000490a32 in ginStepRight (buffer=6713826, index=<optimized out>, lockmode=lockmode@entry=2) at ginbtree.c:174
#6  0x0000000000490c1c in ginFinishSplit (btree=btree@entry=0x7ffd81e4f950, stack=0x28eebf8, freestack=freestack@entry=1 '\001', buildStats=buildStats@entry=0x0) at ginbtree.c:701
#7  0x0000000000491396 in ginInsertValue (btree=btree@entry=0x7ffd81e4f950, stack=<optimized out>, insertdata=insertdata@entry=0x7ffd81e4f940, buildStats=buildStats@entry=0x0)
    at ginbtree.c:773
#8  0x000000000048fb42 in ginInsertItemPointers (index=<optimized out>, rootBlkno=rootBlkno@entry=644, items=items@entry=0x2916598, nitem=nitem@entry=353, buildStats=buildStats@entry=0x0)
    at gindatapage.c:1907
#9  0x000000000048a9ea in ginEntryInsert (ginstate=ginstate@entry=0x28e7ef8, attnum=<optimized out>, key=42920440, category=<optimized out>, items=0x2916598, nitem=353, 
    buildStats=buildStats@entry=0x0) at gininsert.c:214
#10 0x0000000000496d94 in ginInsertCleanup (ginstate=ginstate@entry=0x28e7ef8, full_clean=full_clean@entry=0 '\000', fill_fsm=fill_fsm@entry=1 '\001', 
    forceCleanup=forceCleanup@entry=0 '\000', stats=stats@entry=0x0) at ginfast.c:883
#11 0x0000000000497727 in ginHeapTupleFastInsert (ginstate=ginstate@entry=0x28e7ef8, collector=collector@entry=0x7ffd81e4fe60) at ginfast.c:448
#12 0x000000000048b209 in gininsert (index=<optimized out>, values=0x7ffd81e4ff40, isnull=0x7ffd81e50040 "", ht_ctid=0x280d98c, heapRel=<optimized out>, checkUnique=<optimized out>, 
    indexInfo=0x28b5aa8) at gininsert.c:522
#13 0x00000000005ee8dd in ExecInsertIndexTuples (slot=slot@entry=0x28b5d58, tupleid=tupleid@entry=0x280d98c, estate=estate@entry=0x28b5288, noDupErr=noDupErr@entry=1 '\001', 
    specConflict=specConflict@entry=0x7ffd81e5013b "", arbiterIndexes=arbiterIndexes@entry=0x28c6dd8) at execIndexing.c:386
#14 0x000000000060ccf5 in ExecInsert (canSetTag=1 '\001', estate=0x28b5288, onconflict=ONCONFLICT_UPDATE, arbiterIndexes=0x28c6dd8, planSlot=0x28b5d58, slot=0x28b5d58, mtstate=0x28b5628)
    at nodeModifyTable.c:564
#15 ExecModifyTable (pstate=0x28b5628) at nodeModifyTable.c:1766
#16 0x00000000005ef612 in standard_ExecutorRun (queryDesc=<optimized out>, direction=<optimized out>, count=<optimized out>, execute_once=<optimized out>)
    at ../../../src/include/executor/executor.h:250
#17 0x00007fe10607d15d in pgss_ExecutorRun (queryDesc=0x28cc1d8, direction=ForwardScanDirection, count=0, execute_once=<optimized out>) at pg_stat_statements.c:889
#18 0x000000000071a7ba in ProcessQuery (plan=<optimized out>, 
    sourceText=0x2849058 "INSERT INTO bi_dm.tdm_sncity_workorder_analytic_statistics (CITYCODE,CITYNAME,DISTRICT,DISTRICT_NAME,ZL_WERKS,ZL_WERKS_NAME,AREA_CD,AREA_NM,ZSIZE,DEPT_CD,TMALL_FLG,ORDER_DATE,DISTRIBUTE,WORKORDER,FNSH"..., params=0x28b2260, queryEnv=0x0, dest=0xc9e2a0 <donothingDR>, completionTag=0x7ffd81e507b0 "") at pquery.c:161
#19 0x000000000071a9f7 in PortalRunMulti (portal=portal@entry=0x289fdd8, isTopLevel=isTopLevel@entry=1 '\001', setHoldSnapshot=setHoldSnapshot@entry=0 '\000', dest=0xc9e2a0 <donothingDR>, 
    dest@entry=0x284d778, altdest=0xc9e2a0 <donothingDR>, altdest@entry=0x284d778, completionTag=completionTag@entry=0x7ffd81e507b0 "") at pquery.c:1286
#20 0x000000000071b535 in PortalRun (portal=<optimized out>, count=1, isTopLevel=<optimized out>, run_once=<optimized out>, dest=0x284d778, altdest=0x284d778, 
    completionTag=0x7ffd81e507b0 "") at pquery.c:799
#21 0x0000000000718f84 in PostgresMain (argc=<optimized out>, argv=<optimized out>, dbname=<optimized out>, username=<optimized out>) at postgres.c:1984
#22 0x000000000047ad3c in BackendRun (port=0x27cbc40) at postmaster.c:4405
#23 BackendStartup (port=0x27cbc40) at postmaster.c:4077
#24 ServerLoop () at postmaster.c:1755
#25 0x00000000006afacf in PostmasterMain (argc=argc@entry=3, argv=argv@entry=0x277ba20) at postmaster.c:1363
#26 0x000000000047bb6f in main (argc=3, argv=0x277ba20) at main.c:228
(gdb) p num_held_lwlocks 
$1 = 2
(gdb) p lwlocks
$2 = {{lock = 0x2aaab670dfe4, mode = LW_EXCLUSIVE}, {lock = 0x2aaac587ae64, mode = LW_EXCLUSIVE}, {lock = 0x2aaaaac0a380, mode = LW_SHARED}, {lock = 0x2aaab670a2e4, mode = LW_EXCLUSIVE}, {
    lock = 0x2aaab670a2e4, mode = LW_EXCLUSIVE}, {lock = 0x2aaab670a2e4, mode = LW_EXCLUSIVE}, {lock = 0x2aaab670a2e4, mode = LW_EXCLUSIVE}, {lock = 0x2aaab670a2e4, mode = LW_EXCLUSIVE}, {
    lock = 0x2aaab670a2e4, mode = LW_EXCLUSIVE}, {lock = 0x2aaab670a2e4, mode = LW_EXCLUSIVE}, {lock = 0x2aaaaac15a80, mode = LW_EXCLUSIVE}, {lock = 0x0, 
    mode = LW_EXCLUSIVE} <repeats 189 times>}

(gdb) f 6
#6  0x0000000000490c1c in ginFinishSplit (btree=btree@entry=0x7ffd81e4f950, stack=0x28eebf8, freestack=freestack@entry=1 '\001', buildStats=buildStats@entry=0x0) at ginbtree.c:701
701                parent->buffer = ginStepRight(parent->buffer, btree->index, GIN_EXCLUSIVE);

(gdb) p *stack
$27 = {blkno = 701, buffer = 2758312, off = 0, iptr = {ip_blkid = {bi_hi = 5, bi_lo = 0}, ip_posid = 40884}, predictNumber = 1, parent = 0x28eea68}
(gdb) p ((LWLock*) (&((&BufferDescriptors[(2758312 - 1)].bufferdesc))->content_lock))
$28 = (LWLock *) 0x2aaab670dfe4

(gdb) p *parent
$29 = {blkno = 7054, buffer = 6713826, off = 0, iptr = {ip_blkid = {bi_hi = 8, bi_lo = 0}, ip_posid = 40886}, predictNumber = 1, parent = 0x28eeab8}
(gdb) p ((LWLock*) (&((&BufferDescriptors[(6713826 - 1)].bufferdesc))->content_lock))
$32 = (LWLock *) 0x2aab4fa5cfe4

(gdb) p *(GinBtreeStack *)0x28eeab8
$31 = {blkno = 644, buffer = 6713825, off = 1, iptr = {ip_blkid = {bi_hi = 35, bi_lo = 0}, ip_posid = 40884}, predictNumber = 1, parent = 0x0}
(gdb) p ((LWLock*) (&((&BufferDescriptors[(6713825 - 1)].bufferdesc))->content_lock))
$33 = (LWLock *) 0x2aaac587ae24
-----------------------------------------------------------------


## stack of autovacuum:Acquire lock 0x2aaab670dfe4(blkno:701) and hold 0x2aaab4009564(blkno:9954)
-----------------------------------------------------------------
#0  0x00007fe11552379b in do_futex_wait.constprop.1 () from /lib64/libpthread.so.0
#1  0x00007fe11552382f in __new_sem_wait_slow.constprop.0 () from /lib64/libpthread.so.0
#2  0x00007fe1155238cb in sem_wait@@GLIBC_2.2.5 () from /lib64/libpthread.so.0
#3  0x000000000069d362 in PGSemaphoreLock (sema=0x2aaaaac07eb8) at pg_sema.c:310
#4  0x00000000007095ac in LWLockAcquire (lock=0x2aaab670dfe4, mode=LW_EXCLUSIVE) at lwlock.c:1233
#5  0x00000000004947ef in ginScanToDelete (gvs=gvs@entry=0x7ffd81e4d0f0, blkno=701, isRoot=isRoot@entry=0 '\000', 
    parent=parent@entry=0x7ffd81e4c790, myoff=myoff@entry=37) at ginvacuum.c:262
#6  0x0000000000494874 in ginScanToDelete (gvs=gvs@entry=0x7ffd81e4d0f0, blkno=blkno@entry=9954, isRoot=isRoot@entry=1 '\001', 
    parent=parent@entry=0x7ffd81e4c790, myoff=myoff@entry=0) at ginvacuum.c:277
#7  0x0000000000494ed1 in ginVacuumPostingTreeLeaves (gvs=gvs@entry=0x7ffd81e4d0f0, blkno=9954, isRoot=isRoot@entry=0 '\000') at ginvacuum.c:404
#8  0x0000000000494e21 in ginVacuumPostingTreeLeaves (gvs=gvs@entry=0x7ffd81e4d0f0, blkno=644, isRoot=isRoot@entry=1 '\001') at ginvacuum.c:372
#9  0x0000000000495540 in ginVacuumPostingTree (rootBlkno=<optimized out>, gvs=0x7ffd81e4d0f0) at ginvacuum.c:426
#10 ginbulkdelete (info=0x7ffd81e4f720, stats=<optimized out>, callback=<optimized out>, callback_state=<optimized out>) at ginvacuum.c:649
#11 0x00000000005e1194 in lazy_vacuum_index (indrel=0x3146e28, stats=stats@entry=0x28ec200, vacrelstats=vacrelstats@entry=0x28ebc28)
    at vacuumlazy.c:1621
#12 0x00000000005e214d in lazy_scan_heap (aggressive=<optimized out>, nindexes=<optimized out>, Irel=<optimized out>, 
    vacrelstats=<optimized out>, options=16, onerel=0x28ec1f8) at vacuumlazy.c:1311
#13 lazy_vacuum_rel (onerel=onerel@entry=0x3144fa8, options=options@entry=99, params=params@entry=0x289f270, bstrategy=<optimized out>)
    at vacuumlazy.c:258
#14 0x00000000005dfc35 in vacuum_rel (relid=relid@entry=2060396948, relation=relation@entry=0x7ffd81e4fe50, options=options@entry=99, 
---Type <return> to continue, or q <return> to quit---
    params=params@entry=0x289f270) at vacuum.c:1463
#15 0x00000000005e0ad2 in vacuum (options=99, relation=relation@entry=0x7ffd81e4fe50, relid=<optimized out>, params=params@entry=0x289f270, 
    va_cols=va_cols@entry=0x0, bstrategy=<optimized out>, bstrategy@entry=0x289e988, isTopLevel=isTopLevel@entry=1 '\001') at vacuum.c:306
#16 0x00000000006a01ff in autovacuum_do_vac_analyze (bstrategy=0x289e988, tab=0x289f268) at autovacuum.c:3095
#17 do_autovacuum () at autovacuum.c:2450
#18 0x00000000006a06a9 in AutoVacWorkerMain (argv=0x0, argc=0) at autovacuum.c:1693
#19 0x00000000006a0f49 in StartAutoVacWorker () at autovacuum.c:1498
#20 0x00000000006aeaea in StartAutovacuumWorker () at postmaster.c:5462
#21 sigusr1_handler (postgres_signal_arg=<optimized out>) at postmaster.c:5159
#22 <signal handler called>
#23 0x00007fe11334bb83 in __select_nocancel () from /lib64/libc.so.6
#24 0x000000000047a3a3 in ServerLoop () at postmaster.c:1719
#25 0x00000000006afacf in PostmasterMain (argc=argc@entry=3, argv=argv@entry=0x277ba20) at postmaster.c:1363
#26 0x000000000047bb6f in main (argc=3, argv=0x277ba20) at main.c:228
(gdb) f 4
#4  0x00000000007095ac in LWLockAcquire (lock=0x2aaab670dfe4, mode=LW_EXCLUSIVE) at lwlock.c:1233
1233PGSemaphoreLock(proc->sem);
(gdb)  p num_held_lwlocks
$1 = 1
(gdb) p InterruptHoldoffCount
$2 = 2
(gdb)  p held_lwlocks
$3 = {{lock = 0x2aaab4009564, mode = LW_EXCLUSIVE}, {lock = 0x2aaaaac0aa00, mode = LW_SHARED}, {lock = 0x2aaaba8da364, mode = LW_EXCLUSIVE}, {lock = 0x2aaaaac15900, mode = LW_EXCLUSIVE}, {
    lock = 0x2aaab66eb064, mode = LW_EXCLUSIVE}, {lock = 0x2aaaaac15900, mode = LW_EXCLUSIVE}, {lock = 0x2aaaaac15c80, mode = LW_EXCLUSIVE}, {lock = 0x0, 
    mode = LW_EXCLUSIVE} <repeats 193 times>}
(gdb) f 8
#8  0x0000000000494e21 in ginVacuumPostingTreeLeaves (gvs=gvs@entry=0x7ffd81e4d0f0, blkno=644, isRoot=isRoot@entry=1 '\001') at ginvacuum.c:372
372                if (ginVacuumPostingTreeLeaves(gvs, children[i], FALSE))

(gdb) p i
$13 = 2
(gdb) p children[1]
$14 = 7054
(gdb) p children[2]
$15 = 9954

#7  0x0000000000494ed1 in ginVacuumPostingTreeLeaves (gvs=gvs@entry=0x7ffd81e4d0f0, blkno=9954, isRoot=isRoot@entry=0 '\000') at ginvacuum.c:404
404                ginScanToDelete(gvs, blkno, TRUE, &root, InvalidOffsetNumber);
(gdb) p buffer
$16 = 2119038
(gdb) p ((LWLock*) (&((&BufferDescriptors[(2119038 - 1)].bufferdesc))->content_lock))
$17 = (LWLock *) 0x2aaab4009564

(gdb) f 5
#5  0x00000000004947ef in ginScanToDelete (gvs=gvs@entry=0x7ffd81e4d0f0, blkno=701, isRoot=isRoot@entry=0 '\000', 
    parent=parent@entry=0x7ffd81e4c790, myoff=myoff@entry=37) at ginvacuum.c:262
262            LockBuffer(buffer, GIN_EXCLUSIVE);

(gdb) p buffer
$29 = 2758312
(gdb) p ((LWLock*) (&((&BufferDescriptors[(2758312 - 1)].bufferdesc))->content_lock))
$32 = (LWLock *) 0x2aaab670dfe4

-----------------------------------------------------------------
Reply | Threaded
Open this post in threaded view
|

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

Peter Geoghegan-4
On Tue, Nov 6, 2018 at 10:05 AM chenhj <[hidden email]> wrote:
> I  analyzed the btree block where lwlock deadlock occurred, as follows:

Thank you for doing this important work.

You're using Postgres 10.2. While that version isn't current with all
GIN bug fixes, it does have this important one:

"Ensure that vacuum will always clean up the pending-insertions list
of a GIN index (Masahiko Sawada)"

Later GIN fixes seem unlikely to be relevant to your issue. I think
that this is probably a genuine, new bug.

> The ginInsertValue() function above gets the lwlock in the order described in the README.

> However, ginScanToDelete() depth-first scans the btree and gets the EXCLUSIVE lock, which creates a deadlock.
> Is the above statement correct? If so, deadlocks should easily happen.

I have been suspicious of deadlock hazards in the code for some time
-- particularly around pending list cleanup. I go into a lot of detail
on my suspicions here:

https://www.postgresql.org/message-id/flat/CAH2-WzmfUpRjWcUq3%2B9ijyum4AJ%2Bk-meGT8_HnxBMpKz1aNS-g%40mail.gmail.com#ea5af1088adfacb3d0ba88313be1a5e3

I note that your first deadlock involve the following kinds of backends:

* ginInsertCleanup() calls from a regular backend, which will have a
backend do things that VACUUM generally only gets to do, like call
RecordFreeIndexPage().

* (auto)VACUUM processes.

Your second/recovery deadlock involves:

* Regular read-only queries.

* Recovery code.

Quite a lot of stuff is involved here!

The code in this area is way too complicated, and I haven't thought
about it in about a year, so it's hard for me to be sure of anything
at the moment. My guess is that there is confusion about the type of
page expected within one or more blocks (e.g. entry tree vs. pending
list), due to a race condition in block deletion and/or recycling --
again, I've suspected something like this could happen for some time.
The fact that you get a distinct deadlock during recovery is
consistent with that theory.

It's safe to say that promoting the asserts on gin page type into
"can't happen" elog errors in places like scanPendingInsert() and
ginInsertCleanup() would be a good start. Note that we already did
similar Assert-elog(ERROR) promotion this for posting tree code, when
similar bugs appeared way back in 2013.

--
Peter Geoghegan

Reply | Threaded
Open this post in threaded view
|

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

Peter Geoghegan-4
In reply to this post by chenhj
On Mon, Oct 29, 2018 at 12:04 PM chenhj <[hidden email]> wrote:

>     #4  0x00000000007095ac in LWLockAcquire (lock=0x2aaab4009564, mode=LW_EXCLUSIVE) at lwlock.c:1233
>     #5  0x0000000000490a32 in ginStepRight (buffer=6713826, index=<optimized out>, lockmode=lockmode@entry=2) at ginbtree.c:174
>     #6  0x0000000000490c1c in ginFinishSplit (btree=btree@entry=0x7ffd81e4f950, stack=0x28eebf8, freestack=freestack@entry=1 '\001', buildStats=buildStats@entry=0x0) at ginbtree.c:701
>     #7  0x0000000000491396 in ginInsertValue (btree=btree@entry=0x7ffd81e4f950, stack=<optimized out>, insertdata=insertdata@entry=0x7ffd81e4f940, buildStats=buildStats@entry=0x0)
>         at ginbtree.c:773
>     #8  0x000000000048fb42 in ginInsertItemPointers (index=<optimized out>, rootBlkno=rootBlkno@entry=644, items=items@entry=0x2916598, nitem=nitem@entry=353, buildStats=buildStats@entry=0x0)
>         at gindatapage.c:1907
>     #9  0x000000000048a9ea in ginEntryInsert (ginstate=ginstate@entry=0x28e7ef8, attnum=<optimized out>, key=42920440, category=<optimized out>, items=0x2916598, nitem=353,
>         buildStats=buildStats@entry=0x0) at gininsert.c:214
>     #10 0x0000000000496d94 in ginInsertCleanup (ginstate=ginstate@entry=0x28e7ef8, full_clean=full_clean@entry=0 '\000', fill_fsm=fill_fsm@entry=1 '\001',
>         forceCleanup=forceCleanup@entry=0 '\000', stats=stats@entry=0x0) at ginfast.c:883
>     #11 0x0000000000497727 in ginHeapTupleFastInsert (ginstate=ginstate@entry=0x28e7ef8, collector=collector@entry=0x7ffd81e4fe60) at ginfast.c:448
>     #12 0x000000000048b209 in gininsert (index=<optimized out>, values=0x7ffd81e4ff40, isnull=0x7ffd81e50040 "", ht_ctid=0x280d98c, heapRel=<optimized out>, checkUnique=<optimized out>,
>         indexInfo=0x28b5aa8) at gininsert.c:522

I want to point something out about the above inserter represented by
this stack trace. It deadlocks against VACUUM from within the
following ginEntryInsert() call:

            /*
             * While we left the page unlocked, more stuff might have gotten
             * added to it.  If so, process those entries immediately.  There
             * shouldn't be very many, so we don't worry about the fact that
             * we're doing this with exclusive lock. Insertion algorithm
             * guarantees that inserted row(s) will not continue on next page.
             * NOTE: intentionally no vacuum_delay_point in this loop.
             */
            if (PageGetMaxOffsetNumber(page) != maxoff)
            {
                ginInitBA(&accum);
                processPendingPage(&accum, &datums, page, maxoff + 1);

                ginBeginBAScan(&accum);
                while ((list = ginGetBAEntry(&accum,
                                             &attnum, &key, &category,
&nlist)) != NULL)
                    ginEntryInsert(ginstate, attnum, key, category, //
<--- deadlocks
                                   list, nlist, NULL);
            }

Clearly this particular call to ginEntryInsert() from within
ginInsertCleanup() is generally supposed to be a rare occurrence. It's
not surprising that it's hard for you to hit this issue.

BTW, I strongly doubt that disabling hugepages has fixed anything,
though it may have accidentally masked the problem. This is an issue
around the basic correctness of the locking protocols used by GIN.

--
Peter Geoghegan

Reply | Threaded
Open this post in threaded view
|

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

Peter Geoghegan-4
In reply to this post by chenhj
On Mon, Oct 29, 2018 at 12:04 PM chenhj <[hidden email]> wrote:

> ## stack of autovacuum:Acquire lock 0x2aaab670dfe4 and hold 0x2aaab4009564
> --------------------------------------
>     (gdb) bt
>     #0  0x00007fe11552379b in do_futex_wait.constprop.1 () from /lib64/libpthread.so.0
>     #1  0x00007fe11552382f in __new_sem_wait_slow.constprop.0 () from /lib64/libpthread.so.0
>     #2  0x00007fe1155238cb in sem_wait@@GLIBC_2.2.5 () from /lib64/libpthread.so.0
>     #3  0x000000000069d362 in PGSemaphoreLock (sema=0x2aaaaac07eb8) at pg_sema.c:310
>     #4  0x00000000007095ac in LWLockAcquire (lock=0x2aaab670dfe4, mode=LW_EXCLUSIVE) at lwlock.c:1233
>     #5  0x00000000004947ef in ginScanToDelete (gvs=gvs@entry=0x7ffd81e4d0f0, blkno=701, isRoot=isRoot@entry=0 '\000', parent=parent@entry=0x7ffd81e4c790, myoff=myoff@entry=37) at ginvacuum.c:262
>     #6  0x0000000000494874 in ginScanToDelete (gvs=gvs@entry=0x7ffd81e4d0f0, blkno=blkno@entry=9954, isRoot=isRoot@entry=1 '\001', parent=parent@entry=0x7ffd81e4c790, myoff=myoff@entry=0)
>         at ginvacuum.c:277
>     #7  0x0000000000494ed1 in ginVacuumPostingTreeLeaves (gvs=gvs@entry=0x7ffd81e4d0f0, blkno=9954, isRoot=isRoot@entry=0 '\000') at ginvacuum.c:404
>     #8  0x0000000000494e21 in ginVacuumPostingTreeLeaves (gvs=gvs@entry=0x7ffd81e4d0f0, blkno=644, isRoot=isRoot@entry=1 '\001') at ginvacuum.c:372
>     #9  0x0000000000495540 in ginVacuumPostingTree (rootBlkno=<optimized out>, gvs=0x7ffd81e4d0f0) at ginvacuum.c:426
>     #10 ginbulkdelete (info=0x7ffd81e4f720, stats=<optimized out>, callback=<optimized out>, callback_state=<optimized out>) at ginvacuum.c:649
>     #11 0x00000000005e1194 in lazy_vacuum_index (indrel=0x3146e28, stats=stats@entry=0x28ec200, vacrelstats=vacrelstats@entry=0x28ebc28) at vacuumlazy.c:1621
>     #12 0x00000000005e214d in lazy_scan_heap (aggressive=<optimized out>, nindexes=<optimized out>, Irel=<optimized out>, vacrelstats=<optimized out>, options=16, onerel=0x28ec1f8)
>         at vacuumlazy.c:1311
>     #13 lazy_vacuum_rel (onerel=onerel@entry=0x3144fa8, options=options@entry=99, params=params@entry=0x289f270, bstrategy=<optimized out>) at vacuumlazy.c:258

Actually, the bigger problem is on this side of the deadlock, within
VACUUM. ginInsertCleanup() (the first/other side of the deadlock) may
have problems, but this seems worse. Commit 218f51584d5 appears to be
at fault here.

First things first: ginScanToDelete() *maintains* buffer locks on
multiple levels of a posting tree, meaning that there may be cases
where quite a few exclusive buffer locks may be held all at once (one
per level). MAX_SIMUL_LWLOCKS is 200 these days, and in practice a
B-Tree can never get that tall, but having the number of buffer locks
acquired be determined by the height of the tree is not okay, on
general principle. The nbtree code's page deletion goes to a lot of
effort to keep the number of buffer locks fixed, but nothing like that
is is attempted for GIN posting trees.

Chen's original analysis of the problem seems to be more or less
accurate: the order that ginScanToDelete() acquires buffer locks as it
descends the tree (following commit 218f51584d5) is not compatible
with the order within ginFinishSplit(). The faulty code within
ginScanToDelete() crabs/couples buffer locks while descending the
tree, whereas the code within ginFinishSplit() crabs them as it
ascends the same tree.

Teodor: Do you think that the issue is fixable? It looks like there
are serious issues with the design of 218f51584d5 to me. I don't think
the general "there can't be any inserters at this subtree" thing works
given that we have to couple buffer locks when moving right for other
reasons. We call ginStepRight() within ginFinishSplit(), for reasons
that date back to bug fix commit ac4ab97e from 2013 -- that detail is
probably important, because it seems to be what breaks the subtree
design (we don't delete in two phases or anything in GIN).

I think that you have to be doing a multi-level delete for a deadlock
to take place, which isn't particularly likely to coincide with a
concurrent insertion in general. That may explain why it's taken a
year to get a high-quality bug report.

--
Peter Geoghegan

Reply | Threaded
Open this post in threaded view
|

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

Peter Geoghegan-4
On Wed, Nov 7, 2018 at 5:46 PM Peter Geoghegan <[hidden email]> wrote:
> I think that you have to be doing a multi-level delete for a deadlock
> to take place, which isn't particularly likely to coincide with a
> concurrent insertion in general. That may explain why it's taken a
> year to get a high-quality bug report.

BTW, it's notable that Chen's query uses ON CONFLICT DO UPDATE.
Speculative insertion might cause just the wrong kind of churn,
involving continual recycling of heap TIDs.

--
Peter Geoghegan

Reply | Threaded
Open this post in threaded view
|

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

Peter Geoghegan-4
In reply to this post by Peter Geoghegan-4
On Wed, Nov 7, 2018 at 5:46 PM Peter Geoghegan <[hidden email]> wrote:
> Teodor: Do you think that the issue is fixable? It looks like there
> are serious issues with the design of 218f51584d5 to me. I don't think
> the general "there can't be any inserters at this subtree" thing works
> given that we have to couple buffer locks when moving right for other
> reasons. We call ginStepRight() within ginFinishSplit(), for reasons
> that date back to bug fix commit ac4ab97e from 2013 -- that detail is
> probably important, because it seems to be what breaks the subtree
> design (we don't delete in two phases or anything in GIN).

Ping?

This is a thorny problem, and I'd like to get your input soon. I
suspect that reverting 218f51584d5 may be the ultimate outcome, even
though it's a v10 feature.

--
Peter Geoghegan

Reply | Threaded
Open this post in threaded view
|

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

chenhj
In reply to this post by Peter Geoghegan-4

> >BTW, I strongly doubt that disabling hugepages has fixed anything, >though it may have accidentally masked the problem. This is an issue >around the basic correctness of the locking protocols used by GIN. >
We had disable hugepages for some days, but the bug still occurs.

The attachment is the gcore files that was collected when the issue occurred on the primary, and I hope to help analyze the problem.



Regard,
Chen Huajun

primary_hang_20181026_52.tar.gz (6M) Download Attachment
Reply | Threaded
Open this post in threaded view
|

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

chenhj
In reply to this post by Peter Geoghegan-4
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)
{
XLogRecPtr lsn = record->EndRecPtr;
ginxlogDeletePage *data = (ginxlogDeletePage *) XLogRecGetData(record);
Buffer dbuffer;
Buffer pbuffer;
Buffer lbuffer;
Page page;

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@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@entry=0x1da3ad0, entry=entry@entry=0x159e218, advancePast=..., snapshot=snapshot@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@entry=0x2236168, bitmap=bitmap@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@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@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@entry=0x1112198, forward=forward@entry=1 '\001', count=0, count@entry=9223372036854775807, dest=dest@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@entry=1, argv=argv@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@entry=1) at ginbtree.c:174
174 LockBuffer(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
677 entry->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@entry=0x105ce58, block_id=block_id@entry=2 '\002', mode=mode@entry=RBM_NORMAL, 
    get_cleanup_lock=get_cleanup_lock@entry=0 '\000', buf=buf@entry=0x7fff550d93c0) at xlogutils.c:399
#6  0x0000000000503d00 in XLogReadBufferForRedo (record=record@entry=0x105ce58, block_id=block_id@entry=2 '\002', buf=buf@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@entry=2, argv=argv@entry=0x7fff550dcbe0) at bootstrap.c:426
#12 0x00000000006ad160 in StartChildProcess (type=StartupProcess) at postmaster.c:5361
#13 0x00000000006afaab in PostmasterMain (argc=argc@entry=1, argv=argv@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
482 if (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
482 if (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
 


Reply | Threaded
Open this post in threaded view
|

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

chenhj

There's a mistake in the last mail.
About how to reproduct the issue,the following SQL should be:

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


4. execute select SQL

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

Regard,
Chen Huajun
Reply | Threaded
Open this post in threaded view
|

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

Andrey Borodin-2
In reply to this post by Peter Geoghegan-4
Hi everyone!

I didn't noticed this thread for too long somehow, sorry.

8 нояб. 2018 г., в 6:46, Peter Geoghegan <[hidden email]> написал(а):

I don't think
the general "there can't be any inserters at this subtree" thing works
given that we have to couple buffer locks when moving right for other
reasons. We call ginStepRight() within ginFinishSplit(), for reasons
that date back to bug fix commit ac4ab97e from 2013 -- that detail is
probably important, because it seems to be what breaks the subtree
design (we don't delete in two phases or anything in GIN).

ginVacuumPostingTreeLeaves() holds LockBufferForCleanup() on subtree root b.
Thus there may be no GinBtreeStack's holding pin on b at the moment.
When you ginStepRight(b) to the parent in ginFinishSplit(), you always get to the buffer from your stack.
Hence you can never have ginFinishSplit() deadlock with cleanup of subtree whose root is LockBufferForCleanup()'d.

Is this correct or did I miss something?

But we have a deadlock at hand, I'll think more about it. Something with locking protocol is clearly wrong.

11 нояб. 2018 г., в 22:33, chenhj <[hidden email]> написал(а):

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

This looks correct to me.

Best regards, Andrey Borodin.
Reply | Threaded
Open this post in threaded view
|

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

Andrey Borodin-2
Hi!

Mail.App somehow borken my reponse with <div class="ApplePlainTextBody">, which is far beyond of my understanding of what is plain text, that's why I'll quote all my previous message here. Hope this mail client is OK.

14.11.2018, 23:13, "Andrey Borodin" <[hidden email]>:

> Hi everyone!
>
> I didn't noticed this thread for too long somehow, sorry.
>
>> 8 нояб. 2018 г., в 6:46, Peter Geoghegan <[hidden email]> написал(а):
>>
>> I don't think
>> the general "there can't be any inserters at this subtree" thing works
>> given that we have to couple buffer locks when moving right for other
>> reasons. We call ginStepRight() within ginFinishSplit(), for reasons
>> that date back to bug fix commit ac4ab97e from 2013 -- that detail is
>> probably important, because it seems to be what breaks the subtree
>> design (we don't delete in two phases or anything in GIN).
>
> ginVacuumPostingTreeLeaves() holds LockBufferForCleanup() on subtree root b.
> Thus there may be no GinBtreeStack's holding pin on b at the moment.
> When you ginStepRight(b) to the parent in ginFinishSplit(), you always get to the buffer from your stack.
> Hence you can never have ginFinishSplit() deadlock with cleanup of subtree whose root is LockBufferForCleanup()'d.
>
> Is this correct or did I miss something?
>
> But we have a deadlock at hand, I'll think more about it. Something with locking protocol is clearly wrong.
>
>> 11 нояб. 2018 г., в 22:33, chenhj <[hidden email]> написал(а):
>>
>> The order of get lwlock in ginRedoDeletePage() may should be change from "dbuffer->pbuffer->lbuffer" to "lbuffer->dbuffer->pbuffer" . Is this right?
>
> This looks correct to me.
>
> Best regards, Andrey Borodin.

I've reread Chen's reports and understood his findings.

> When you ginStepRight(b) to the parent in ginFinishSplit(), you always get to the buffer from your stack.

This statement does not hold.
When you have a GinBtreeStack S, one of it's internal pages may split into new page P. If in this moment you start a multi-level delete from P and cascade split from S, P is not in S and we may deadlock.

Correct solution seems to replace lock-coupling descent by usual B-tree searches for parent pages as in B-tree.
I think I can compose patch for consideration.

Best regards, Andrey Borodin.

Reply | Threaded
Open this post in threaded view
|

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

Andrey Borodin-2
Hi!

> 15 нояб. 2018 г., в 17:30, Andrey Borodin <[hidden email]> написал(а):
>
> I think I can compose patch for consideration.

I found no practical way to fix concept of "subtree-lock". Pre-locking all left siblings for cleanup would suffice, but does not look very practical.
GIN Posting tree has no all useful B-tree inventory like left links and high keys for concurrent deletes without "subtree-lock".

Let's consider concurrent deletion.
As far as I understand, absence of high-key makes unsafe concurrent deletion of highest keys from internal pages. Thus, internal pages cannot be deleted at all.
PFA patch with most simple deletion algorithm:
1. Descend to leftmost leaf
2. Scan by rightlinks until rightmost page
3. Delete empty leaf pages, if they are not highest keys in corresponding parent page

Parent page is found by rightlink scan for leftmost parent with cached previous result.
Deleted page is stamped by ReadNewTransactionId()'s xid, page cannot be reused until deletion xid is beyond RecentGlobalDataXmin.
DeleteXid is WAL-logged.
I've refactored btree->getLeftMostChild() and btree->findChildPtr() to reuse their code (removed unnecessary parameter).

Please note, that attached patch do not fix 2nd bug found by Chen in page delete redo.

I understand that reverting commit 218f51584d5 and returning to long but finite root locks is safest solution. In this description of proposed patch I've tried to put concepts in a minimum of words. Please ping me if some concepts sound cryptic and require more clarification.

Best regards, Andrey Borodin.

0001-Use-correct-locking-protocol-during-GIN-posting-tree.patch (28K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

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

Peter Geoghegan-4
On Fri, Nov 23, 2018 at 2:18 AM Andrey Borodin <[hidden email]> wrote:
> I found no practical way to fix concept of "subtree-lock". Pre-locking all left siblings for cleanup would suffice, but does not look very practical.
> GIN Posting tree has no all useful B-tree inventory like left links and high keys for concurrent deletes without "subtree-lock".

Significantly changing the design of GIN vacuuming in back branches
for a release that's more than a year old is absolutely out of the
question. I think that your patch should be evaluated as a new v12
feature, following the revert of 218f51584d5.

> Please note, that attached patch do not fix 2nd bug found by Chen in page delete redo.
>
> I understand that reverting commit 218f51584d5 and returning to long but finite root locks is safest solution

Whatever happens with the master branch, I think that reverting commit
218f51584d5 is the only option on the table for the back branches. Its
design is based on ideas on locking protocols that are fundamentally
incorrect and unworkable. I don't have a lot of faith in our ability
to retrofit a design that fixes the issue without causing problems
elsewhere.

--
Peter Geoghegan

Reply | Threaded
Open this post in threaded view
|

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

Andres Freund
In reply to this post by Peter Geoghegan-4
Hi,

On 2018-11-10 17:42:16 -0800, Peter Geoghegan wrote:

> On Wed, Nov 7, 2018 at 5:46 PM Peter Geoghegan <[hidden email]> wrote:
> > Teodor: Do you think that the issue is fixable? It looks like there
> > are serious issues with the design of 218f51584d5 to me. I don't think
> > the general "there can't be any inserters at this subtree" thing works
> > given that we have to couple buffer locks when moving right for other
> > reasons. We call ginStepRight() within ginFinishSplit(), for reasons
> > that date back to bug fix commit ac4ab97e from 2013 -- that detail is
> > probably important, because it seems to be what breaks the subtree
> > design (we don't delete in two phases or anything in GIN).
>
> Ping?
>
> This is a thorny problem, and I'd like to get your input soon. I
> suspect that reverting 218f51584d5 may be the ultimate outcome, even
> though it's a v10 feature.

Teodor, any chance for a response here?  It's not OK to commit something
and then just not respond to bug-reports, especially when they're well
diagnose and clearly point towards issues in a commit of yours.

Alexander, CCing you, perhaps you could point the thread out to Teodor?

Greetings,

Andres Freund

Reply | Threaded
Open this post in threaded view
|

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

Alexander Korotkov-4
On Tue, Dec 4, 2018 at 8:01 PM Andres Freund <[hidden email]> wrote:

> On 2018-11-10 17:42:16 -0800, Peter Geoghegan wrote:
> > On Wed, Nov 7, 2018 at 5:46 PM Peter Geoghegan <[hidden email]> wrote:
> > > Teodor: Do you think that the issue is fixable? It looks like there
> > > are serious issues with the design of 218f51584d5 to me. I don't think
> > > the general "there can't be any inserters at this subtree" thing works
> > > given that we have to couple buffer locks when moving right for other
> > > reasons. We call ginStepRight() within ginFinishSplit(), for reasons
> > > that date back to bug fix commit ac4ab97e from 2013 -- that detail is
> > > probably important, because it seems to be what breaks the subtree
> > > design (we don't delete in two phases or anything in GIN).
> >
> > Ping?
> >
> > This is a thorny problem, and I'd like to get your input soon. I
> > suspect that reverting 218f51584d5 may be the ultimate outcome, even
> > though it's a v10 feature.
>
> Teodor, any chance for a response here?  It's not OK to commit something
> and then just not respond to bug-reports, especially when they're well
> diagnose and clearly point towards issues in a commit of yours.

Unfortunately, Teodor is unreachable at least till next week.

> Alexander, CCing you, perhaps you could point the thread out to Teodor?

I'll take a look at this issue.

------
Alexander Korotkov
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

Reply | Threaded
Open this post in threaded view
|

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

Alexander Korotkov-4
On Thu, Dec 6, 2018 at 10:56 PM Alexander Korotkov <[hidden email]> wrote:

> On Tue, Dec 4, 2018 at 8:01 PM Andres Freund <[hidden email]> wrote:
> > On 2018-11-10 17:42:16 -0800, Peter Geoghegan wrote:
> > > On Wed, Nov 7, 2018 at 5:46 PM Peter Geoghegan <[hidden email]> wrote:
> > > > Teodor: Do you think that the issue is fixable? It looks like there
> > > > are serious issues with the design of 218f51584d5 to me. I don't think
> > > > the general "there can't be any inserters at this subtree" thing works
> > > > given that we have to couple buffer locks when moving right for other
> > > > reasons. We call ginStepRight() within ginFinishSplit(), for reasons
> > > > that date back to bug fix commit ac4ab97e from 2013 -- that detail is
> > > > probably important, because it seems to be what breaks the subtree
> > > > design (we don't delete in two phases or anything in GIN).
> > >
> > > Ping?
> > >
> > > This is a thorny problem, and I'd like to get your input soon. I
> > > suspect that reverting 218f51584d5 may be the ultimate outcome, even
> > > though it's a v10 feature.
> >
> > Teodor, any chance for a response here?  It's not OK to commit something
> > and then just not respond to bug-reports, especially when they're well
> > diagnose and clearly point towards issues in a commit of yours.
>
> Unfortunately, Teodor is unreachable at least till next week.
>
> > Alexander, CCing you, perhaps you could point the thread out to Teodor?
>
> I'll take a look at this issue.

I've run through the thread.

So, algorithm introduced by 218f51584d5 is broken.  It tries to
guarantee that there are no inserters in the subtree by placing
cleanup lock to subtree root, assuming that inserter holds pins on the
path from root to leaf.  But due to concurrent splits of internal
pages the pins held can be not relevant to actual path.  I don't see
the way to fix this easily.  So, I think we should revert it from back
branches and try to reimplement that in master.

However, I'd like to note that 218f51584d5 introduces two changes:
1) Cleanup locking only if there pages to delete
2) Cleanup locking only subtree root
The 2nd one is broken.  But the 1st one seems still good for me and
useful, because in vast majority of cases vacuum doesn't delete any
index pages.  So, I propose to revert 218f51584d5, but leave there
logic, which locks root for cleanup only once there are pages to
delete.  Any thoughts?

------
Alexander Korotkov
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

Reply | Threaded
Open this post in threaded view
|

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

Peter Geoghegan-4
On Thu, Dec 6, 2018 at 12:51 PM Alexander Korotkov <[hidden email]> wrote:

> So, algorithm introduced by 218f51584d5 is broken.  It tries to
> guarantee that there are no inserters in the subtree by placing
> cleanup lock to subtree root, assuming that inserter holds pins on the
> path from root to leaf.  But due to concurrent splits of internal
> pages the pins held can be not relevant to actual path.  I don't see
> the way to fix this easily.  So, I think we should revert it from back
> branches and try to reimplement that in master.
>
> However, I'd like to note that 218f51584d5 introduces two changes:
> 1) Cleanup locking only if there pages to delete
> 2) Cleanup locking only subtree root
> The 2nd one is broken.  But the 1st one seems still good for me and
> useful, because in vast majority of cases vacuum doesn't delete any
> index pages.  So, I propose to revert 218f51584d5, but leave there
> logic, which locks root for cleanup only once there are pages to
> delete.  Any thoughts?

Can you post a patch that just removes the 2nd part, leaving the
still-correct first part?

Your proposal sounds reasonable, but I'd like to see what you have in
mind in detail before commenting.

Thanks
--
Peter Geoghegan

Reply | Threaded
Open this post in threaded view
|

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

Andrey Borodin-2
Hi!

> 7 дек. 2018 г., в 2:50, Peter Geoghegan <[hidden email]> написал(а):
>
> On Thu, Dec 6, 2018 at 12:51 PM Alexander Korotkov <[hidden email]> wrote:
>>
>> However, I'd like to note that 218f51584d5 introduces two changes:
>> 1) Cleanup locking only if there pages to delete
>> 2) Cleanup locking only subtree root
>> The 2nd one is broken.  But the 1st one seems still good for me and
>> useful, because in vast majority of cases vacuum doesn't delete any
>> index pages.  So, I propose to revert 218f51584d5, but leave there
>> logic, which locks root for cleanup only once there are pages to
>> delete.  Any thoughts?
>
> Can you post a patch that just removes the 2nd part, leaving the
> still-correct first part?
I like the idea of keeping cleanup lock only if there are pages to delete. It will still solve the original problem that caused proposals for GIN VACUUM enhancements.

But I must note that there is one more problem: ginVacuumPostingTreeLeaves() do not ensure that all splitted pages are visited. It copies downlink block numbers to a temp array and then unlocks parent. It is not correct way to scan posting tree for cleanup.

PFA diff with following changes:
1. Always take root cleanup lock before deleting pages
2. Check for concurrent splits after scanning page

Please note, that neither applying this diff nor reverting 218f51584d5 will solve bug of page delete redo lock on standby.

Best regards, Andrey Borodin.

gin_root_lock.diff (2K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

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

Alexander Korotkov-4
On Fri, Dec 7, 2018 at 12:14 PM Andrey Borodin <[hidden email]> wrote:

> > 7 дек. 2018 г., в 2:50, Peter Geoghegan <[hidden email]> написал(а):
> > On Thu, Dec 6, 2018 at 12:51 PM Alexander Korotkov <[hidden email]> wrote:
> >> However, I'd like to note that 218f51584d5 introduces two changes:
> >> 1) Cleanup locking only if there pages to delete
> >> 2) Cleanup locking only subtree root
> >> The 2nd one is broken.  But the 1st one seems still good for me and
> >> useful, because in vast majority of cases vacuum doesn't delete any
> >> index pages.  So, I propose to revert 218f51584d5, but leave there
> >> logic, which locks root for cleanup only once there are pages to
> >> delete.  Any thoughts?
> >
> > Can you post a patch that just removes the 2nd part, leaving the
> > still-correct first part?
>
> I like the idea of keeping cleanup lock only if there are pages to delete. It will still solve the original problem that caused proposals for GIN VACUUM enhancements.
>
> But I must note that there is one more problem: ginVacuumPostingTreeLeaves() do not ensure that all splitted pages are visited. It copies downlink block numbers to a temp array and then unlocks parent. It is not correct way to scan posting tree for cleanup.

Hmm... In ginVacuumPostingTreeLeaves() we visit pages from parent to
children.  This is why splitted pages might be unvisited.  Should we
visit leafpages by rightlinks instead?  Then, if we have candidates
for delete, ginScanToDelete() can work the same as before 218f51584d5.

> PFA diff with following changes:
> 1. Always take root cleanup lock before deleting pages
> 2. Check for concurrent splits after scanning page
>
> Please note, that neither applying this diff nor reverting 218f51584d5 will solve bug of page delete redo lock on standby.

ginRedoDeletePage() visits pages in following order: right(to be
deleted), parent, left.  I didn't find any description of why it has
been done so.  Any guesses don't we visit parent page first here?

------
Alexander Korotkov
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

12