Re: Potential "AIO / io workers" inter-worker locking issue in PG18?

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 10:04:20
Message-ID: 4cc396f3-6508-4e25-a6da-efdd4f939946@boeringa.demon.nl
Views: Whole Thread | Raw Message | Download mbox | Resend email
Thread:
Lists: pgsql-bugs

> Could you show perf report --no-children? That would show us which individual
> functions, rather than call-stacks, take the longest.

Andres, I now captured a few more 'perf' sessions.

Run 1 is the original run I already showed you. For comparison, runs 2-4
are from a different backend captured during a new geoprocessing run,
but all refering to same PID. Run 5 is also from the same geoprocessing
run, but another backend PID, so another python thread launched from my
code.

Not much difference between all of these, especially the ordinary "perf
report", the "perf report --no children" show a little more
variation. "perf report --no children" runs are grouped together at the
bottom of the email.

Despite the minor differences, maybe seeing different captures of perf
is still of some use.

Marco

*** sudo perf -p <PID of one stuck postgres backend> -g -d 10 ***
*** sudo perf report -g ***

RUN 1:
Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10008250000
  Children      Self  Command   Shared Object      Symbol
+  100,00%     0,00%  postgres  postgres           [.] _start
+  100,00%     0,00%  postgres  libc.so.6          [.]
__libc_start_main@@GLIBC_2.34
+  100,00%     0,00%  postgres  libc.so.6          [.]
__libc_start_call_main
+  100,00%     0,00%  postgres  postgres           [.] main
+  100,00%     0,00%  postgres  postgres           [.] PostmasterMain
+  100,00%     0,00%  postgres  postgres           [.] ServerLoop.isra.0
+  100,00%     0,00%  postgres  postgres           [.]
postmaster_child_launch
+  100,00%     0,00%  postgres  postgres           [.] 0x00005f3570fb9dbf
+  100,00%     0,00%  postgres  postgres           [.] PostgresMain
+  100,00%     0,00%  postgres  postgres           [.] exec_simple_query
+  100,00%     0,63%  postgres  postgres           [.] ExecNestLoop
+  100,00%     0,00%  postgres  postgres           [.] PortalRun
+  100,00%     0,00%  postgres  postgres           [.] PortalRunMulti
+  100,00%     0,00%  postgres  postgres           [.] ProcessQuery
+  100,00%     0,00%  postgres  postgres           [.] standard_ExecutorRun
+  100,00%     0,00%  postgres  postgres           [.] ExecModifyTable
+   94,63%     1,47%  postgres  postgres           [.] ExecScan
+   78,76%     1,49%  postgres  postgres           [.] IndexNext
+   66,89%     1,96%  postgres  postgres           [.] index_fetch_heap
+   64,35%     3,61%  postgres  postgres           [.]
heapam_index_fetch_tuple.lto_priv.0
+   21,92%     0,40%  postgres  postgres           [.] ReadBufferExtended
+   20,36%     1,19%  postgres  postgres           [.] StartReadBuffer
+   16,23%     5,79%  postgres  postgres           [.] ExecInterpExpr
+   15,00%    10,70%  postgres  postgres           [.]
heap_hot_search_buffer
+   12,81%    12,81%  postgres  postgres           [.] LWLockAttemptLock
+   10,31%     2,36%  postgres  postgres           [.] index_getnext_tid
+    9,69%     0,48%  postgres  postgres           [.] slot_getsomeattrs_int
+    9,27%     9,27%  postgres  postgres           [.]
tts_heap_getsomeattrs.lto_priv.0
+    8,45%     1,85%  postgres  postgres           [.] LWLockRelease
+    7,91%     1,08%  postgres  postgres           [.] btgettuple
+    6,89%     1,12%  postgres  postgres           [.] _bt_next
+    6,77%     6,77%  postgres  postgres           [.] LWLockReleaseInternal
+    5,89%     5,89%  postgres  postgres           [.]
hash_search_with_hash_value
+    5,78%     0,10%  postgres  postgres           [.] _bt_readnextpage
+    4,48%     4,14%  postgres  postgres           [.] PinBuffer
+    4,41%     1,90%  postgres  postgres           [.] _bt_readpage
+    4,09%     3,00%  postgres  postgres           [.] ReleaseAndReadBuffer
+    2,99%     2,38%  postgres  postgres           [.]
HeapTupleSatisfiesVisibility
+    2,58%     0,82%  postgres  postgres           [.]
ExecStoreBufferHeapTuple
+    2,43%     2,43%  postgres  postgres           [.] LWLockAcquire
+    2,28%     1,47%  postgres  postgres           [.] _bt_checkkeys
+    1,74%     1,74%  postgres  postgres           [.] heap_page_prune_opt
+    1,67%     1,10%  postgres  postgres           [.]
UnpinBufferNoOwner.lto_priv.0
+    1,47%     1,47%  postgres  postgres           [.] XidInMVCCSnapshot
+    1,18%     1,18%  postgres  postgres           [.]
GetPrivateRefCountEntry.lto_priv.0
+    1,09%     1,09%  postgres  postgres           [.] MemoryContextReset

