| From: | Marco Boeringa <marco(at)boeringa(dot)demon(dot)nl> |
|---|---|
| To: | Andres Freund <andres(at)anarazel(dot)de> |
| Cc: | pgsql-bugs(at)lists(dot)postgresql(dot)org, Thom Brown <thom(at)linux(dot)com> |
| Subject: | Re: Potential "AIO / io workers" inter-worker locking issue in PG18? |
| Date: | 2025-10-08 17:46:42 |
| Message-ID: | 9d2027e4-ff80-4da9-90d6-4a7af58a1d9e@boeringa.demon.nl |
| Views: | Whole Thread | Raw Message | Download mbox | Resend email |
| Thread: | |
| Lists: | pgsql-bugs |
Hi Andres,
Thanks for all the help and suggestions so far!
> Can you test this with postgis 3.6 on 17?
If I find time... but looking through the release notes of PostGIS
3.6.0, I doubt the issue is in PostGIS, as there do not appear to be any
changes to the specific PostGIS functions I am using. That doesn't
exclude it though.
> The fact that it runs without a problem in 17 means it's actually
rather meaningful to look at the query plan. It could have changed.
Separately, it might help us to narrow down what changes to look at that
could potentially be causing problems.
I would fully understand if this was an "ordinary" issue case with a
simple self-contained query and with things going wrong each time in the
same way. However, as said, besides the major issue of running the query
separately from my geoprocessing workflow which involves many more steps
- which would mean that any test outside of it would *not* be very much
representative of what is going on inside my tool and geoprocessing
workflow - there is the fact that things going wrong is a random
anomaly. I cannot stress this enough: about 3-4 in 5 runs are OK, then a
random follow up run *with exactly the same input data* turns out bad
with the stall. Even if there was an easy way to run the query, I think
the chance is highly likely the postgres query planner would come up
with a decent plan, as in normal circumstances, there is no issue.
> Making vacuum more aggressive won't really help much if you have
longrunning queries/sessions, since vacuum can't clean up row versions
that are still visibile to some of the transactions.
My code batches the updates in sets of 2000 records at a time and then
COMMITs, so the transactions themselves are limited in time and size,
which should allow vacuum to do its job.
> Could you "unfold" the callstacks for the top entries? And/or attach
a perf report --no-children > somefile (when redirecting to a file perf
will include much more detail than when using it interactively)
See below:
# Total Lost Samples: 0
#
# Samples: 40K of event 'task-clock:ppp'
# Event count (approx.): 10003250000
#
# Overhead Command Shared Object Symbol
# ........ ........ .................
...........................................
#
26.48% postgres postgres [.] LWLockAttemptLock
|
---LWLockAttemptLock
|
|--23.15%--heapam_index_fetch_tuple.lto_priv.0
| index_fetch_heap
| IndexNext
| ExecScan
| ExecNestLoop
| ExecNestLoop
| ExecModifyTable
| standard_ExecutorRun
| ProcessQuery
| PortalRunMulti
| PortalRun
| exec_simple_query
| PostgresMain
| 0x5f3570fb9dbf
| postmaster_child_launch
| ServerLoop.isra.0
| PostmasterMain
| main
| __libc_start_call_main
| __libc_start_main@@GLIBC_2.34
| _start
|
--3.30%--StartReadBuffer
ReadBufferExtended
|
--3.25%--heapam_index_fetch_tuple.lto_priv.0
index_fetch_heap
IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
15.81% postgres postgres [.] LWLockReleaseInternal
|
---LWLockReleaseInternal
|
--15.71%--LWLockRelease
|
|--15.03%--heapam_index_fetch_tuple.lto_priv.0
| index_fetch_heap
| IndexNext
| ExecScan
| ExecNestLoop
| ExecNestLoop
| ExecModifyTable
| standard_ExecutorRun
| ProcessQuery
| PortalRunMulti
| PortalRun
| exec_simple_query
| PostgresMain
| 0x5f3570fb9dbf
| postmaster_child_launch
| ServerLoop.isra.0
| PostmasterMain
| main
| __libc_start_call_main
| __libc_start_main@@GLIBC_2.34
| _start
|
--0.66%--StartReadBuffer
ReadBufferExtended
|
--0.66%--heapam_index_fetch_tuple.lto_priv.0
index_fetch_heap
IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
12.88% postgres postgres [.] ReleaseAndReadBuffer
|
---ReleaseAndReadBuffer
|
--12.78%--heapam_index_fetch_tuple.lto_priv.0
index_fetch_heap
IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
4.84% postgres postgres [.]
tts_heap_getsomeattrs.lto_priv.0
|
---tts_heap_getsomeattrs.lto_priv.0
|
--4.80%--slot_getsomeattrs_int
ExecInterpExpr
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
4.64% postgres postgres [.] PinBuffer
|
---PinBuffer
|
--4.64%--StartReadBuffer
ReadBufferExtended
|
--4.57%--heapam_index_fetch_tuple.lto_priv.0
index_fetch_heap
IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
3.67% postgres postgres [.] heap_hot_search_buffer
|
---heap_hot_search_buffer
|
--3.61%--heapam_index_fetch_tuple.lto_priv.0
index_fetch_heap
IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
3.47% postgres postgres [.] hash_search_with_hash_value
|
---hash_search_with_hash_value
|
--3.45%--StartReadBuffer
ReadBufferExtended
|
--3.35%--heapam_index_fetch_tuple.lto_priv.0
index_fetch_heap
IndexNext
ExecScan
ExecNestLoop
|
--3.34%--ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
2.97% postgres postgres [.] ExecInterpExpr
|
---ExecInterpExpr
|
|--1.64%--ExecNestLoop
| |
| --1.60%--ExecNestLoop
| ExecModifyTable
| standard_ExecutorRun
| ProcessQuery
| PortalRunMulti
| PortalRun
| exec_simple_query
| PostgresMain
| 0x5f3570fb9dbf
| postmaster_child_launch
| ServerLoop.isra.0
| PostmasterMain
| main
| __libc_start_call_main
| __libc_start_main@@GLIBC_2.34
| _start
|
--1.33%--ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
2.11% postgres postgres [.] UnpinBufferNoOwner.lto_priv.0
|
---UnpinBufferNoOwner.lto_priv.0
|
|--1.24%--ExecStoreBufferHeapTuple
| heapam_index_fetch_tuple.lto_priv.0
| index_fetch_heap
| IndexNext
| ExecScan
| ExecNestLoop
| ExecNestLoop
| ExecModifyTable
| standard_ExecutorRun
| ProcessQuery
| PortalRunMulti
| PortalRun
| exec_simple_query
| PostgresMain
| 0x5f3570fb9dbf
| postmaster_child_launch
| ServerLoop.isra.0
| PostmasterMain
| main
| __libc_start_call_main
| __libc_start_main@@GLIBC_2.34
| _start
|
--0.81%--ReleaseAndReadBuffer
heapam_index_fetch_tuple.lto_priv.0
index_fetch_heap
IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
1.92% postgres postgres [.]
heapam_index_fetch_tuple.lto_priv.0
|
---heapam_index_fetch_tuple.lto_priv.0
|
--1.67%--index_fetch_heap
IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
1.88% postgres postgres [.] StartReadBuffer
|
---StartReadBuffer
|
--1.86%--ReadBufferExtended
|
--1.83%--heapam_index_fetch_tuple.lto_priv.0
index_fetch_heap
IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
1.41% postgres postgres [.] LWLockAcquire
|
---LWLockAcquire
|
--1.15%--heapam_index_fetch_tuple.lto_priv.0
index_fetch_heap
IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
1.12% postgres postgres [.] heap_page_prune_opt
|
---heap_page_prune_opt
|
--1.12%--heapam_index_fetch_tuple.lto_priv.0
index_fetch_heap
IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
1.09% postgres postgres [.] HeapTupleSatisfiesVisibility
|
---HeapTupleSatisfiesVisibility
|
--1.02%--heap_hot_search_buffer
heapam_index_fetch_tuple.lto_priv.0
index_fetch_heap
IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
1.00% postgres postgres [.] index_fetch_heap
|
---index_fetch_heap
|
--0.83%--IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
0.97% postgres postgres [.] _bt_readpage
|
---_bt_readpage
|
--0.97%--_bt_readnextpage
_bt_next
btgettuple
index_getnext_tid
IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
0.92% postgres postgres [.] _bt_next
|
---_bt_next
|
--0.82%--btgettuple
index_getnext_tid
IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
0.92% postgres postgres [.] index_getnext_tid
|
---index_getnext_tid
|
--0.82%--IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
0.90% postgres postgres [.] ExecScan
|
---ExecScan
ExecNestLoop
|
--0.83%--ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
0.85% postgres postgres [.] IndexNext
|
---IndexNext
|
--0.80%--ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
0.83% postgres postgres [.] XidInMVCCSnapshot
|
---XidInMVCCSnapshot
0.81% postgres postgres [.] LWLockRelease
|
---LWLockRelease
|
--0.54%--heapam_index_fetch_tuple.lto_priv.0
index_fetch_heap
IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
0.71% postgres postgres [.] _bt_checkkeys
|
---_bt_checkkeys
|
--0.65%--_bt_readpage
_bt_readnextpage
_bt_next
btgettuple
index_getnext_tid
IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
0.69% postgres postgres [.] ReleaseBuffer
|
---ReleaseBuffer
|
--0.68%--ExecStoreBufferHeapTuple
heapam_index_fetch_tuple.lto_priv.0
index_fetch_heap
IndexNext
ExecScan
ExecNestLoop
ExecNestLoop
ExecModifyTable
standard_ExecutorRun
ProcessQuery
PortalRunMulti
PortalRun
exec_simple_query
PostgresMain
0x5f3570fb9dbf
postmaster_child_launch
ServerLoop.isra.0
PostmasterMain
main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
0.57% postgres postgres [.]
GetPrivateRefCountEntry.lto_priv.0
|
---GetPrivateRefCountEntry.lto_priv.0
0.53% postgres postgres [.] btgettuple
|
---btgettuple
0.48% postgres postgres [.] _bt_check_compare.lto_priv.0
0.46% postgres postgres [.] MemoryContextReset
0.42% postgres postgres [.] hash_bytes
0.40% postgres postgres [.] ExecStoreBufferHeapTuple
0.36% postgres postgres [.] ResourceOwnerForget
0.35% postgres postgres [.] ExecNestLoop
0.33% postgres postgres [.] ExecEvalSysVar
0.32% postgres postgres [.] HeapTupleIsSurelyDead
0.27% postgres postgres [.] GlobalVisTestFor
0.26% postgres postgres [.] PredicateLockTID
0.22% postgres postgres [.] ReadBufferExtended
0.22% postgres postgres [.] tts_virtual_clear.lto_priv.0
0.21% postgres postgres [.] slot_getsomeattrs_int
0.19% postgres postgres [.] _bt_saveitem
0.19% postgres postgres [.] _bt_setuppostingitems
0.18% postgres postgres [.] ResourceOwnerEnlarge
0.17% postgres postgres [.] ExecIndexScan
0.14% postgres libc.so.6 [.] __memcmp_sse2
0.12% postgres postgres [.] pgstat_count_io_op
0.10% postgres postgres [.] int8eq
0.10% postgres postgres [.]
HeapCheckForSerializableConflictOut
0.10% postgres postgres [.]
ReservePrivateRefCountEntry.lto_priv.0
0.09% postgres postgres [.] IncrBufferRefCount
0.06% postgres postgres [.] _bt_checkpage
0.03% postgres postgres [.] BufferGetLSNAtomic
0.03% postgres postgres [.] tag_hash
0.03% postgres postgres [.] LockBufHdr
0.03% postgres postgres [.] _bt_readnextpage
0.02% postgres postgres [.]
tts_buffer_heap_getsomeattrs.lto_priv.0
0.02% postgres [kernel.kallsyms] [k] handle_softirqs
0.01% postgres postgres [.] _bt_steppage
0.01% postgres [kernel.kallsyms] [k] task_mm_cid_work
0.00% postgres [kernel.kallsyms] [k] _raw_spin_unlock_irq
0.00% postgres [kernel.kallsyms] [k] irqentry_exit_to_user_mode
0.00% postgres postgres [.]
TransactionIdIsCurrentTransactionId
0.00% postgres postgres [.] index_rescan
0.00% postgres [kernel.kallsyms] [k] _raw_spin_unlock_irqrestore
0.00% postgres postgres [.] AllocSetAlloc
0.00% postgres postgres [.] PredicateLockPage
0.00% postgres postgres [.] _bt_set_startikey
| From | Date | Subject | |
|---|---|---|---|
| Next Message | Andres Freund | 2025-10-08 19:08:28 | Re: Potential "AIO / io workers" inter-worker locking issue in PG18? |
| Previous Message | Andres Freund | 2025-10-08 13:07:45 | Re: Potential "AIO / io workers" inter-worker locking issue in PG18? |