RUN 2:
amples: 40K of event 'task-clock:ppp', Event count (approx.): 10020750000
  Children      Self  Command   Shared Object     Symbol
+  100,00%     0,00%  postgres  postgres          [.] _start
+  100,00%     0,00%  postgres  libc.so.6         [.]
__libc_start_main@@GLIBC_2.34
+  100,00%     0,00%  postgres  libc.so.6         [.] __libc_start_call_main
+  100,00%     0,00%  postgres  postgres          [.] main
+  100,00%     0,00%  postgres  postgres          [.] PostmasterMain
+  100,00%     0,00%  postgres  postgres          [.] ServerLoop.isra.0
+  100,00%     0,00%  postgres  postgres          [.]
postmaster_child_launch
+  100,00%     0,00%  postgres  postgres          [.] 0x00005f3570fb9dbf
+  100,00%     0,00%  postgres  postgres          [.] PostgresMain
+  100,00%     0,00%  postgres  postgres          [.] exec_simple_query
+  100,00%     0,34%  postgres  postgres          [.] ExecNestLoop
+  100,00%     0,00%  postgres  postgres          [.] PortalRun
+  100,00%     0,00%  postgres  postgres          [.] PortalRunMulti
+  100,00%     0,00%  postgres  postgres          [.] ProcessQuery
+  100,00%     0,00%  postgres  postgres          [.] standard_ExecutorRun
+  100,00%     0,00%  postgres  postgres          [.] ExecModifyTable
+   97,34%     1,13%  postgres  postgres          [.] ExecScan
+   88,55%     0,73%  postgres  postgres          [.] IndexNext
+   82,41%     1,05%  postgres  postgres          [.] index_fetch_heap
+   81,10%     1,78%  postgres  postgres          [.]
heapam_index_fetch_tuple.lto_priv.0
+   25,70%    25,70%  postgres  postgres          [.] LWLockAttemptLock
+   16,67%     0,86%  postgres  postgres          [.] LWLockRelease
+   15,91%    15,91%  postgres  postgres          [.] LWLockReleaseInternal
+   15,27%     0,22%  postgres  postgres          [.] ReadBufferExtended
+   14,41%     1,73%  postgres  postgres          [.] StartReadBuffer
+   14,11%    13,01%  postgres  postgres          [.] ReleaseAndReadBuffer
+    8,60%     3,08%  postgres  postgres          [.] ExecInterpExpr
+    6,27%     3,90%  postgres  postgres          [.] heap_hot_search_buffer
+    5,36%     1,11%  postgres  postgres          [.] index_getnext_tid
+    5,20%     0,20%  postgres  postgres          [.] slot_getsomeattrs_int
+    5,05%     5,05%  postgres  postgres          [.]
tts_heap_getsomeattrs.lto_priv.0
+    4,74%     4,59%  postgres  postgres          [.] PinBuffer
+    4,21%     0,54%  postgres  postgres          [.] btgettuple
+    3,75%     0,72%  postgres  postgres          [.] _bt_next
+    3,27%     3,27%  postgres  postgres          [.]
hash_search_with_hash_value
+    3,04%     0,03%  postgres  postgres          [.] _bt_readnextpage
+    3,00%     0,44%  postgres  postgres          [.]
ExecStoreBufferHeapTuple
+    2,43%     2,16%  postgres  postgres          [.]
UnpinBufferNoOwner.lto_priv.0
+    2,24%     1,01%  postgres  postgres          [.] _bt_readpage
+    1,62%     1,25%  postgres  postgres          [.]
HeapTupleSatisfiesVisibility
+    1,51%     1,51%  postgres  postgres          [.] LWLockAcquire
+    1,18%     1,18%  postgres  postgres          [.] heap_page_prune_opt
+    1,07%     0,72%  postgres  postgres          [.] _bt_checkkeys
+    0,85%     0,85%  postgres  postgres          [.] XidInMVCCSnapshot
+    0,82%     0,74%  postgres  postgres          [.] ReleaseBuffer
+    0,56%     0,56%  postgres  postgres          [.]
GetPrivateRefCountEntry.lto_priv.0
     0,41%     0,41%  postgres  postgres          [.]
_bt_check_compare.lto_priv.0

RUN 3:
Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10010750000
  Children      Self  Command   Shared Object     Symbol
+  100,00%     0,00%  postgres  postgres          [.] _start
+  100,00%     0,00%  postgres  libc.so.6         [.]
__libc_start_main@@GLIBC_2.34
+  100,00%     0,00%  postgres  libc.so.6         [.] __libc_start_call_main
+  100,00%     0,00%  postgres  postgres          [.] main
+  100,00%     0,00%  postgres  postgres          [.] PostmasterMain
+  100,00%     0,00%  postgres  postgres          [.] ServerLoop.isra.0
+  100,00%     0,00%  postgres  postgres          [.]
postmaster_child_launch
+  100,00%     0,00%  postgres  postgres          [.] 0x00005f3570fb9dbf
+  100,00%     0,00%  postgres  postgres          [.] PostgresMain
+  100,00%     0,00%  postgres  postgres          [.] exec_simple_query
+  100,00%     0,34%  postgres  postgres          [.] ExecNestLoop
+  100,00%     0,00%  postgres  postgres          [.] PortalRun
+  100,00%     0,00%  postgres  postgres          [.] PortalRunMulti
+  100,00%     0,00%  postgres  postgres          [.] ProcessQuery
+  100,00%     0,00%  postgres  postgres          [.] standard_ExecutorRun
+  100,00%     0,00%  postgres  postgres          [.] ExecModifyTable
+   97,43%     1,10%  postgres  postgres          [.] ExecScan
+   88,96%     0,79%  postgres  postgres          [.] IndexNext
+   82,68%     1,03%  postgres  postgres          [.] index_fetch_heap
+   81,42%     1,89%  postgres  postgres          [.]
heapam_index_fetch_tuple.lto_priv.0
+   25,54%    25,54%  postgres  postgres          [.] LWLockAttemptLock
+   17,38%     1,01%  postgres  postgres          [.] LWLockRelease
+   16,44%    16,44%  postgres  postgres          [.] LWLockReleaseInternal
+   15,39%     0,25%  postgres  postgres          [.] ReadBufferExtended
+   14,49%     1,69%  postgres  postgres          [.] StartReadBuffer
+   13,77%    12,72%  postgres  postgres          [.] ReleaseAndReadBuffer
+    8,28%     2,95%  postgres  postgres          [.] ExecInterpExpr
+    6,05%     3,75%  postgres  postgres          [.] heap_hot_search_buffer
+    5,39%     1,09%  postgres  postgres          [.] index_getnext_tid
+    5,05%     0,21%  postgres  postgres          [.] slot_getsomeattrs_int
+    4,88%     4,88%  postgres  postgres          [.]
tts_heap_getsomeattrs.lto_priv.0
+    4,87%     4,69%  postgres  postgres          [.] PinBuffer
+    4,29%     0,61%  postgres  postgres          [.] btgettuple
+    3,74%     0,74%  postgres  postgres          [.] _bt_next
+    3,47%     3,47%  postgres  postgres          [.]
hash_search_with_hash_value
+    3,00%     0,05%  postgres  postgres          [.] _bt_readnextpage
+    2,99%     0,50%  postgres  postgres          [.]
ExecStoreBufferHeapTuple
+    2,27%     2,01%  postgres  postgres          [.]
UnpinBufferNoOwner.lto_priv.0
+    2,19%     0,99%  postgres  postgres          [.] _bt_readpage
+    1,52%     1,14%  postgres  postgres          [.]
HeapTupleSatisfiesVisibility
+    1,50%     1,50%  postgres  postgres          [.] LWLockAcquire
+    1,12%     1,12%  postgres  postgres          [.] heap_page_prune_opt
+    1,06%     0,72%  postgres  postgres          [.] _bt_checkkeys
+    0,87%     0,87%  postgres  postgres          [.] XidInMVCCSnapshot
+    0,87%     0,76%  postgres  postgres          [.] ReleaseBuffer
+    0,59%     0,59%  postgres  postgres          [.]
GetPrivateRefCountEntry.lto_priv.0
     0,41%     0,41%  postgres  postgres          [.]
_bt_check_compare.lto_priv.0

RUN 4:
Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10010500000
  Children      Self  Command   Shared Object     Symbol
+  100,00%     0,00%  postgres  postgres          [.] _start
+  100,00%     0,00%  postgres  libc.so.6         [.]
__libc_start_main@@GLIBC_2.34
+  100,00%     0,00%  postgres  libc.so.6         [.] __libc_start_call_main
+  100,00%     0,00%  postgres  postgres          [.] main
+  100,00%     0,00%  postgres  postgres          [.] PostmasterMain
+  100,00%     0,00%  postgres  postgres          [.] ServerLoop.isra.0
+  100,00%     0,00%  postgres  postgres          [.]
postmaster_child_launch
+  100,00%     0,00%  postgres  postgres          [.] 0x00005f3570fb9dbf
+  100,00%     0,00%  postgres  postgres          [.] PostgresMain
+  100,00%     0,00%  postgres  postgres          [.] exec_simple_query
+  100,00%     0,32%  postgres  postgres          [.] ExecNestLoop
+  100,00%     0,00%  postgres  postgres          [.] PortalRun
+  100,00%     0,00%  postgres  postgres          [.] PortalRunMulti
+  100,00%     0,00%  postgres  postgres          [.] ProcessQuery
+  100,00%     0,00%  postgres  postgres          [.] standard_ExecutorRun
+  100,00%     0,00%  postgres  postgres          [.] ExecModifyTable
+   97,30%     1,16%  postgres  postgres          [.] ExecScan
+   88,81%     0,73%  postgres  postgres          [.] IndexNext
+   82,49%     0,99%  postgres  postgres          [.] index_fetch_heap
+   81,18%     2,01%  postgres  postgres          [.]
heapam_index_fetch_tuple.lto_priv.0
+   25,65%    25,65%  postgres  postgres          [.] LWLockAttemptLock
+   16,65%     1,01%  postgres  postgres          [.] LWLockRelease
+   15,79%     0,26%  postgres  postgres          [.] ReadBufferExtended
+   15,76%    15,76%  postgres  postgres          [.] LWLockReleaseInternal
+   15,00%     1,65%  postgres  postgres          [.] StartReadBuffer
+   13,88%    12,75%  postgres  postgres          [.] ReleaseAndReadBuffer
+    8,41%     3,03%  postgres  postgres          [.] ExecInterpExpr
+    6,13%     3,82%  postgres  postgres          [.] heap_hot_search_buffer
+    5,46%     1,04%  postgres  postgres          [.] index_getnext_tid
+    5,02%     0,23%  postgres  postgres          [.] slot_getsomeattrs_int
+    4,94%     4,78%  postgres  postgres          [.] PinBuffer
+    4,83%     4,83%  postgres  postgres          [.]
tts_heap_getsomeattrs.lto_priv.0
+    4,40%     0,58%  postgres  postgres          [.] btgettuple
+    3,87%     0,79%  postgres  postgres          [.] _bt_next
+    3,76%     3,76%  postgres  postgres          [.]
hash_search_with_hash_value
+    3,09%     0,05%  postgres  postgres          [.] _bt_readnextpage
+    2,88%     0,46%  postgres  postgres          [.]
ExecStoreBufferHeapTuple
+    2,44%     2,11%  postgres  postgres          [.]
UnpinBufferNoOwner.lto_priv.0
+    2,26%     1,01%  postgres  postgres          [.] _bt_readpage
+    1,53%     1,16%  postgres  postgres          [.]
HeapTupleSatisfiesVisibility
+    1,45%     1,45%  postgres  postgres          [.] LWLockAcquire
+    1,17%     1,17%  postgres  postgres          [.] heap_page_prune_opt
+    1,09%     0,72%  postgres  postgres          [.] _bt_checkkeys
+    0,82%     0,82%  postgres  postgres          [.] XidInMVCCSnapshot
+    0,80%     0,71%  postgres  postgres          [.] ReleaseBuffer
+    0,63%     0,63%  postgres  postgres          [.]
GetPrivateRefCountEntry.lto_priv.0
     0,44%     0,44%  postgres  postgres          [.]
_bt_check_compare.lto_priv.0

RUN 5:
Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10003250000
  Children      Self  Command   Shared Object      Symbol
+  100,00%     0,00%  postgres  postgres           [.] _start
+  100,00%     0,00%  postgres  libc.so.6          [.]
__libc_start_main@@GLIBC_2.34
+  100,00%     0,00%  postgres  libc.so.6          [.]
__libc_start_call_main
+  100,00%     0,00%  postgres  postgres           [.] main
+  100,00%     0,00%  postgres  postgres           [.] PostmasterMain
+  100,00%     0,00%  postgres  postgres           [.] ServerLoop.isra.0
+  100,00%     0,00%  postgres  postgres           [.]
postmaster_child_launch
+  100,00%     0,00%  postgres  postgres           [.] 0x00005f3570fb9dbf
+  100,00%     0,00%  postgres  postgres           [.] PostgresMain
+  100,00%     0,00%  postgres  postgres           [.] exec_simple_query
+  100,00%     0,00%  postgres  postgres           [.] PortalRun
+  100,00%     0,00%  postgres  postgres           [.] PortalRunMulti
+  100,00%     0,00%  postgres  postgres           [.] ProcessQuery
+  100,00%     0,00%  postgres  postgres           [.] standard_ExecutorRun
+  100,00%     0,00%  postgres  postgres           [.] ExecModifyTable
+  100,00%     0,35%  postgres  postgres           [.] ExecNestLoop
+   97,20%     0,90%  postgres  postgres           [.] ExecScan
+   89,12%     0,85%  postgres  postgres           [.] IndexNext
+   82,86%     1,00%  postgres  postgres           [.] index_fetch_heap
+   81,60%     1,92%  postgres  postgres           [.]
heapam_index_fetch_tuple.lto_priv.0
+   26,49%    26,48%  postgres  postgres           [.] LWLockAttemptLock
+   16,53%     0,81%  postgres  postgres           [.] LWLockRelease
+   15,81%    15,81%  postgres  postgres           [.] LWLockReleaseInternal
+   15,57%     0,22%  postgres  postgres           [.] ReadBufferExtended
+   14,68%     1,88%  postgres  postgres           [.] StartReadBuffer
+   14,10%    12,88%  postgres  postgres           [.] ReleaseAndReadBuffer
+    8,27%     2,97%  postgres  postgres           [.] ExecInterpExpr
+    5,87%     3,67%  postgres  postgres           [.]
heap_hot_search_buffer
+    5,38%     0,92%  postgres  postgres           [.] index_getnext_tid
+    5,01%     0,21%  postgres  postgres           [.] slot_getsomeattrs_int
+    4,85%     4,84%  postgres  postgres           [.]
tts_heap_getsomeattrs.lto_priv.0
+    4,81%     4,64%  postgres  postgres           [.] PinBuffer
+    4,41%     0,53%  postgres  postgres           [.] btgettuple
+    3,96%     0,92%  postgres  postgres           [.] _bt_next
+    3,47%     3,47%  postgres  postgres           [.]
hash_search_with_hash_value
+    3,03%     0,03%  postgres  postgres           [.] _bt_readnextpage
+    2,77%     0,40%  postgres  postgres           [.]
ExecStoreBufferHeapTuple
+    2,41%     2,11%  postgres  postgres           [.]
UnpinBufferNoOwner.lto_priv.0
+    2,28%     0,97%  postgres  postgres           [.] _bt_readpage
+    1,46%     1,09%  postgres  postgres           [.]
HeapTupleSatisfiesVisibility
+    1,41%     1,41%  postgres  postgres           [.] LWLockAcquire
+    1,14%     0,71%  postgres  postgres           [.] _bt_checkkeys
+    1,12%     1,12%  postgres  postgres           [.] heap_page_prune_opt
+    0,83%     0,83%  postgres  postgres           [.] XidInMVCCSnapshot
+    0,81%     0,69%  postgres  postgres           [.] ReleaseBuffer
+    0,57%     0,57%  postgres  postgres           [.]
GetPrivateRefCountEntry.lto_priv.0
     0,48%     0,48%  postgres  postgres           [.]
_bt_check_compare.lto_priv.0

*** sudo perf -p <PID of one stuck postgres backend> -g -d 10 ***
*** sudo perf report --no-children ***

RUN 1 - NO CHILDREN:
Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10008250000
  Overhead  Command   Shared Object      Symbol
+   12,81%  postgres  postgres           [.] LWLockAttemptLock
+   10,70%  postgres  postgres           [.] heap_hot_search_buffer
+    9,27%  postgres  postgres           [.]
tts_heap_getsomeattrs.lto_priv.0
+    6,77%  postgres  postgres           [.] LWLockReleaseInternal
+    5,89%  postgres  postgres           [.] hash_search_with_hash_value
+    5,79%  postgres  postgres           [.] ExecInterpExpr
+    4,14%  postgres  postgres           [.] PinBuffer
+    3,61%  postgres  postgres           [.]
heapam_index_fetch_tuple.lto_priv.0
+    3,00%  postgres  postgres           [.] ReleaseAndReadBuffer
+    2,43%  postgres  postgres           [.] LWLockAcquire
+    2,38%  postgres  postgres           [.] HeapTupleSatisfiesVisibility
+    2,36%  postgres  postgres           [.] index_getnext_tid
+    1,96%  postgres  postgres           [.] index_fetch_heap
+    1,90%  postgres  postgres           [.] _bt_readpage
+    1,85%  postgres  postgres           [.] LWLockRelease
+    1,74%  postgres  postgres           [.] heap_page_prune_opt
+    1,49%  postgres  postgres           [.] IndexNext
+    1,47%  postgres  postgres           [.] _bt_checkkeys
+    1,47%  postgres  postgres           [.] ExecScan
+    1,47%  postgres  postgres           [.] XidInMVCCSnapshot
+    1,19%  postgres  postgres           [.] StartReadBuffer
+    1,18%  postgres  postgres           [.]
GetPrivateRefCountEntry.lto_priv.0
+    1,12%  postgres  postgres           [.] _bt_next
+    1,10%  postgres  postgres           [.] UnpinBufferNoOwner.lto_priv.0
+    1,09%  postgres  postgres           [.] MemoryContextReset
+    1,08%  postgres  postgres           [.] btgettuple
+    0,91%  postgres  postgres           [.] _bt_check_compare.lto_priv.0
+    0,82%  postgres  postgres           [.] ExecEvalSysVar
+    0,82%  postgres  postgres           [.] ExecStoreBufferHeapTuple
+    0,71%  postgres  postgres           [.] hash_bytes
+    0,65%  postgres  postgres           [.] tts_virtual_clear.lto_priv.0
+    0,63%  postgres  postgres           [.] GlobalVisTestFor
+    0,63%  postgres  postgres           [.] ExecNestLoop
+    0,55%  postgres  postgres           [.] HeapTupleIsSurelyDead
+    0,52%  postgres  postgres           [.] ResourceOwnerForget
     0,48%  postgres  postgres           [.] slot_getsomeattrs_int
     0,42%  postgres  postgres           [.] PredicateLockTID
     0,40%  postgres  postgres           [.] ReadBufferExtended
     0,37%  postgres  postgres           [.] _bt_saveitem
     0,31%  postgres  postgres           [.] ExecIndexScan
     0,30%  postgres  libc.so.6          [.] __memcmp_sse2
     0,28%  postgres  postgres           [.] _bt_setuppostingitems
     0,26%  postgres  postgres           [.] ReleaseBuffer
     0,23%  postgres  postgres           [.] ResourceOwnerEnlarge
     0,23%  postgres  postgres           [.]
HeapCheckForSerializableConflictOut
     0,22%  postgres  postgres           [.] IncrBufferRefCount
     0,18%  postgres  postgres           [.] pgstat_count_io_op

RUN 2 - NO CHILDREN:
Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10020750000
  Overhead  Command   Shared Object  Symbol
+   25,70%  postgres  postgres       [.] LWLockAttemptLock
+   15,91%  postgres  postgres       [.] LWLockReleaseInternal
+   13,01%  postgres  postgres       [.] ReleaseAndReadBuffer
+    5,05%  postgres  postgres       [.] tts_heap_getsomeattrs.lto_priv.0
+    4,59%  postgres  postgres       [.] PinBuffer
+    3,90%  postgres  postgres       [.] heap_hot_search_buffer
+    3,27%  postgres  postgres       [.] hash_search_with_hash_value
+    3,08%  postgres  postgres       [.] ExecInterpExpr
+    2,16%  postgres  postgres       [.] UnpinBufferNoOwner.lto_priv.0
+    1,78%  postgres  postgres       [.] heapam_index_fetch_tuple.lto_priv.0
+    1,73%  postgres  postgres       [.] StartReadBuffer
+    1,51%  postgres  postgres       [.] LWLockAcquire
+    1,25%  postgres  postgres       [.] HeapTupleSatisfiesVisibility
+    1,18%  postgres  postgres       [.] heap_page_prune_opt
+    1,13%  postgres  postgres       [.] ExecScan
+    1,11%  postgres  postgres       [.] index_getnext_tid
+    1,05%  postgres  postgres       [.] index_fetch_heap
+    1,01%  postgres  postgres       [.] _bt_readpage
+    0,86%  postgres  postgres       [.] LWLockRelease
+    0,85%  postgres  postgres       [.] XidInMVCCSnapshot
+    0,74%  postgres  postgres       [.] ReleaseBuffer
+    0,73%  postgres  postgres       [.] IndexNext
+    0,72%  postgres  postgres       [.] _bt_checkkeys
+    0,72%  postgres  postgres       [.] _bt_next
+    0,56%  postgres  postgres       [.] GetPrivateRefCountEntry.lto_priv.0
+    0,54%  postgres  postgres       [.] btgettuple
     0,44%  postgres  postgres       [.] ExecStoreBufferHeapTuple
     0,41%  postgres  postgres       [.] _bt_check_compare.lto_priv.0
     0,41%  postgres  postgres       [.] hash_bytes
     0,39%  postgres  postgres       [.] MemoryContextReset
     0,34%  postgres  postgres       [.] ExecEvalSysVar
     0,34%  postgres  postgres       [.] ExecNestLoop
     0,32%  postgres  postgres       [.] tts_virtual_clear.lto_priv.0
     0,32%  postgres  postgres       [.] ResourceOwnerForget
     0,30%  postgres  postgres       [.] GlobalVisTestFor
     0,30%  postgres  postgres       [.] HeapTupleIsSurelyDead
     0,26%  postgres  postgres       [.] PredicateLockTID
     0,22%  postgres  postgres       [.] ReadBufferExtended
     0,20%  postgres  postgres       [.] _bt_setuppostingitems
     0,20%  postgres  postgres       [.] ExecIndexScan
     0,20%  postgres  postgres       [.] slot_getsomeattrs_int
     0,17%  postgres  libc.so.6      [.] __memcmp_sse2
     0,16%  postgres  postgres       [.] _bt_saveitem
     0,13%  postgres  postgres       [.] ResourceOwnerEnlarge
     0,12%  postgres  postgres       [.]
HeapCheckForSerializableConflictOut
     0,10%  postgres  postgres       [.] pgstat_count_io_op
     0,08%  postgres  postgres       [.] IncrBufferRefCount

RUN 3 - NO CHILDREN:
Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10010750000
  Overhead  Command   Shared Object  Symbol
+   25,54%  postgres  postgres       [.] LWLockAttemptLock
+   16,44%  postgres  postgres       [.] LWLockReleaseInternal
+   12,72%  postgres  postgres       [.] ReleaseAndReadBuffer
+    4,88%  postgres  postgres       [.] tts_heap_getsomeattrs.lto_priv.0
+    4,69%  postgres  postgres       [.] PinBuffer
+    3,75%  postgres  postgres       [.] heap_hot_search_buffer
+    3,47%  postgres  postgres       [.] hash_search_with_hash_value
+    2,95%  postgres  postgres       [.] ExecInterpExpr
+    2,01%  postgres  postgres       [.] UnpinBufferNoOwner.lto_priv.0
+    1,89%  postgres  postgres       [.] heapam_index_fetch_tuple.lto_priv.0
+    1,69%  postgres  postgres       [.] StartReadBuffer
+    1,50%  postgres  postgres       [.] LWLockAcquire
+    1,14%  postgres  postgres       [.] HeapTupleSatisfiesVisibility
+    1,12%  postgres  postgres       [.] heap_page_prune_opt
+    1,10%  postgres  postgres       [.] ExecScan
+    1,09%  postgres  postgres       [.] index_getnext_tid
+    1,03%  postgres  postgres       [.] index_fetch_heap
+    1,01%  postgres  postgres       [.] LWLockRelease
+    0,99%  postgres  postgres       [.] _bt_readpage
+    0,87%  postgres  postgres       [.] XidInMVCCSnapshot
+    0,79%  postgres  postgres       [.] IndexNext
+    0,76%  postgres  postgres       [.] ReleaseBuffer
+    0,74%  postgres  postgres       [.] _bt_next
+    0,72%  postgres  postgres       [.] _bt_checkkeys
+    0,61%  postgres  postgres       [.] btgettuple
+    0,59%  postgres  postgres       [.] GetPrivateRefCountEntry.lto_priv.0
     0,50%  postgres  postgres       [.] ExecStoreBufferHeapTuple
     0,41%  postgres  postgres       [.] _bt_check_compare.lto_priv.0
     0,41%  postgres  postgres       [.] hash_bytes
     0,38%  postgres  postgres       [.] MemoryContextReset
     0,34%  postgres  postgres       [.] ExecEvalSysVar
     0,34%  postgres  postgres       [.] HeapTupleIsSurelyDead
     0,34%  postgres  postgres       [.] ExecNestLoop
     0,32%  postgres  postgres       [.] ResourceOwnerForget
     0,31%  postgres  postgres       [.] GlobalVisTestFor
     0,31%  postgres  postgres       [.] tts_virtual_clear.lto_priv.0
     0,25%  postgres  postgres       [.] ReadBufferExtended
     0,22%  postgres  postgres       [.] PredicateLockTID
     0,21%  postgres  postgres       [.] slot_getsomeattrs_int
     0,17%  postgres  postgres       [.] ExecIndexScan
     0,17%  postgres  postgres       [.] _bt_saveitem
     0,16%  postgres  postgres       [.] _bt_setuppostingitems
     0,14%  postgres  postgres       [.]
HeapCheckForSerializableConflictOut
     0,13%  postgres  libc.so.6      [.] __memcmp_sse2
     0,12%  postgres  postgres       [.] ResourceOwnerEnlarge
     0,11%  postgres  postgres       [.] IncrBufferRefCount
     0,10%  postgres  postgres       [.] pgstat_count_io_op

RUN 4 - NO CHILDREN:
Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10010500000
  Overhead  Command   Shared Object  Symbol
+   25,65%  postgres  postgres       [.] LWLockAttemptLock
+   15,76%  postgres  postgres       [.] LWLockReleaseInternal
+   12,75%  postgres  postgres       [.] ReleaseAndReadBuffer
+    4,83%  postgres  postgres       [.] tts_heap_getsomeattrs.lto_priv.0
+    4,78%  postgres  postgres       [.] PinBuffer
+    3,82%  postgres  postgres       [.] heap_hot_search_buffer
+    3,76%  postgres  postgres       [.] hash_search_with_hash_value
+    3,03%  postgres  postgres       [.] ExecInterpExpr
+    2,11%  postgres  postgres       [.] UnpinBufferNoOwner.lto_priv.0
+    2,01%  postgres  postgres       [.] heapam_index_fetch_tuple.lto_priv.0
+    1,65%  postgres  postgres       [.] StartReadBuffer
+    1,45%  postgres  postgres       [.] LWLockAcquire
+    1,17%  postgres  postgres       [.] heap_page_prune_opt
+    1,16%  postgres  postgres       [.] ExecScan
+    1,16%  postgres  postgres       [.] HeapTupleSatisfiesVisibility
+    1,04%  postgres  postgres       [.] index_getnext_tid
+    1,01%  postgres  postgres       [.] LWLockRelease
+    1,01%  postgres  postgres       [.] _bt_readpage
+    0,99%  postgres  postgres       [.] index_fetch_heap
+    0,82%  postgres  postgres       [.] XidInMVCCSnapshot
+    0,79%  postgres  postgres       [.] _bt_next
+    0,73%  postgres  postgres       [.] IndexNext
+    0,72%  postgres  postgres       [.] _bt_checkkeys
+    0,71%  postgres  postgres       [.] ReleaseBuffer
+    0,63%  postgres  postgres       [.] GetPrivateRefCountEntry.lto_priv.0
+    0,58%  postgres  postgres       [.] btgettuple
     0,46%  postgres  postgres       [.] ExecStoreBufferHeapTuple
     0,44%  postgres  postgres       [.] _bt_check_compare.lto_priv.0
     0,37%  postgres  postgres       [.] ExecEvalSysVar
     0,36%  postgres  postgres       [.] MemoryContextReset
     0,34%  postgres  postgres       [.] tts_virtual_clear.lto_priv.0
     0,32%  postgres  postgres       [.] ExecNestLoop
     0,31%  postgres  postgres       [.] GlobalVisTestFor
     0,30%  postgres  postgres       [.] HeapTupleIsSurelyDead
     0,30%  postgres  postgres       [.] hash_bytes
     0,27%  postgres  postgres       [.] PredicateLockTID
     0,26%  postgres  postgres       [.] ResourceOwnerForget
     0,26%  postgres  postgres       [.] ReadBufferExtended
     0,23%  postgres  postgres       [.] slot_getsomeattrs_int
     0,17%  postgres  postgres       [.] _bt_setuppostingitems
     0,17%  postgres  libc.so.6      [.] __memcmp_sse2
     0,15%  postgres  postgres       [.] ExecIndexScan
     0,14%  postgres  postgres       [.] _bt_saveitem
     0,12%  postgres  postgres       [.] int8eq
     0,12%  postgres  postgres       [.]
ReservePrivateRefCountEntry.lto_priv.0
     0,12%  postgres  postgres       [.] ResourceOwnerEnlarge
     0,11%  postgres  postgres       [.]
HeapCheckForSerializableConflictOut

RUN 5 - NO CHILDREN:
Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10003250000
  Overhead  Command   Shared Object      Symbol
+   26,48%  postgres  postgres           [.] LWLockAttemptLock
+   15,81%  postgres  postgres           [.] LWLockReleaseInternal
+   12,88%  postgres  postgres           [.] ReleaseAndReadBuffer
+    4,84%  postgres  postgres           [.]
tts_heap_getsomeattrs.lto_priv.0
+    4,64%  postgres  postgres           [.] PinBuffer
+    3,67%  postgres  postgres           [.] heap_hot_search_buffer
+    3,47%  postgres  postgres           [.] hash_search_with_hash_value
+    2,97%  postgres  postgres           [.] ExecInterpExpr
+    2,11%  postgres  postgres           [.] UnpinBufferNoOwner.lto_priv.0
+    1,92%  postgres  postgres           [.]
heapam_index_fetch_tuple.lto_priv.0
+    1,88%  postgres  postgres           [.] StartReadBuffer
+    1,41%  postgres  postgres           [.] LWLockAcquire
+    1,12%  postgres  postgres           [.] heap_page_prune_opt
+    1,09%  postgres  postgres           [.] HeapTupleSatisfiesVisibility
+    1,00%  postgres  postgres           [.] index_fetch_heap
+    0,97%  postgres  postgres           [.] _bt_readpage
+    0,92%  postgres  postgres           [.] _bt_next
+    0,92%  postgres  postgres           [.] index_getnext_tid
+    0,90%  postgres  postgres           [.] ExecScan
+    0,85%  postgres  postgres           [.] IndexNext
+    0,83%  postgres  postgres           [.] XidInMVCCSnapshot
+    0,81%  postgres  postgres           [.] LWLockRelease
+    0,71%  postgres  postgres           [.] _bt_checkkeys
+    0,69%  postgres  postgres           [.] ReleaseBuffer
+    0,57%  postgres  postgres           [.]
GetPrivateRefCountEntry.lto_priv.0
+    0,53%  postgres  postgres           [.] 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

In response to

Browse pgsql-bugs by date

  From Date Subject
Next Message Premal Patel 2025-10-08 11:17:03 Re: BUG #19076: Generic query plan is extremely slow
Previous Message David Rowley 2025-10-08 09:13:54 Re: BUG #19076: Generic query plan is extremely slow